Attachment 1725420 Details for Bug 1893360 – journal snippets (journal debug output - reversed) around the reboot slowdowns

journal snippets (journal debug output - reversed) around the reboot slowdowns

journal-debug (text/plain), 13.88 KB, created by Yu Qi Zhang on 2020-10-30 20:39:05 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Yu Qi Zhang

Created: 2020-10-30 20:39:05 UTC

Size: 13.88 KB

patch

obsolete

>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods.slice: Consumed 1h 4min 32.768s CPU time
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Removed slice libcontainer container kubepods.slice.
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods.slice: Job kubepods.slice/stop finished, result=done
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods.slice changed active -> dead
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods-burstable.slice: Consumed 1h 4min 31.319s CPU time
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Removed slice libcontainer container kubepods-burstable.slice.
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods-burstable.slice: Job kubepods-burstable.slice/stop finished, result=done
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods-burstable.slice changed active -> dead
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods-burstable-pod4a1b7660_3b3e_44c1_8469_5cd6eb8583ab.slice: Consumed 3min 55.199s CPU time
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Removed slice libcontainer container kubepods-burstable-pod4a1b7660_3b3e_44c1_8469_5cd6eb8583ab.slice.
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods-burstable-pod4a1b7660_3b3e_44c1_8469_5cd6eb8583ab.slice: Job kubepods-burstable-pod4a1b7660_3b3e_44c1_8469_5cd6eb8583ab.slice/stop finished, result=done
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods-burstable-pod4a1b7660_3b3e_44c1_8469_5cd6eb8583ab.slice changed active -> dead
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Got cgroup empty notification for: /kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod4a1b7660_3b3e_44c1_8469_5cd6eb8583ab.slice
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Got cgroup empty notification for: /kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod4a1b7660_3b3e_44c1_8469_5cd6eb8583ab.slice/crio-conmon-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope: Collecting.
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope: Consumed 3min 12.285s CPU time
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Stopped libcontainer container 9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope: Job crio-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope/stop finished, result=done
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope changed stop-sigterm -> dead
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope: cgroup is empty
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Got cgroup empty notification for: /kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod4a1b7660_3b3e_44c1_8469_5cd6eb8583ab.slice/crio-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope: Collecting.
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope: Consumed 50ms CPU time
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Stopped crio-conmon-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope.
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope: Job crio-conmon-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope/stop finished, result=done
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope changed stop-sigterm -> dead
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope: cgroup is empty
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope: Child 3238 belongs to crio-conmon-9ed0fa03d6e8c0e5e34843231368ad59c73662fee0f4829207472420d2a3b049.scope.
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Child 3238 (conmon) died (code=exited, status=0/SUCCESS)
>Oct 30 15:11:08 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Received SIGCHLD from PID 3238 (conmon).
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods-burstable-pod48143c50_a16a_4a7b_8cc3_25d6d3ae57d4.slice: Collecting.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods-burstable-pod48143c50_a16a_4a7b_8cc3_25d6d3ae57d4.slice: Consumed 3min 53.741s CPU time
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Removed slice libcontainer container kubepods-burstable-pod48143c50_a16a_4a7b_8cc3_25d6d3ae57d4.slice.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods-burstable-pod48143c50_a16a_4a7b_8cc3_25d6d3ae57d4.slice: Job kubepods-burstable-pod48143c50_a16a_4a7b_8cc3_25d6d3ae57d4.slice/stop finished, result=done
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: kubepods-burstable-pod48143c50_a16a_4a7b_8cc3_25d6d3ae57d4.slice changed active -> dead
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Got cgroup empty notification for: /kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod48143c50_a16a_4a7b_8cc3_25d6d3ae57d4.slice
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Got cgroup empty notification for: /kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod48143c50_a16a_4a7b_8cc3_25d6d3ae57d4.slice/crio-conmon-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Collecting.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Consumed 3min 53.076s CPU time
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Unit entered failed state.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Stopped libcontainer container bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Job crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope/stop finished, result=done
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope changed stop-sigkill -> failed
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Failed with result 'timeout'.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: cgroup is empty
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Got cgroup empty notification for: /kubepods.slice/kubepods-burstable.slice/kubepods-burstable-pod48143c50_a16a_4a7b_8cc3_25d6d3ae57d4.slice/crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Collecting.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Consumed 237ms CPU time
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Stopped crio-conmon-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Job crio-conmon-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope/stop finished, result=done
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope changed stop-sigterm -> dead
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: cgroup is empty
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-conmon-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Child 2227 belongs to crio-conmon-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Child 2227 (conmon) died (code=exited, status=137/n/a)
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Received SIGCHLD from PID 2227 (conmon).
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: sys-subsystem-net-devices-veth698ad719.device: Collecting.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: sys-devices-virtual-net-veth698ad719.device: Collecting.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: sys-devices-virtual-net-veth698ad719.device: Changed plugged -> dead
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: sys-subsystem-net-devices-veth698ad719.device: Changed plugged -> dead
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd-udevd[1184758]: passed 383 byte device to netlink monitor 0x564889fd5830
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd-udevd[904]: passed 185 byte device to netlink monitor 0x564889fc7d90
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd-udevd[1184758]: passed 166 byte device to netlink monitor 0x564889fd5830
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd-udevd[1184757]: passed 166 byte device to netlink monitor 0x564889fd55b0
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd kernel: audit: type=1700 audit(1604070638.569:842): dev=veth698ad719 prom=0 old_prom=256 auid=4294967295 uid=0 gid=0 ses=4294967295
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd kernel: device veth698ad719 left promiscuous mode
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope changed stop-sigterm -> stop-sigkill
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Killing process 2306 (tail) with signal SIGKILL.
>Oct 30 15:10:38 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: crio-bb121d29a9b04c15724c0af67be2ab0f3990a17f6748d9b147d743cc791162ed.scope: Stopping timed out. Killing.
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: systemd-journald.service: Received EPOLLHUP on stored fd 16 (stored), closing.
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Got cgroup empty notification for: /system.slice/lvm2-monitor.service
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd kernel: audit: type=1131 audit(1604070616.688:841): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-monitor comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: lvm2-monitor.service: Consumed 24ms CPU time
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Stopped Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling.
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: lvm2-monitor.service: Job lvm2-monitor.service/stop finished, result=done
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: lvm2-monitor.service: Changed stop -> dead
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: lvm2-monitor.service: Got final SIGCHLD for state stop.
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: lvm2-monitor.service: Control process exited, code=exited status=0
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: lvm2-monitor.service: Child 1184755 belongs to lvm2-monitor.service.
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Child 1184755 (lvm) died (code=exited, status=0/SUCCESS)
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: Received SIGCHLD from PID 1184755 (lvm).
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: systemd-journald.service: Added fd 16 (n/a) to fd store.
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: systemd-journald.service: Got notification message from PID 877 (FDSTORE=1)
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd systemd[1]: systemd-sysusers.service: Consumed 0 CPU time
>Oct 30 15:10:16 jerzhang-201029-01-nq26v-worker-a-ptkvd kernel: audit: type=1131 audit(1604070616.638:840): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-sysusers comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'

Actions: View

Attachments on bug 1893360: 1725420 | 1725421