To have trace-cmd trace guests from the host, it is required that the guest
is set up with vsocks. These are a virtual socket that lets the guest connect
directly with the host. To do this, make sure that your guest kernel has the
following configurations:
CONFIG_VSOCKETS=m
CONFIG_VHOST_VSOCK=m
CONFIG_VIRTIO_VSOCKETS=m
CONFIG_VIRTIO_VSOCKETS_COMMON=m
CONFIG_VSOCKETS_DIAG=m
CONFIG_VSOCKETS_LOOPBACK=mAnd obviously have tracing enabled as well:
CONFIG_TRACING=y
CONFIG_FTRACE=y
CONFIG_FUNCTION_TRACER=y
CONFIG_FUNCTION_GRAPH_TRACER=y
CONFIG_DYNAMIC_FTRACE=y
CONFIG_DYNAMIC_FTRACE_WITH_REGS=y
CONFIG_DYNAMIC_FTRACE_WITH_DIRECT_CALLS=y
CONFIG_DYNAMIC_FTRACE_WITH_ARGS=y
CONFIG_SCHED_TRACER=y
CONFIG_FTRACE_SYSCALLS=y
CONFIG_TRACER_SNAPSHOT=y
CONFIG_KPROBE_EVENTS=y
CONFIG_UPROBE_EVENTS=y
CONFIG_BPF_EVENTS=y
CONFIG_DYNAMIC_EVENTS=y
CONFIG_PROBE_EVENTS=y
CONFIG_SYNTH_EVENTS=y
CONFIG_HIST_TRIGGERS=yGive a the guest access to the vsocket. This is done in different ways.
With libvirt and virt-manager you can add it in via the dialog.
It is best to specify the VSOCK ID for the guest as you will need to know it when connecting to it when tracing.
After setting up the guest with the proper kernel configuration and booting it.
You need to install trace-cmd on the machine. It is best to use the latest version,
and you can find that at the trace-cmd website.
After installing trace-cmd on the guest. Simply run it with:
sudo trace-cmd agent
You will see where the agent connects to. Something like:
listening on @3:823
The format is the VSOCK ID followed by the port number. By default, the agent will connect to port 823. The above shows that the vsocket is 3.
That's it. Note, if you run trace-cmd agent -D, it will run in daemon mode, but it will
not (at this time) show you where it connected.
Once you have all your guests running with trace-cmd agent you can now trace them from
the host, and also include tracing the host at the same time.
sudo trace-cmd record -e kvm -e sched -e irq -A 3:823 --name myguest -e all sleep 1
The above will enable the kvm, sched and irq events on the host that traces the
KVM events that handle the guest, a bunch of scheduling events, and interrupt events respectively.
Then the -A option is used to specify what commands to send to the agent. We give it a
name of myguest and enable all events by enabling the special all event. Finally we sleep for
one second after the tracing has begun. Note, the last command is any command you want to run
that you can do from the command line. You could even ssh into the guest and run commands there.
The tracing will be recorded into files (one for host and one for each guest, if you had specified
more than one guest with more than one -A option), until the command finishes. Once the command completes,
the tracing will stop. If you do not pass in a command, then it will continue to trace until you hit Ctrl-C.
Here's an example of what I had done:
# trace-cmd record -o /tmp/trace.dat -e kvm -e sched -e irq -e irq_vectors -A @3:823 --name gentoo -e all ssh root@192.168.122.169 'ls -lR . > /dev/null'
Negotiated kvm time sync protocol with guest gentoo
(root@192.168.122.169) Password:
version = 7
version = 7
CPU0 data recorded at offset=0x338000
82649 bytes in size (569344 uncompressed)
CPU1 data recorded at offset=0x34d000
67512 bytes in size (327680 uncompressed)
CPU2 data recorded at offset=0x35e000
44798 bytes in size (241664 uncompressed)
CPU3 data recorded at offset=0x369000
45978 bytes in size (237568 uncompressed)
CPU4 data recorded at offset=0x375000
49760 bytes in size (368640 uncompressed)
CPU5 data recorded at offset=0x382000
139617 bytes in size (663552 uncompressed)
CPU6 data recorded at offset=0x3a5000
56748 bytes in size (282624 uncompressed)
CPU7 data recorded at offset=0x3b3000
71556 bytes in size (331776 uncompressed)
CPU0 data recorded at offset=0x7c8000
43543 bytes in size (290816 uncompressed)
CPU1 data recorded at offset=0x7d3000
122215 bytes in size (933888 uncompressed)
CPU2 data recorded at offset=0x7f1000
182580 bytes in size (2002944 uncompressed)
CPU3 data recorded at offset=0x81e000
66737 bytes in size (471040 uncompressed)
CPU4 data recorded at offset=0x82f000
66795 bytes in size (532480 uncompressed)
CPU5 data recorded at offset=0x840000
7422 bytes in size (53248 uncompressed)
CPU6 data recorded at offset=0x842000
21721 bytes in size (184320 uncompressed)
CPU7 data recorded at offset=0x848000
55919 bytes in size (462848 uncompressed)
CPU8 data recorded at offset=0x856000
133064 bytes in size (1048576 uncompressed)
CPU9 data recorded at offset=0x877000
243255 bytes in size (1875968 uncompressed)
CPU10 data recorded at offset=0x8b3000
156652 bytes in size (1757184 uncompressed)
CPU11 data recorded at offset=0x8da000
169438 bytes in size (1290240 uncompressed)
CPU12 data recorded at offset=0x904000
3833 bytes in size (24576 uncompressed)
CPU13 data recorded at offset=0x905000
1389 bytes in size (8192 uncompressed)
CPU14 data recorded at offset=0x906000
1139 bytes in size (8192 uncompressed)
CPU15 data recorded at offset=0x907000
16718 bytes in size (135168 uncompressed)
CPU16 data recorded at offset=0x90c000
235860 bytes in size (2506752 uncompressed)
CPU17 data recorded at offset=0x946000
220602 bytes in size (2306048 uncompressed)
CPU18 data recorded at offset=0x97c000
183759 bytes in size (1433600 uncompressed)
CPU19 data recorded at offset=0x9a9000
210492 bytes in size (2179072 uncompressed)
CPU20 data recorded at offset=0x9dd000
19330 bytes in size (204800 uncompressed)
CPU21 data recorded at offset=0x9e2000
1471 bytes in size (8192 uncompressed)
CPU22 data recorded at offset=0x9e3000
4999 bytes in size (32768 uncompressed)
CPU23 data recorded at offset=0x9e5000
1811 bytes in size (12288 uncompressed)
CPU24 data recorded at offset=0x9e6000
5848 bytes in size (40960 uncompressed)
CPU25 data recorded at offset=0x9e8000
140671 bytes in size (1228800 uncompressed)
CPU26 data recorded at offset=0xa0b000
74227 bytes in size (618496 uncompressed)
CPU27 data recorded at offset=0xa1e000
10551 bytes in size (77824 uncompressed)
CPU28 data recorded at offset=0xa21000
11474 bytes in size (69632 uncompressed)
CPU29 data recorded at offset=0xa24000
72762 bytes in size (638976 uncompressed)
CPU30 data recorded at offset=0xa36000
12673 bytes in size (106496 uncompressed)
CPU31 data recorded at offset=0xa3a000
2915 bytes in size (20480 uncompressed)
CPU32 data recorded at offset=0xa3b000
6962 bytes in size (40960 uncompressed)
CPU33 data recorded at offset=0xa3d000
6209 bytes in size (45056 uncompressed)
CPU34 data recorded at offset=0xa3f000
939 bytes in size (8192 uncompressed)
CPU35 data recorded at offset=0xa40000
2130 bytes in size (16384 uncompressed)
CPU36 data recorded at offset=0xa41000
128033 bytes in size (1585152 uncompressed)
CPU37 data recorded at offset=0xa61000
86672 bytes in size (643072 uncompressed)
CPU38 data recorded at offset=0xa77000
265003 bytes in size (2318336 uncompressed)
CPU39 data recorded at offset=0xab8000
82990 bytes in size (679936 uncompressed)
CPU40 data recorded at offset=0xacd000
120381 bytes in size (1077248 uncompressed)
CPU41 data recorded at offset=0xaeb000
56505 bytes in size (487424 uncompressed)
CPU42 data recorded at offset=0xaf9000
3789 bytes in size (28672 uncompressed)
CPU43 data recorded at offset=0xafa000
3674 bytes in size (24576 uncompressed)
CPU44 data recorded at offset=0xafb000
9573 bytes in size (86016 uncompressed)
CPU45 data recorded at offset=0xafe000
681 bytes in size (4096 uncompressed)
CPU46 data recorded at offset=0xaff000
1228 bytes in size (8192 uncompressed)
CPU47 data recorded at offset=0xb00000
12738 bytes in size (135168 uncompressed)
CPU48 data recorded at offset=0xb04000
34066 bytes in size (262144 uncompressed)
CPU49 data recorded at offset=0xb0d000
14099 bytes in size (94208 uncompressed)
CPU50 data recorded at offset=0xb11000
44213 bytes in size (299008 uncompressed)
CPU51 data recorded at offset=0xb1c000
326322 bytes in size (3547136 uncompressed)
CPU52 data recorded at offset=0xb6c000
1171 bytes in size (8192 uncompressed)
CPU53 data recorded at offset=0xb6d000
2948 bytes in size (20480 uncompressed)
CPU54 data recorded at offset=0xb6e000
6212 bytes in size (40960 uncompressed)
CPU55 data recorded at offset=0xb70000
3125 bytes in size (20480 uncompressed)
CPU56 data recorded at offset=0xb71000
11284 bytes in size (90112 uncompressed)
CPU57 data recorded at offset=0xb74000
7187 bytes in size (57344 uncompressed)
CPU58 data recorded at offset=0xb76000
36213 bytes in size (270336 uncompressed)
CPU59 data recorded at offset=0xb7f000
35387 bytes in size (286720 uncompressed)
CPU60 data recorded at offset=0xb88000
520 bytes in size (4096 uncompressed)
CPU61 data recorded at offset=0xb89000
224 bytes in size (4096 uncompressed)
CPU62 data recorded at offset=0xb8a000
519 bytes in size (4096 uncompressed)
CPU63 data recorded at offset=0xb8b000
3462 bytes in size (20480 uncompressed)
CPU64 data recorded at offset=0xb8c000
0 bytes in size (0 uncompressed)
CPU65 data recorded at offset=0xb8c000
0 bytes in size (0 uncompressed)
[..]
CPU126 data recorded at offset=0xb8c000
0 bytes in size (0 uncompressed)
CPU127 data recorded at offset=0xb8c000
0 bytes in size (0 uncompressed)
My host has 128 CPUs and there was no data on most of the latter ones, so I cut off that. Notice at the beginning that the host and guest negotiated the time synchronization. Since this is a KVM guest, and the host supplies some information about how the guest's clock relates to the host clock, the synchronization will use this KVM information to synchronize the guest event timestamps with the host's timestamps.
Negotiated kvm time sync protocol with guest gentoo
Now there's two files in the /tmp directory. One for my host and one for my guest:
$ ls -l /tmp/trace*
-rw-r--r-- 1 root root 12108683 Mar 14 14:43 /tmp/trace.dat
-rw-r--r-- 1 root root 3950815 Mar 14 14:43 /tmp/trace-gentoo.dat
Now we can display the output with trace-cmd that will automatically synchronize the
guest and host events.
$ trace-cmd report -i /tmp/trace.dat -i /tmp/trace-gentoo.dat
version = 7
version = 7
trace.dat: cpus=128
trace-gentoo.dat: cpus=8
trace-gentoo.dat: <...>-561 [000] 159685.796303: page_fault_user: address=0x7f8f25f844d0 ip=0x7f8f25f844d0 error_code=0x14
trace-gentoo.dat: <...>-550 [004] 159685.796303: sys_exit: NR 1 = 1
trace-gentoo.dat: <...>-561 [000] 159685.796304: mmap_lock_start_locking: mm=0xffff88810177ec00 memcg_path= write=false
trace-gentoo.dat: <...>-561 [000] 159685.796305: mmap_lock_acquire_returned: mm=0xffff88810177ec00 memcg_path= write=false success=true
trace-gentoo.dat: <...>-550 [004] 159685.796305: sys_enter: NR 0 (4, 7ffd8afef0f0, c, 0, 0, 55a77edd2330)
trace-gentoo.dat: <...>-561 [000] 159685.796306: mmap_lock_released: mm=0xffff88810177ec00 memcg_path= write=false
trace-gentoo.dat: <...>-550 [004] 159685.796306: rcu_utilization: Start context switch
trace-gentoo.dat: <...>-550 [004] 159685.796306: rcu_utilization: End context switch
[..]
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798824: workqueue_activate_work: work struct 0xffff8881079764a8
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798824: workqueue_execute_end: work struct 0xffff888107976420: function virtio_transport_tx_work
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798824: workqueue_execute_start: work struct 0xffff8881079764a8: function virtio_transport_send_pkt_work
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798824: workqueue_execute_end: work struct 0xffff8881079764a8: function virtio_transport_send_pkt_work
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798825: rcu_utilization: Start context switch
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798825: rcu_utilization: End context switch
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798825: sched_stat_runtime: comm=kworker/5:1 pid=553 runtime=6663 [ns] vruntime=2002188997 [ns]
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798826: sched_switch: kworker/5:1:553 [120] W ==> swapper/5:0 [120]
trace-gentoo.dat: -0 [005] 159685.798826: cpu_idle: state=1 cpu_id=5
trace.dat: <...>-1854 [040] 159685.799113: sched_waking: comm=in:imuxsock pid=2553 prio=130 target_cpu=042
trace.dat: <...>-1854 [040] 159685.799116: sched_wakeup: in:imuxsock:2553 [130] CPU:042
trace.dat: -0 [042] 159685.799119: reschedule_entry: vector=253
trace.dat: -0 [042] 159685.799119: reschedule_exit: vector=253
trace.dat: -0 [042] 159685.799121: sched_switch: swapper/42:0 [120] R ==> in:imuxsock:2553 [130]
trace.dat: in:imuxsock-2553 [042] 159685.799127: sched_waking: comm=rs:main Q:Reg pid=2558 prio=130 target_cpu=041
trace.dat: in:imuxsock-2553 [042] 159685.799128: sched_wakeup: rs:main Q:Reg:2558 [130] CPU:041
trace.dat: in:imuxsock-2553 [042] 159685.799129: sched_stat_runtime: comm=in:imuxsock pid=2553 runtime=14848 [ns] vruntime=967690451 [ns]
trace.dat: in:imuxsock-2553 [042] 159685.799130: sched_switch: in:imuxsock:2553 [130] S ==> swapper/42:0 [120]
trace.dat: -0 [041] 159685.799130: reschedule_entry: vector=253
trace.dat: -0 [041] 159685.799131: reschedule_exit: vector=253
trace.dat: -0 [041] 159685.799132: sched_switch: swapper/41:0 [120] R ==> rs:main Q:Reg:2558 [130]
trace.dat: rs:main Q:Reg-2558 [041] 159685.799144: sched_stat_runtime: comm=rs:main Q:Reg pid=2558 runtime=17102 [ns] vruntime=1017492934 [ns]
trace.dat: rs:main Q:Reg-2558 [041] 159685.799145: sched_switch: rs:main Q:Reg:2558 [130] S ==> swapper/41:0 [120]
trace.dat: <...>-1854 [040] 159685.799163: sched_waking: comm=in:imuxsock pid=2553 prio=130 target_cpu=042
trace.dat: <...>-1854 [040] 159685.799164: sched_wakeup: in:imuxsock:2553 [130] CPU:042
trace.dat: -0 [042] 159685.799167: reschedule_entry: vector=253
trace.dat: -0 [042] 159685.799167: reschedule_exit: vector=253
[..]
trace.dat: CPU 4/KVM-351644 [048] 159685.802281: kvm_pv_tlb_flush: vcpu 4 need_flush_tlb false
trace.dat: CPU 4/KVM-351644 [048] 159685.802281: kvm_inj_virq: irq 236
trace.dat: -0 [051] 159685.802282: sched_wakeup: CPU 2/KVM:351642 [120] CPU:051
trace.dat: CPU 4/KVM-351644 [048] 159685.802282: kvm_entry: vcpu 4, rip 0xffffffff81618a4e
trace.dat: -0 [003] 159685.802282: sched_wakeup: CPU 5/KVM:351645 [120] CPU:003
trace.dat: -0 [011] 159685.802282: sched_switch: swapper/11:0 [120] R ==> CPU 1/KVM:351641 [120]
trace.dat: -0 [051] 159685.802282: sched_waking: comm=CPU 6/KVM pid=351646 prio=120 target_cpu=051
trace.dat: -0 [003] 159685.802283: local_timer_exit: vector=236
trace-gentoo.dat: -0 [004] 159685.802283: local_timer_entry: vector=236
trace.dat: CPU 3/KVM-351643 [008] 159685.802283: kvm_vcpu_wakeup: wait time 8426899 ns, polling valid
trace-gentoo.dat: -0 [004] 159685.802283: hrtimer_cancel: hrtimer=0xffff88827fd1dc00
trace.dat: CPU 3/KVM-351643 [008] 159685.802283: kvm_apic_accept_irq: apicid 3 vec 236 (Fixed|edge)
trace-gentoo.dat: -0 [004] 159685.802284: hrtimer_expire_entry: hrtimer=0xffff88827fd1dc00 now=4618237385697 function=tick_sched_timer/0x0
trace.dat: CPU 3/KVM-351643 [008] 159685.802284: kvm_pv_tlb_flush: vcpu 3 need_flush_tlb false
trace.dat: -0 [051] 159685.802284: sched_wakeup: CPU 6/KVM:351646 [120] CPU:051
trace.dat: CPU 3/KVM-351643 [008] 159685.802284: kvm_inj_virq: irq 236
trace-gentoo.dat: -0 [004] 159685.802284: rcu_utilization: Start scheduler-tick
trace.dat: -0 [051] 159685.802284: local_timer_exit: vector=236
trace-gentoo.dat: -0 [004] 159685.802285: softirq_raise: vec=9 [action=RCU]
trace-gentoo.dat: -0 [004] 159685.802285: rcu_utilization: End scheduler-tick
trace.dat: -0 [051] 159685.802285: irq_work_entry: vector=246
trace.dat: CPU 3/KVM-351643 [008] 159685.802285: kvm_entry: vcpu 3, rip 0xffffffff81618a4e
trace-gentoo.dat: -0 [004] 159685.802286: softirq_raise: vec=7 [action=SCHED]
trace.dat: CPU 1/KVM-351641 [011] 159685.802286: kvm_vcpu_wakeup: wait time 4668430 ns, polling valid
trace.dat: -0 [003] 159685.802286: sched_switch: swapper/3:0 [120] R ==> CPU 5/KVM:351645 [120]
trace.dat: -0 [051] 159685.802286: sched_waking: comm=kworker/51:2 pid=256296 prio=120 target_cpu=051
trace-gentoo.dat: -0 [004] 159685.802286: hrtimer_expire_exit: hrtimer=0xffff88827fd1dc00
trace-gentoo.dat: -0 [004] 159685.802286: hrtimer_start: hrtimer=0xffff88827fd1dc00 function=tick_sched_timer/0x0 expires=4618247380685 softexpires=4618247380685
trace.dat: CPU 1/KVM-351641 [011] 159685.802286: kvm_apic_accept_irq: apicid 1 vec 236 (Fixed|edge)
trace-gentoo.dat: -0 [003] 159685.802287: local_timer_entry: vector=236
trace.dat: -0 [051] 159685.802287: sched_wakeup: kworker/51:2:256296 [120] CPU:051
trace.dat: -0 [051] 159685.802287: irq_work_exit: vector=246
[..]
Now that is a big mess. It would be more interesting if we only saw the events from the host threads that handle the guest's vCPUS. To do so, first find the guest's unique ID saved in the guest's trace file.
$ trace-cmd dump --options /tmp/trace-gentoo.dat
[..]
[Option TSC2NSEC, 16 bytes]
796858867 31 0 [multiplier, shift, offset]
[Option TimeShift, 560 bytes]
0x8751F145487573CA [peer's trace id]
0x0 [peer's protocol flags]
0x8 [peer's CPU count]
The above shows that the guest's trace id is 0x8751F145487573CA. Now we can use this on the
host's tracing file.
$ trace-cmd dump --options /tmp/trace.dat
[..]
[Option GUEST, 77 bytes]
[Guest name]
0x407B00B8AD375915 [trace id]
8 [Guest CPUs]
0 351640 [guest cpu, host pid]
1 351641 [guest cpu, host pid]
2 351642 [guest cpu, host pid]
3 351643 [guest cpu, host pid]
4 351644 [guest cpu, host pid]
5 351645 [guest cpu, host pid]
6 351646 [guest cpu, host pid]
7 351647 [guest cpu, host pid]
Now that we know the host threads that handle the guest vCPUs, we can filter the host to only show those threads while stil showing all the threads by the guest.
$ trace-cmd report -i /tmp/trace.dat -F '.*:(common_pid >= 351640 && common_pid <= 351647)' -i /tmp/trace-gentoo.dat
version = 7
version = 7
trace.dat: cpus=128
trace-gentoo.dat: cpus=8
trace-gentoo.dat: <...>-561 [000] 159685.796303: page_fault_user: address=0x7f8f25f844d0 ip=0x7f8f25f844d0 error_code=0x14
trace-gentoo.dat: <...>-550 [004] 159685.796303: sys_exit: NR 1 = 1
trace-gentoo.dat: <...>-561 [000] 159685.796304: mmap_lock_start_locking: mm=0xffff88810177ec00 memcg_path= write=false
trace-gentoo.dat: <...>-561 [000] 159685.796305: mmap_lock_acquire_returned: mm=0xffff88810177ec00 memcg_path= write=false success=true
trace-gentoo.dat: <...>-550 [004] 159685.796305: sys_enter: NR 0 (4, 7ffd8afef0f0, c, 0, 0, 55a77edd2330)
trace-gentoo.dat: <...>-561 [000] 159685.796306: mmap_lock_released: mm=0xffff88810177ec00 memcg_path= write=false
trace-gentoo.dat: <...>-550 [004] 159685.796306: rcu_utilization: Start context switch
trace-gentoo.dat: <...>-550 [004] 159685.796306: rcu_utilization: End context switch
trace-gentoo.dat: <...>-561 [000] 159685.796307: sys_enter: NR 13 (2, 7ffd8afeee10, 7ffd8afeeeb0, 8, 7ffd8afef000, 7f8f262a2000)
trace-gentoo.dat: <...>-550 [004] 159685.796307: sched_stat_runtime: comm=trace-cmd pid=550 runtime=57768 [ns] vruntime=971705956 [ns]
trace-gentoo.dat: <...>-561 [000] 159685.796307: sys_exit: NR 13 = 0
trace-gentoo.dat: <...>-561 [000] 159685.796308: sys_enter: NR 13 (a, 7ffd8afeee10, 7ffd8afeeeb0, 8, 7ffd8afef000, 0)
trace-gentoo.dat: <...>-550 [004] 159685.796308: sched_switch: trace-cmd:550 [120] S ==> swapper/4:0 [120]
trace-gentoo.dat: <...>-561 [000] 159685.796308: sys_exit: NR 13 = 0
trace-gentoo.dat: trace-cmd-550 [004] 159685.796309: x86_fpu_regs_deactivated: x86/fpu: 0xffff888100828e40 load: 0 xfeatures: 2 xcomp_bv: 8000000000000007
trace-gentoo.dat: <...>-561 [000] 159685.796309: page_fault_user: address=0x55a77d3010f8 ip=0x55a77d29c453 error_code=0x7
trace-gentoo.dat: <...>-561 [000] 159685.796309: mmap_lock_start_locking: mm=0xffff88810177ec00 memcg_path= write=false
trace-gentoo.dat: <...>-561 [000] 159685.796309: mmap_lock_acquire_returned: mm=0xffff88810177ec00 memcg_path= write=false success=true
trace-gentoo.dat: -0 [004] 159685.796309: cpu_idle: state=1 cpu_id=4
trace-gentoo.dat: <...>-561 [000] 159685.796310: mmap_lock_released: mm=0xffff88810177ec00 memcg_path= write=false
trace-gentoo.dat: <...>-561 [000] 159685.796311: sys_enter: NR 43 (b, 0, 0, 8, 0, 0)
trace-gentoo.dat: <...>-561 [000] 159685.796311: kmem_cache_alloc: (sock_alloc_inode+0x12) call_site=sock_alloc_inode+0x12 ptr=0xffff88810049d380 bytes_req=768 bytes_alloc=768 gfp_flags=GFP_KERNEL
trace-gentoo.dat: <...>-561 [000] 159685.796312: module_get: vsock call_site=do_accept refcnt=34
trace-gentoo.dat: <...>-561 [000] 159685.796313: kmem_cache_alloc: (__d_alloc+0x1b) call_site=__d_alloc+0x1b ptr=0xffff888105615a80 bytes_req=192 bytes_alloc=192 gfp_flags=GFP_KERNEL
[..]
trace-gentoo.dat: -0 [005] 159685.798820: rcu_utilization: End context switch
trace-gentoo.dat: -0 [000] 159685.798821: cpu_idle: state=1 cpu_id=0
trace-gentoo.dat: -0 [005] 159685.798821: sched_switch: swapper/5:0 [120] R ==> kworker/5:1:553 [120]
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798822: workqueue_execute_start: work struct 0xffff888107976420: function virtio_transport_tx_work
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798822: kfree: (detach_buf_split+0xd4) call_site=detach_buf_split+0xd4 ptr=0xffff8881008f77e0
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798823: kfree: (virtio_transport_free_pkt+0xd) call_site=virtio_transport_free_pkt+0xd ptr=0xffff8881050ee000
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798823: kfree: (virtio_transport_tx_work+0x5f) call_site=virtio_transport_tx_work+0x5f ptr=0xffff888105cd1800
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798823: workqueue_queue_work: work struct=0xffff8881079764a8 function=virtio_transport_send_pkt_work workqueue=virtio_vsock req_cpu=64 cpu=5
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798824: workqueue_activate_work: work struct 0xffff8881079764a8
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798824: workqueue_execute_end: work struct 0xffff888107976420: function virtio_transport_tx_work
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798824: workqueue_execute_start: work struct 0xffff8881079764a8: function virtio_transport_send_pkt_work
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798824: workqueue_execute_end: work struct 0xffff8881079764a8: function virtio_transport_send_pkt_work
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798825: rcu_utilization: Start context switch
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798825: rcu_utilization: End context switch
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798825: sched_stat_runtime: comm=kworker/5:1 pid=553 runtime=6663 [ns] vruntime=2002188997 [ns]
trace-gentoo.dat: kworker/5:1-553 [005] 159685.798826: sched_switch: kworker/5:1:553 [120] W ==> swapper/5:0 [120]
trace-gentoo.dat: -0 [005] 159685.798826: cpu_idle: state=1 cpu_id=5
trace.dat: CPU 4/KVM-351644 [048] 159685.802280: kvm_halt_poll_ns: vcpu 4: halt_poll_ns 0 (shrink 40000)
trace.dat: CPU 4/KVM-351644 [048] 159685.802280: kvm_vcpu_wakeup: wait time 5969543 ns, polling valid
trace.dat: CPU 4/KVM-351644 [048] 159685.802281: kvm_apic_accept_irq: apicid 4 vec 236 (Fixed|edge)
trace.dat: CPU 4/KVM-351644 [048] 159685.802281: kvm_pv_tlb_flush: vcpu 4 need_flush_tlb false
trace.dat: CPU 4/KVM-351644 [048] 159685.802281: kvm_inj_virq: irq 236
trace.dat: CPU 4/KVM-351644 [048] 159685.802282: kvm_entry: vcpu 4, rip 0xffffffff81618a4e
trace-gentoo.dat: -0 [004] 159685.802283: local_timer_entry: vector=236
trace.dat: CPU 3/KVM-351643 [008] 159685.802283: kvm_vcpu_wakeup: wait time 8426899 ns, polling valid
trace-gentoo.dat: -0 [004] 159685.802283: hrtimer_cancel: hrtimer=0xffff88827fd1dc00
trace.dat: CPU 3/KVM-351643 [008] 159685.802283: kvm_apic_accept_irq: apicid 3 vec 236 (Fixed|edge)
trace-gentoo.dat: -0 [004] 159685.802284: hrtimer_expire_entry: hrtimer=0xffff88827fd1dc00 now=4618237385697 function=tick_sched_timer/0x0
trace.dat: CPU 3/KVM-351643 [008] 159685.802284: kvm_pv_tlb_flush: vcpu 3 need_flush_tlb false
trace.dat: CPU 3/KVM-351643 [008] 159685.802284: kvm_inj_virq: irq 236
trace-gentoo.dat: -0 [004] 159685.802284: rcu_utilization: Start scheduler-tick
trace-gentoo.dat: -0 [004] 159685.802285: softirq_raise: vec=9 [action=RCU]
trace-gentoo.dat: -0 [004] 159685.802285: rcu_utilization: End scheduler-tick
trace.dat: CPU 3/KVM-351643 [008] 159685.802285: kvm_entry: vcpu 3, rip 0xffffffff81618a4e
trace-gentoo.dat: -0 [004] 159685.802286: softirq_raise: vec=7 [action=SCHED]
trace.dat: CPU 1/KVM-351641 [011] 159685.802286: kvm_vcpu_wakeup: wait time 4668430 ns, polling valid
trace-gentoo.dat: -0 [004] 159685.802286: hrtimer_expire_exit: hrtimer=0xffff88827fd1dc00
trace-gentoo.dat: -0 [004] 159685.802286: hrtimer_start: hrtimer=0xffff88827fd1dc00 function=tick_sched_timer/0x0 expires=4618247380685 softexpires=4618247380685
trace.dat: CPU 1/KVM-351641 [011] 159685.802286: kvm_apic_accept_irq: apicid 1 vec 236 (Fixed|edge)
trace-gentoo.dat: -0 [003] 159685.802287: local_timer_entry: vector=236
trace.dat: CPU 4/KVM-351644 [048] 159685.802287: kvm_wait_lapic_expire: vcpu 4: delta 9924 (late)
trace.dat: CPU 4/KVM-351644 [048] 159685.802287: kvm_eoi: apicid 4 vector 236
trace.dat: CPU 4/KVM-351644 [048] 159685.802287: kvm_pv_eoi: apicid 4 vector 236
trace.dat: CPU 1/KVM-351641 [011] 159685.802287: kvm_pv_tlb_flush: vcpu 1 need_flush_tlb false
trace.dat: CPU 4/KVM-351644 [048] 159685.802287: kvm_exit: reason EXIT_MSR rip 0xffffffff8104fb36 info 1 0
trace-gentoo.dat: -0 [003] 159685.802288: hrtimer_cancel: hrtimer=0xffff88827fcddc00
trace.dat: CPU 4/KVM-351644 [048] 159685.802288: kvm_hv_timer_state: vcpu_id 4 hv_timer 0
trace.dat: CPU 4/KVM-351644 [048] 159685.802288: kvm_msr: msr_write 6e0 = 0xb55ddb56207
trace.dat: CPU 1/KVM-351641 [011] 159685.802288: kvm_inj_virq: irq 236
trace-gentoo.dat: -0 [003] 159685.802288: hrtimer_expire_entry: hrtimer=0xffff88827fcddc00 now=4618237390045 function=tick_sched_timer/0x0
trace.dat: CPU 4/KVM-351644 [048] 159685.802288: kvm_entry: vcpu 4, rip 0xffffffff8104fb38
trace-gentoo.dat: -0 [003] 159685.802289: rcu_utilization: Start scheduler-tick
trace-gentoo.dat: -0 [004] 159685.802289: write_msr: 6e0, value b55ddb56207
trace-gentoo.dat: -0 [004] 159685.802289: local_timer_exit: vector=236
trace-gentoo.dat: -0 [003] 159685.802289: softirq_raise: vec=9 [action=RCU]
trace.dat: CPU 5/KVM-351645 [003] 159685.802289: kvm_halt_poll_ns: vcpu 5: halt_poll_ns 0 (shrink 160000)
trace-gentoo.dat: -0 [003] 159685.802289: rcu_utilization: End scheduler-tick
trace-gentoo.dat: -0 [004] 159685.802289: softirq_entry: vec=7 [action=SCHED]
trace.dat: CPU 5/KVM-351645 [003] 159685.802289: kvm_vcpu_wakeup: wait time 3460601 ns, polling valid
trace.dat: CPU 1/KVM-351641 [011] 159685.802290: kvm_entry: vcpu 1, rip 0xffffffff81618a4e
trace.dat: CPU 5/KVM-351645 [003] 159685.802290: kvm_apic_accept_irq: apicid 5 vec 236 (Fixed|edge)
trace-gentoo.dat: -0 [003] 159685.802290: hrtimer_expire_exit: hrtimer=0xffff88827fcddc00
trace-gentoo.dat: -0 [003] 159685.802290: hrtimer_start: hrtimer=0xffff88827fcddc00 function=tick_sched_timer/0x0 expires=4618247380685 softexpires=4618247380685
trace-gentoo.dat: -0 [004] 159685.802291: softirq_exit: vec=7 [action=SCHED]
trace.dat: CPU 5/KVM-351645 [003] 159685.802291: kvm_pv_tlb_flush: vcpu 5 need_flush_tlb false
trace-gentoo.dat: -0 [004] 159685.802291: softirq_entry: vec=9 [action=RCU]
trace-gentoo.dat: -0 [004] 159685.802291: rcu_utilization: Start RCU core
trace-gentoo.dat: -0 [004] 159685.802291: rcu_utilization: End RCU core
trace-gentoo.dat: -0 [004] 159685.802292: softirq_exit: vec=9 [action=RCU]
trace.dat: CPU 3/KVM-351643 [008] 159685.802292: kvm_wait_lapic_expire: vcpu 3: delta 19154 (late)
trace.dat: CPU 3/KVM-351643 [008] 159685.802292: kvm_eoi: apicid 3 vector 236
trace-gentoo.dat: -0 [004] 159685.802292: cpu_idle: state=4294967295 cpu_id=4
trace.dat: CPU 3/KVM-351643 [008] 159685.802292: kvm_pv_eoi: apicid 3 vector 236
trace.dat: CPU 3/KVM-351643 [008] 159685.802292: kvm_exit: reason EXIT_MSR rip 0xffffffff8104fb36 info 1 0
trace-gentoo.dat: -0 [004] 159685.802292: cpu_idle: state=1 cpu_id=4
trace.dat: CPU 5/KVM-351645 [003] 159685.802292: kvm_inj_virq: irq 236
trace-gentoo.dat: -0 [001] 159685.802292: local_timer_entry: vector=236
trace.dat: CPU 4/KVM-351644 [048] 159685.802293: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace.dat: CPU 3/KVM-351643 [008] 159685.802293: kvm_hv_timer_state: vcpu_id 3 hv_timer 0
trace.dat: CPU 3/KVM-351643 [008] 159685.802293: kvm_msr: msr_write 6e0 = 0xb55ddb56228
trace.dat: CPU 4/KVM-351644 [048] 159685.802293: sched_stat_runtime: comm=CPU 4/KVM pid=351644 runtime=15659 [ns] vruntime=146436065 [ns]
trace.dat: CPU 3/KVM-351643 [008] 159685.802293: kvm_entry: vcpu 3, rip 0xffffffff8104fb38
trace-gentoo.dat: -0 [003] 159685.802293: write_msr: 6e0, value b55ddb56228
trace.dat: CPU 5/KVM-351645 [003] 159685.802294: kvm_entry: vcpu 5, rip 0xffffffff81618a4e
trace-gentoo.dat: -0 [003] 159685.802294: local_timer_exit: vector=236
trace-gentoo.dat: -0 [003] 159685.802294: softirq_entry: vec=9 [action=RCU]
trace-gentoo.dat: -0 [003] 159685.802294: rcu_utilization: Start RCU core
trace-gentoo.dat: -0 [001] 159685.802294: hrtimer_cancel: hrtimer=0xffff88827fc5dc00
trace-gentoo.dat: -0 [003] 159685.802294: rcu_utilization: End RCU core
trace-gentoo.dat: -0 [003] 159685.802295: softirq_exit: vec=9 [action=RCU]
trace-gentoo.dat: -0 [001] 159685.802295: hrtimer_expire_entry: hrtimer=0xffff88827fc5dc00 now=4618237396337 function=tick_sched_timer/0x0
trace-gentoo.dat: -0 [003] 159685.802295: cpu_idle: state=4294967295 cpu_id=3
trace-gentoo.dat: -0 [003] 159685.802295: cpu_idle: state=1 cpu_id=3
trace-gentoo.dat: -0 [001] 159685.802296: rcu_utilization: Start scheduler-tick
trace.dat: CPU 6/KVM-351646 [051] 159685.802296: kvm_vcpu_wakeup: wait time 4008309 ns, polling valid
trace.dat: CPU 3/KVM-351643 [008] 159685.802296: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace-gentoo.dat: -0 [001] 159685.802296: rcu_utilization: End scheduler-tick
trace.dat: CPU 6/KVM-351646 [051] 159685.802296: kvm_apic_accept_irq: apicid 6 vec 236 (Fixed|edge)
trace.dat: CPU 3/KVM-351643 [008] 159685.802296: sched_stat_runtime: comm=CPU 3/KVM pid=351643 runtime=17623 [ns] vruntime=193684920 [ns]
trace.dat: CPU 4/KVM-351644 [048] 159685.802297: sched_migrate_task: comm=CPU 2/KVM pid=351642 prio=120 orig_cpu=51 dest_cpu=48
trace.dat: CPU 6/KVM-351646 [051] 159685.802297: kvm_pv_tlb_flush: vcpu 6 need_flush_tlb false
trace-gentoo.dat: -0 [005] 159685.802297: local_timer_entry: vector=236
trace.dat: CPU 6/KVM-351646 [051] 159685.802298: kvm_inj_virq: irq 236
trace.dat: CPU 6/KVM-351646 [051] 159685.802298: kvm_entry: vcpu 6, rip 0xffffffff81618a4e
trace-gentoo.dat: -0 [001] 159685.802298: hrtimer_expire_exit: hrtimer=0xffff88827fc5dc00
trace-gentoo.dat: -0 [001] 159685.802298: hrtimer_start: hrtimer=0xffff88827fc5dc00 function=tick_sched_timer/0x0 expires=4618247380685 softexpires=4618247380685
trace.dat: CPU 3/KVM-351643 [008] 159685.802299: sched_switch: CPU 3/KVM:351643 [120] S ==> CPU 7/KVM:351647 [120]
trace-gentoo.dat: -0 [005] 159685.802299: hrtimer_cancel: hrtimer=0xffff88827fd5dc00
trace-gentoo.dat: -0 [006] 159685.802300: local_timer_entry: vector=236
trace-gentoo.dat: -0 [005] 159685.802300: hrtimer_expire_entry: hrtimer=0xffff88827fd5dc00 now=4618237401517 function=tick_sched_timer/0x0
trace.dat: CPU 4/KVM-351644 [048] 159685.802300: sched_switch: CPU 4/KVM:351644 [120] S ==> CPU 2/KVM:351642 [120]
trace.dat: CPU 1/KVM-351641 [011] 159685.802301: kvm_wait_lapic_expire: vcpu 1: delta 31548 (late)
trace.dat: CPU 7/KVM-351647 [008] 159685.802301: kvm_vcpu_wakeup: wait time 3721451 ns, polling valid
trace.dat: CPU 1/KVM-351641 [011] 159685.802301: kvm_eoi: apicid 1 vector 236
trace-gentoo.dat: -0 [006] 159685.802301: hrtimer_cancel: hrtimer=0xffff88827fd9dc00
trace.dat: CPU 7/KVM-351647 [008] 159685.802301: kvm_apic_accept_irq: apicid 7 vec 236 (Fixed|edge)
trace-gentoo.dat: -0 [005] 159685.802301: rcu_utilization: Start scheduler-tick
trace.dat: CPU 1/KVM-351641 [011] 159685.802301: kvm_pv_eoi: apicid 1 vector 236
trace-gentoo.dat: -0 [006] 159685.802301: hrtimer_expire_entry: hrtimer=0xffff88827fd9dc00 now=4618237403230 function=tick_sched_timer/0x0
trace.dat: CPU 1/KVM-351641 [011] 159685.802302: kvm_exit: reason EXIT_MSR rip 0xffffffff8104fb36 info 1 0
trace.dat: CPU 7/KVM-351647 [008] 159685.802302: kvm_pv_tlb_flush: vcpu 7 need_flush_tlb false
trace.dat: CPU 2/KVM-351642 [048] 159685.802302: kvm_vcpu_wakeup: wait time 4357566 ns, polling valid
trace.dat: CPU 7/KVM-351647 [008] 159685.802302: kvm_inj_virq: irq 236
trace-gentoo.dat: -0 [005] 159685.802302: softirq_raise: vec=9 [action=RCU]
trace.dat: CPU 2/KVM-351642 [048] 159685.802302: kvm_apic_accept_irq: apicid 2 vec 236 (Fixed|edge)
trace-gentoo.dat: -0 [006] 159685.802302: rcu_utilization: Start scheduler-tick
trace-gentoo.dat: -0 [005] 159685.802302: rcu_utilization: End scheduler-tick
trace.dat: CPU 7/KVM-351647 [008] 159685.802303: kvm_entry: vcpu 7, rip 0xffffffff81618a4e
trace.dat: CPU 2/KVM-351642 [048] 159685.802303: kvm_pv_tlb_flush: vcpu 2 need_flush_tlb false
trace.dat: CPU 1/KVM-351641 [011] 159685.802303: kvm_hv_timer_state: vcpu_id 1 hv_timer 0
trace-gentoo.dat: -0 [006] 159685.802303: softirq_raise: vec=9 [action=RCU]
trace.dat: CPU 1/KVM-351641 [011] 159685.802303: kvm_msr: msr_write 6e0 = 0xb55ddb562a9
trace.dat: CPU 2/KVM-351642 [048] 159685.802303: kvm_inj_virq: irq 236
trace-gentoo.dat: -0 [006] 159685.802303: rcu_utilization: End scheduler-tick
trace-gentoo.dat: -0 [007] 159685.802304: local_timer_entry: vector=236
trace.dat: CPU 1/KVM-351641 [011] 159685.802304: kvm_entry: vcpu 1, rip 0xffffffff8104fb38
trace.dat: CPU 2/KVM-351642 [048] 159685.802304: kvm_entry: vcpu 2, rip 0xffffffff81618a4e
trace-gentoo.dat: -0 [001] 159685.802304: write_msr: 6e0, value b55ddb562a9
trace-gentoo.dat: -0 [005] 159685.802304: softirq_raise: vec=7 [action=SCHED]
trace-gentoo.dat: -0 [007] 159685.802304: hrtimer_cancel: hrtimer=0xffff88827fdddc00
trace-gentoo.dat: -0 [001] 159685.802305: local_timer_exit: vector=236
trace-gentoo.dat: -0 [007] 159685.802305: hrtimer_expire_entry: hrtimer=0xffff88827fdddc00 now=4618237406777 function=tick_sched_timer/0x0
trace-gentoo.dat: -0 [006] 159685.802305: hrtimer_expire_exit: hrtimer=0xffff88827fd9dc00
trace-gentoo.dat: -0 [005] 159685.802305: hrtimer_expire_exit: hrtimer=0xffff88827fd5dc00
trace-gentoo.dat: -0 [007] 159685.802305: rcu_utilization: Start scheduler-tick
trace-gentoo.dat: -0 [006] 159685.802305: hrtimer_start: hrtimer=0xffff88827fd9dc00 function=tick_sched_timer/0x0 expires=4618247380685 softexpires=4618247380685
trace-gentoo.dat: -0 [005] 159685.802305: hrtimer_start: hrtimer=0xffff88827fd5dc00 function=tick_sched_timer/0x0 expires=4618247380685 softexpires=4618247380685
trace-gentoo.dat: -0 [007] 159685.802305: rcu_utilization: End scheduler-tick
trace-gentoo.dat: -0 [002] 159685.802305: local_timer_entry: vector=236
trace-gentoo.dat: -0 [001] 159685.802306: cpu_idle: state=4294967295 cpu_id=1
trace-gentoo.dat: -0 [002] 159685.802306: hrtimer_cancel: hrtimer=0xffff88827fc9dc00
trace-gentoo.dat: -0 [001] 159685.802307: cpu_idle: state=1 cpu_id=1
trace-gentoo.dat: -0 [007] 159685.802307: hrtimer_expire_exit: hrtimer=0xffff88827fdddc00
trace-gentoo.dat: -0 [002] 159685.802307: hrtimer_expire_entry: hrtimer=0xffff88827fc9dc00 now=4618237408660 function=tick_sched_timer/0x0
trace-gentoo.dat: -0 [007] 159685.802307: hrtimer_start: hrtimer=0xffff88827fdddc00 function=tick_sched_timer/0x0 expires=4618247380685 softexpires=4618247380685
trace.dat: CPU 6/KVM-351646 [051] 159685.802307: kvm_wait_lapic_expire: vcpu 6: delta 54332 (late)
trace-gentoo.dat: -0 [002] 159685.802307: rcu_utilization: Start scheduler-tick
trace.dat: CPU 6/KVM-351646 [051] 159685.802307: kvm_eoi: apicid 6 vector 236
trace-gentoo.dat: -0 [002] 159685.802307: softirq_raise: vec=9 [action=RCU]
trace-gentoo.dat: -0 [002] 159685.802308: rcu_utilization: End scheduler-tick
trace.dat: CPU 6/KVM-351646 [051] 159685.802308: kvm_pv_eoi: apicid 6 vector 236
trace.dat: CPU 1/KVM-351641 [011] 159685.802308: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace.dat: CPU 5/KVM-351645 [003] 159685.802308: kvm_wait_lapic_expire: vcpu 5: delta 42539 (late)
trace.dat: CPU 6/KVM-351646 [051] 159685.802308: kvm_exit: reason EXIT_MSR rip 0xffffffff8104fb36 info 1 0
trace.dat: CPU 7/KVM-351647 [008] 159685.802308: kvm_wait_lapic_expire: vcpu 7: delta 65889 (late)
trace.dat: CPU 7/KVM-351647 [008] 159685.802308: kvm_eoi: apicid 7 vector 236
trace.dat: CPU 5/KVM-351645 [003] 159685.802308: kvm_eoi: apicid 5 vector 236
trace.dat: CPU 7/KVM-351647 [008] 159685.802308: kvm_pv_eoi: apicid 7 vector 236
trace.dat: CPU 7/KVM-351647 [008] 159685.802308: kvm_exit: reason EXIT_MSR rip 0xffffffff8104fb36 info 1 0
trace.dat: CPU 5/KVM-351645 [003] 159685.802308: kvm_pv_eoi: apicid 5 vector 236
trace.dat: CPU 5/KVM-351645 [003] 159685.802309: kvm_exit: reason EXIT_MSR rip 0xffffffff8104fb36 info 1 0
trace.dat: CPU 1/KVM-351641 [011] 159685.802309: sched_stat_runtime: comm=CPU 1/KVM pid=351641 runtime=29716 [ns] vruntime=776401119 [ns]
trace-gentoo.dat: -0 [002] 159685.802309: hrtimer_expire_exit: hrtimer=0xffff88827fc9dc00
trace.dat: CPU 7/KVM-351647 [008] 159685.802309: kvm_hv_timer_state: vcpu_id 7 hv_timer 0
trace-gentoo.dat: -0 [002] 159685.802309: hrtimer_start: hrtimer=0xffff88827fc9dc00 function=tick_sched_timer/0x0 expires=4618247380685 softexpires=4618247380685
trace.dat: CPU 7/KVM-351647 [008] 159685.802309: kvm_msr: msr_write 6e0 = 0xb55ddb56225
trace.dat: CPU 6/KVM-351646 [051] 159685.802309: kvm_hv_timer_state: vcpu_id 6 hv_timer 0
trace.dat: CPU 7/KVM-351647 [008] 159685.802309: kvm_entry: vcpu 7, rip 0xffffffff8104fb38
trace.dat: CPU 6/KVM-351646 [051] 159685.802309: kvm_msr: msr_write 6e0 = 0xb55ddb562ac
trace-gentoo.dat: -0 [007] 159685.802309: write_msr: 6e0, value b55ddb56225
trace.dat: CPU 6/KVM-351646 [051] 159685.802310: kvm_entry: vcpu 6, rip 0xffffffff8104fb38
trace-gentoo.dat: -0 [007] 159685.802310: local_timer_exit: vector=236
trace.dat: CPU 5/KVM-351645 [003] 159685.802310: kvm_hv_timer_state: vcpu_id 5 hv_timer 0
trace.dat: CPU 2/KVM-351642 [048] 159685.802310: kvm_wait_lapic_expire: vcpu 2: delta 68992 (late)
trace.dat: CPU 5/KVM-351645 [003] 159685.802310: kvm_msr: msr_write 6e0 = 0xb55ddb562dc
trace.dat: CPU 2/KVM-351642 [048] 159685.802310: kvm_eoi: apicid 2 vector 236
trace.dat: CPU 2/KVM-351642 [048] 159685.802310: kvm_pv_eoi: apicid 2 vector 236
trace-gentoo.dat: -0 [007] 159685.802310: cpu_idle: state=4294967295 cpu_id=7
trace-gentoo.dat: -0 [006] 159685.802310: write_msr: 6e0, value b55ddb562ac
trace.dat: CPU 2/KVM-351642 [048] 159685.802310: kvm_exit: reason EXIT_MSR rip 0xffffffff8104fb36 info 1 0
trace-gentoo.dat: -0 [007] 159685.802311: cpu_idle: state=1 cpu_id=7
trace-gentoo.dat: -0 [006] 159685.802311: local_timer_exit: vector=236
trace.dat: CPU 5/KVM-351645 [003] 159685.802311: kvm_entry: vcpu 5, rip 0xffffffff8104fb38
trace.dat: CPU 2/KVM-351642 [048] 159685.802311: kvm_hv_timer_state: vcpu_id 2 hv_timer 0
trace.dat: CPU 2/KVM-351642 [048] 159685.802311: kvm_msr: msr_write 6e0 = 0xb55ddb56221
trace.dat: CPU 7/KVM-351647 [008] 159685.802311: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace-gentoo.dat: -0 [006] 159685.802311: softirq_entry: vec=9 [action=RCU]
trace.dat: CPU 2/KVM-351642 [048] 159685.802311: kvm_entry: vcpu 2, rip 0xffffffff8104fb38
trace-gentoo.dat: -0 [006] 159685.802311: rcu_utilization: Start RCU core
trace.dat: CPU 7/KVM-351647 [008] 159685.802312: sched_stat_runtime: comm=CPU 7/KVM pid=351647 runtime=15218 [ns] vruntime=167341582 [ns]
trace-gentoo.dat: -0 [005] 159685.802312: write_msr: 6e0, value b55ddb562dc
trace-gentoo.dat: -0 [002] 159685.802312: write_msr: 6e0, value b55ddb56221
trace-gentoo.dat: -0 [006] 159685.802312: rcu_utilization: End RCU core
trace-gentoo.dat: -0 [002] 159685.802312: local_timer_exit: vector=236
trace-gentoo.dat: -0 [005] 159685.802312: local_timer_exit: vector=236
trace-gentoo.dat: -0 [006] 159685.802312: softirq_exit: vec=9 [action=RCU]
trace-gentoo.dat: -0 [002] 159685.802312: softirq_entry: vec=9 [action=RCU]
trace-gentoo.dat: -0 [002] 159685.802312: rcu_utilization: Start RCU core
trace-gentoo.dat: -0 [005] 159685.802313: softirq_entry: vec=7 [action=SCHED]
trace-gentoo.dat: -0 [002] 159685.802313: rcu_utilization: End RCU core
trace-gentoo.dat: -0 [006] 159685.802313: cpu_idle: state=4294967295 cpu_id=6
trace-gentoo.dat: -0 [002] 159685.802313: softirq_exit: vec=9 [action=RCU]
trace-gentoo.dat: -0 [006] 159685.802313: cpu_idle: state=1 cpu_id=6
trace-gentoo.dat: -0 [002] 159685.802313: cpu_idle: state=4294967295 cpu_id=2
trace.dat: CPU 7/KVM-351647 [008] 159685.802313: sched_switch: CPU 7/KVM:351647 [120] S ==> swapper/8:0 [120]
trace-gentoo.dat: -0 [002] 159685.802314: cpu_idle: state=1 cpu_id=2
trace.dat: CPU 6/KVM-351646 [051] 159685.802314: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace.dat: CPU 2/KVM-351642 [048] 159685.802314: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace.dat: CPU 6/KVM-351646 [051] 159685.802315: sched_stat_runtime: comm=CPU 6/KVM pid=351646 runtime=22292 [ns] vruntime=28833443 [ns]
trace.dat: CPU 2/KVM-351642 [048] 159685.802315: sched_stat_runtime: comm=CPU 2/KVM pid=351642 runtime=17032 [ns] vruntime=79653779 [ns]
trace-gentoo.dat: -0 [005] 159685.802316: softirq_exit: vec=7 [action=SCHED]
trace-gentoo.dat: -0 [005] 159685.802317: softirq_entry: vec=9 [action=RCU]
trace-gentoo.dat: -0 [005] 159685.802317: rcu_utilization: Start RCU core
trace-gentoo.dat: -0 [005] 159685.802317: rcu_utilization: End RCU core
trace-gentoo.dat: -0 [005] 159685.802318: softirq_exit: vec=9 [action=RCU]
trace-gentoo.dat: -0 [005] 159685.802319: cpu_idle: state=4294967295 cpu_id=5
trace-gentoo.dat: -0 [005] 159685.802319: cpu_idle: state=1 cpu_id=5
trace.dat: CPU 1/KVM-351641 [011] 159685.802320: sched_switch: CPU 1/KVM:351641 [120] S ==> swapper/11:0 [120]
trace.dat: CPU 5/KVM-351645 [003] 159685.802321: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace.dat: CPU 5/KVM-351645 [003] 159685.802322: sched_stat_runtime: comm=CPU 5/KVM pid=351645 runtime=42730 [ns] vruntime=91433279 [ns]
trace.dat: CPU 2/KVM-351642 [048] 159685.802323: sched_switch: CPU 2/KVM:351642 [120] S ==> swapper/48:0 [120]
trace.dat: CPU 6/KVM-351646 [051] 159685.802323: sched_switch: CPU 6/KVM:351646 [120] S ==> swapper/51:0 [120]
trace.dat: CPU 5/KVM-351645 [003] 159685.802325: sched_switch: CPU 5/KVM:351645 [120] S ==> swapper/3:0 [120]
trace.dat: CPU 0/KVM-351640 [009] 159685.802327: kvm_vcpu_wakeup: wait time 3504583 ns, polling valid
trace.dat: CPU 0/KVM-351640 [009] 159685.802327: kvm_apic_accept_irq: apicid 0 vec 236 (Fixed|edge)
trace.dat: CPU 0/KVM-351640 [009] 159685.802327: kvm_pv_tlb_flush: vcpu 0 need_flush_tlb false
trace.dat: CPU 0/KVM-351640 [009] 159685.802328: kvm_inj_virq: irq 236
trace.dat: CPU 0/KVM-351640 [009] 159685.802328: kvm_entry: vcpu 0, rip 0xffffffff81618a4e
trace-gentoo.dat: -0 [000] 159685.802329: local_timer_entry: vector=236
trace-gentoo.dat: -0 [000] 159685.802329: hrtimer_cancel: hrtimer=0xffff88827fc1dc00
trace-gentoo.dat: -0 [000] 159685.802330: hrtimer_expire_entry: hrtimer=0xffff88827fc1dc00 now=4618237431683 function=tick_sched_timer/0x0
trace-gentoo.dat: -0 [000] 159685.802331: rcu_utilization: Start scheduler-tick
trace-gentoo.dat: -0 [000] 159685.802331: softirq_raise: vec=9 [action=RCU]
trace-gentoo.dat: -0 [000] 159685.802331: rcu_utilization: End scheduler-tick
trace-gentoo.dat: -0 [000] 159685.802332: hrtimer_expire_exit: hrtimer=0xffff88827fc1dc00
trace-gentoo.dat: -0 [000] 159685.802332: hrtimer_start: hrtimer=0xffff88827fc1dc00 function=tick_sched_timer/0x0 expires=4618247380685 softexpires=4618247380685
trace.dat: CPU 0/KVM-351640 [009] 159685.802333: kvm_wait_lapic_expire: vcpu 0: delta 11271 (late)
trace.dat: CPU 0/KVM-351640 [009] 159685.802333: kvm_eoi: apicid 0 vector 236
trace.dat: CPU 0/KVM-351640 [009] 159685.802333: kvm_pv_eoi: apicid 0 vector 236
trace.dat: CPU 0/KVM-351640 [009] 159685.802333: kvm_exit: reason EXIT_MSR rip 0xffffffff8104fb36 info 1 0
trace.dat: CPU 0/KVM-351640 [009] 159685.802334: kvm_hv_timer_state: vcpu_id 0 hv_timer 0
trace.dat: CPU 0/KVM-351640 [009] 159685.802334: kvm_msr: msr_write 6e0 = 0xb55ddb56221
trace.dat: CPU 0/KVM-351640 [009] 159685.802334: kvm_entry: vcpu 0, rip 0xffffffff8104fb38
trace-gentoo.dat: -0 [000] 159685.802335: write_msr: 6e0, value b55ddb56221
trace-gentoo.dat: -0 [000] 159685.802335: local_timer_exit: vector=236
trace-gentoo.dat: -0 [000] 159685.802335: softirq_entry: vec=9 [action=RCU]
trace-gentoo.dat: -0 [000] 159685.802335: rcu_utilization: Start RCU core
trace-gentoo.dat: -0 [000] 159685.802336: sched_waking: comm=rcu_sched pid=10 prio=120 target_cpu=001
trace.dat: CPU 0/KVM-351640 [009] 159685.802337: kvm_apic_ipi: dst 1 vec 251 (Fixed|physical|de-assert|edge|dst)
trace.dat: CPU 0/KVM-351640 [009] 159685.802338: kvm_apic_accept_irq: apicid 1 vec 251 (Fixed|edge)
trace.dat: CPU 0/KVM-351640 [009] 159685.802338: sched_waking: comm=CPU 1/KVM pid=351641 prio=120 target_cpu=011
trace.dat: CPU 0/KVM-351640 [009] 159685.802339: sched_wakeup: CPU 1/KVM:351641 [120] CPU:011
trace.dat: CPU 0/KVM-351640 [009] 159685.802339: kvm_apic: apic_write APIC_ICR = 0xfb
trace.dat: CPU 0/KVM-351640 [009] 159685.802340: kvm_msr: msr_write 830 = 0x1000000fb
trace.dat: CPU 0/KVM-351640 [009] 159685.802340: kvm_exit: reason EXIT_MSR rip 0xffffffff8104fb38 info 1 0
trace.dat: CPU 0/KVM-351640 [009] 159685.802340: kvm_entry: vcpu 0, rip 0xffffffff8104fb38
trace-gentoo.dat: -0 [000] 159685.802340: write_msr: 830, value 1000000fb
trace-gentoo.dat: -0 [000] 159685.802340: rcu_utilization: End RCU core
trace-gentoo.dat: -0 [000] 159685.802341: softirq_exit: vec=9 [action=RCU]
trace-gentoo.dat: -0 [000] 159685.802341: cpu_idle: state=4294967295 cpu_id=0
trace-gentoo.dat: -0 [000] 159685.802341: cpu_idle: state=1 cpu_id=0
trace.dat: CPU 0/KVM-351640 [009] 159685.802341: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace.dat: CPU 0/KVM-351640 [009] 159685.802342: sched_stat_runtime: comm=CPU 0/KVM pid=351640 runtime=18374 [ns] vruntime=925226688 [ns]
trace.dat: CPU 0/KVM-351640 [009] 159685.802342: sched_switch: CPU 0/KVM:351640 [120] S ==> swapper/9:0 [120]
trace.dat: CPU 1/KVM-351641 [011] 159685.802346: kvm_halt_poll_ns: vcpu 1: halt_poll_ns 10000 (grow 0)
trace.dat: CPU 1/KVM-351641 [011] 159685.802346: kvm_vcpu_wakeup: wait time 37391 ns, polling valid
trace.dat: CPU 1/KVM-351641 [011] 159685.802346: kvm_pv_tlb_flush: vcpu 1 need_flush_tlb false
trace.dat: CPU 1/KVM-351641 [011] 159685.802346: kvm_inj_virq: irq 251
trace.dat: CPU 1/KVM-351641 [011] 159685.802347: kvm_entry: vcpu 1, rip 0xffffffff81618a4e
trace-gentoo.dat: -0 [001] 159685.802348: call_function_single_entry: vector=251
trace-gentoo.dat: -0 [001] 159685.802351: sched_wakeup: rcu_sched:10 [120] CPU:001
trace-gentoo.dat: -0 [001] 159685.802351: call_function_single_exit: vector=251
trace-gentoo.dat: -0 [001] 159685.802351: cpu_idle: state=4294967295 cpu_id=1
trace-gentoo.dat: -0 [001] 159685.802352: rcu_utilization: Start context switch
trace-gentoo.dat: -0 [001] 159685.802352: rcu_utilization: End context switch
trace-gentoo.dat: -0 [001] 159685.802353: sched_switch: swapper/1:0 [120] R ==> rcu_sched:10 [120]
trace-gentoo.dat: rcu_sched-10 [001] 159685.802355: timer_cancel: timer=0xffffc90000063e58
trace-gentoo.dat: rcu_sched-10 [001] 159685.802357: timer_init: timer=0xffffc90000063e58
trace-gentoo.dat: rcu_sched-10 [001] 159685.802358: timer_start: timer=0xffffc90000063e58 function=process_timeout expires=4295399117 [timeout=1] cpu=1 idx=14 flags=D|P|I
trace-gentoo.dat: rcu_sched-10 [001] 159685.802358: rcu_utilization: Start context switch
trace-gentoo.dat: rcu_sched-10 [001] 159685.802358: rcu_utilization: End context switch
trace-gentoo.dat: rcu_sched-10 [001] 159685.802359: sched_stat_runtime: comm=rcu_sched pid=10 runtime=9778 [ns] vruntime=1102429836 [ns]
trace-gentoo.dat: rcu_sched-10 [001] 159685.802360: sched_switch: rcu_sched:10 [120] W ==> swapper/1:0 [120]
trace-gentoo.dat: -0 [001] 159685.802361: cpu_idle: state=1 cpu_id=1
trace.dat: CPU 1/KVM-351641 [011] 159685.802362: kvm_eoi: apicid 1 vector 251
trace.dat: CPU 1/KVM-351641 [011] 159685.802362: kvm_pv_eoi: apicid 1 vector 251
trace.dat: CPU 1/KVM-351641 [011] 159685.802362: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace.dat: CPU 1/KVM-351641 [011] 159685.802373: sched_stat_runtime: comm=CPU 1/KVM pid=351641 runtime=34775 [ns] vruntime=776435894 [ns]
trace.dat: CPU 1/KVM-351641 [011] 159685.802375: sched_switch: CPU 1/KVM:351641 [120] S ==> swapper/11:0 [120]
trace.dat: CPU 1/KVM-351641 [011] 159685.803252: kvm_halt_poll_ns: vcpu 1: halt_poll_ns 0 (shrink 10000)
trace.dat: CPU 1/KVM-351641 [011] 159685.803252: kvm_vcpu_wakeup: wait time 889420 ns, polling valid
trace.dat: CPU 1/KVM-351641 [011] 159685.803253: kvm_pv_tlb_flush: vcpu 1 need_flush_tlb false
trace.dat: CPU 1/KVM-351641 [011] 159685.803253: kvm_inj_virq: irq 36
trace.dat: CPU 1/KVM-351641 [011] 159685.803254: kvm_entry: vcpu 1, rip 0xffffffff81618a4e
trace-gentoo.dat: -0 [001] 159685.803257: irq_handler_entry: irq=44 name=virtio0-input.0
trace-gentoo.dat: -0 [001] 159685.803259: softirq_raise: vec=3 [action=NET_RX]
trace-gentoo.dat: -0 [001] 159685.803260: irq_handler_exit: irq=44 ret=handled
trace-gentoo.dat: -0 [001] 159685.803261: mix_pool_bytes_nolock: ffffffff81decea8 pool: bytes 16 caller add_interrupt_randomness+0x13d
trace-gentoo.dat: -0 [001] 159685.803263: credit_entropy_bits: ffffffff81decea8 pool: bits 1 entropy_count 1196 caller handle_irq_event_percpu+0x3b
trace-gentoo.dat: -0 [001] 159685.803264: softirq_entry: vec=3 [action=NET_RX]
trace-gentoo.dat: -0 [001] 159685.803268: kmalloc: (__alloc_skb+0x98) call_site=__alloc_skb+0x98 ptr=0xffff888106235600 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC|__GFP_NOWARN|__GFP_NOMEMALLOC
trace.dat: CPU 1/KVM-351641 [011] 159685.803272: kvm_eoi: apicid 1 vector 36
trace.dat: CPU 1/KVM-351641 [011] 159685.803272: kvm_pv_eoi: apicid 1 vector 36
trace.dat: CPU 1/KVM-351641 [011] 159685.803273: kvm_exit: reason EXIT_NPF rip 0xffffffff8153beca info 100000014 153b000
trace.dat: CPU 1/KVM-351641 [011] 159685.803273: kvm_page_fault: address 153b000 error_code 14
trace.dat: CPU 1/KVM-351641 [011] 159685.803277: kvm_entry: vcpu 1, rip 0xffffffff8153beca
trace.dat: CPU 1/KVM-351641 [011] 159685.803278: kvm_exit: reason EXIT_NPF rip 0xffffffff8153923f info 100000014 1539000
trace.dat: CPU 1/KVM-351641 [011] 159685.803278: kvm_page_fault: address 1539000 error_code 14
trace.dat: CPU 1/KVM-351641 [011] 159685.803279: kvm_entry: vcpu 1, rip 0xffffffff8153923f
trace-gentoo.dat: -0 [001] 159685.803280: napi_gro_receive_entry: dev=enp1s0 napi_id=0x41 queue_mapping=1 skbaddr=0xffff888107a2d400 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x0000 protocol=0x0800 ip_summed=3 hash=0x00000000 l4_hash=0 len=60 data_len=0 truesize=768 mac_header_valid=1 mac_header=-14 nr_frags=0 gso_size=0 gso_type=0
trace.dat: CPU 1/KVM-351641 [011] 159685.803281: kvm_exit: reason EXIT_NPF rip 0xffffffff8153bffc info 100000014 153c000
trace.dat: CPU 1/KVM-351641 [011] 159685.803281: kvm_page_fault: address 153c000 error_code 14
trace.dat: CPU 1/KVM-351641 [011] 159685.803282: kvm_entry: vcpu 1, rip 0xffffffff8153bffc
trace-gentoo.dat: -0 [001] 159685.803285: napi_gro_receive_exit: ret=3
trace-gentoo.dat: -0 [001] 159685.803287: netif_receive_skb: dev=enp1s0 skbaddr=0xffff888107a2d400x len=60
trace.dat: CPU 1/KVM-351641 [011] 159685.803298: kvm_exit: reason EXIT_NPF rip 0xffffffff8153a259 info 100000014 153a000
trace.dat: CPU 1/KVM-351641 [011] 159685.803298: kvm_page_fault: address 153a000 error_code 14
trace.dat: CPU 1/KVM-351641 [011] 159685.803299: kvm_entry: vcpu 1, rip 0xffffffff8153a259
trace-gentoo.dat: -0 [001] 159685.803299: fib_table_lookup: table 254 oif 0 iif 2 proto 0 192.168.122.1/0 -> 192.168.122.169/0 tos 8 scope 0 flags 0 ==> dev enp1s0 gw 0.0.0.0/:: err 0
trace-gentoo.dat: -0 [001] 159685.803301: fib_table_lookup: table 254 oif 0 iif 1 proto 0 192.168.122.169/0 -> 192.168.122.1/0 tos 8 scope 0 flags 0 ==> dev enp1s0 gw 0.0.0.0/:: err 0
trace-gentoo.dat: -0 [001] 159685.803308: mm_page_alloc: page=0xffffea00001049f2 pfn=0x1049f2 order=0 migratetype=0 gfp_flags=GFP_ATOMIC|__GFP_NOWARN|__GFP_COMP
trace-gentoo.dat: -0 [001] 159685.803308: kmem_cache_alloc: (inet_reqsk_alloc+0x1d) call_site=inet_reqsk_alloc+0x1d ptr=0xffff8881049f2e60 bytes_req=296 bytes_alloc=296 gfp_flags=GFP_ATOMIC|__GFP_NOWARN
trace-gentoo.dat: -0 [001] 159685.803311: fib_table_lookup: table 254 oif 0 iif 1 proto 6 192.168.122.169/22 -> 192.168.122.1/50788 tos 0 scope 0 flags 0 ==> dev enp1s0 gw 0.0.0.0/:: err 0
trace-gentoo.dat: -0 [001] 159685.803315: prandom_u32: ret=544372811
trace-gentoo.dat: -0 [001] 159685.803317: timer_init: timer=0xffff8881049f2ef8
trace-gentoo.dat: -0 [001] 159685.803317: timer_start: timer=0xffff8881049f2ef8 function=reqsk_timer_handler expires=4295399216 [timeout=100] cpu=1 idx=103 flags=D|P|I
trace-gentoo.dat: -0 [001] 159685.803319: kmem_cache_alloc: (__alloc_skb+0x70) call_site=__alloc_skb+0x70 ptr=0xffff888107a2d200 bytes_req=224 bytes_alloc=256 gfp_flags=GFP_ATOMIC
trace-gentoo.dat: -0 [001] 159685.803319: kmalloc: (__alloc_skb+0x98) call_site=__alloc_skb+0x98 ptr=0xffff88810834f800 bytes_req=640 bytes_alloc=1024 gfp_flags=GFP_ATOMIC|__GFP_NOWARN|__GFP_NOMEMALLOC
trace-gentoo.dat: -0 [001] 159685.803324: net_dev_queue: dev=enp1s0 skbaddr=0xffff888107a2d200x len=74
trace-gentoo.dat: -0 [001] 159685.803326: kmem_cache_alloc: (skb_clone+0x5b) call_site=skb_clone+0x5b ptr=0xffff888107a2d900 bytes_req=224 bytes_alloc=256 gfp_flags=GFP_ATOMIC
trace-gentoo.dat: -0 [001] 159685.803327: consume_skb: skbaddr=0xffff888107a2d900
trace-gentoo.dat: -0 [001] 159685.803328: kmem_cache_free: (packet_rcv+0x2a6) call_site=packet_rcv+0x2a6 ptr=0xffff888107a2d900 name=skbuff_head_cache
trace-gentoo.dat: -0 [001] 159685.803329: net_dev_start_xmit: dev=enp1s0 queue_mapping=0 skbaddr=0xffff888107a2d200 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x0000 protocol=0x0800 ip_summed=3 len=74 data_len=0 network_offset=14 transport_offset_valid=1 transport_offset=34 tx_flags=0 gso_size=0 gso_segs=0 gso_type=0
trace.dat: CPU 1/KVM-351641 [011] 159685.803332: kvm_exit: reason EXIT_NPF rip 0xffffffff81300198 info 10000000f fea03004
trace.dat: CPU 1/KVM-351641 [011] 159685.803332: kvm_page_fault: address fea03004 error_code f
trace.dat: CPU 1/KVM-351641 [011] 159685.803334: kvm_emulate_insn: 0:ffffffff81300198: 66 89 06
trace.dat: CPU 1/KVM-351641 [011] 159685.803335: vcpu_match_mmio: gva 0xffffc900001d5004 gpa 0xfea03004 Write GPA
trace.dat: CPU 1/KVM-351641 [011] 159685.803335: kvm_mmio: mmio write len 2 gpa 0xfea03004 val 0x1
trace.dat: CPU 1/KVM-351641 [011] 159685.803337: sched_waking: comm=vhost-351631 pid=351638 prio=120 target_cpu=017
trace.dat: CPU 1/KVM-351641 [011] 159685.803339: kvm_entry: vcpu 1, rip 0xffffffff8130019b
trace-gentoo.dat: -0 [001] 159685.803340: net_dev_xmit: dev=enp1s0 skbaddr=0xffff888107a2d200 len=74 rc=0
trace-gentoo.dat: -0 [001] 159685.803341: consume_skb: skbaddr=0xffff888107a2d400
trace-gentoo.dat: -0 [001] 159685.803342: kfree: (skb_release_data+0x88) call_site=skb_release_data+0x88 ptr=0xffff888106235600
trace-gentoo.dat: -0 [001] 159685.803342: kmem_cache_free: (tcp_rcv_state_process+0xb3) call_site=tcp_rcv_state_process+0xb3 ptr=0xffff888107a2d400 name=skbuff_head_cache
trace-gentoo.dat: -0 [001] 159685.803344: napi_poll: napi poll on napi struct 0xffff888106b0a808 for device enp1s0 work 1 budget 64
trace-gentoo.dat: -0 [001] 159685.803344: softirq_exit: vec=3 [action=NET_RX]
trace-gentoo.dat: -0 [001] 159685.803345: cpu_idle: state=4294967295 cpu_id=1
trace-gentoo.dat: -0 [001] 159685.803345: cpu_idle: state=1 cpu_id=1
trace.dat: CPU 1/KVM-351641 [011] 159685.803346: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace.dat: CPU 1/KVM-351641 [011] 159685.803347: sched_stat_runtime: comm=CPU 1/KVM pid=351641 runtime=99948 [ns] vruntime=776535842 [ns]
trace.dat: CPU 1/KVM-351641 [011] 159685.803349: sched_switch: CPU 1/KVM:351641 [120] S ==> swapper/11:0 [120]
trace.dat: CPU 2/KVM-351642 [048] 159685.803422: kvm_vcpu_wakeup: wait time 1107841 ns, polling valid
trace.dat: CPU 2/KVM-351642 [048] 159685.803422: kvm_pv_tlb_flush: vcpu 2 need_flush_tlb false
trace.dat: CPU 2/KVM-351642 [048] 159685.803423: kvm_inj_virq: irq 36
trace.dat: CPU 2/KVM-351642 [048] 159685.803423: kvm_entry: vcpu 2, rip 0xffffffff81618a4e
trace.dat: CPU 1/KVM-351641 [011] 159685.803424: kvm_halt_poll_ns: vcpu 1: halt_poll_ns 10000 (grow 0)
trace.dat: CPU 1/KVM-351641 [011] 159685.803424: kvm_vcpu_wakeup: wait time 76985 ns, polling valid
trace.dat: CPU 1/KVM-351641 [011] 159685.803424: kvm_pv_tlb_flush: vcpu 1 need_flush_tlb false
trace.dat: CPU 1/KVM-351641 [011] 159685.803425: kvm_inj_virq: irq 36
trace.dat: CPU 1/KVM-351641 [011] 159685.803425: kvm_entry: vcpu 1, rip 0xffffffff81618a4e
trace-gentoo.dat: -0 [001] 159685.803426: irq_handler_entry: irq=44 name=virtio0-input.0
trace-gentoo.dat: -0 [002] 159685.803426: irq_handler_entry: irq=45 name=virtio0-output.0
trace-gentoo.dat: -0 [001] 159685.803427: softirq_raise: vec=3 [action=NET_RX]
trace-gentoo.dat: -0 [001] 159685.803427: irq_handler_exit: irq=44 ret=handled
trace-gentoo.dat: -0 [001] 159685.803428: softirq_entry: vec=3 [action=NET_RX]
trace-gentoo.dat: -0 [002] 159685.803428: softirq_raise: vec=3 [action=NET_RX]
trace-gentoo.dat: -0 [002] 159685.803429: irq_handler_exit: irq=45 ret=handled
trace-gentoo.dat: -0 [001] 159685.803429: consume_skb: skbaddr=0xffff888107a2d200
trace-gentoo.dat: -0 [001] 159685.803429: kfree: (skb_release_data+0x88) call_site=skb_release_data+0x88 ptr=0xffff88810834f800
trace-gentoo.dat: -0 [002] 159685.803430: mix_pool_bytes_nolock: ffffffff81decea8 pool: bytes 16 caller add_interrupt_randomness+0x13d
trace-gentoo.dat: -0 [001] 159685.803431: kmalloc: (__alloc_skb+0x98) call_site=__alloc_skb+0x98 ptr=0xffff888106235600 bytes_req=512 bytes_alloc=512 gfp_flags=GFP_ATOMIC|__GFP_NOWARN|__GFP_NOMEMALLOC
trace-gentoo.dat: -0 [002] 159685.803431: credit_entropy_bits: ffffffff81decea8 pool: bits 1 entropy_count 1196 caller handle_irq_event_percpu+0x3b
trace-gentoo.dat: -0 [002] 159685.803431: softirq_entry: vec=3 [action=NET_RX]
trace-gentoo.dat: -0 [001] 159685.803431: napi_gro_receive_entry: dev=enp1s0 napi_id=0x41 queue_mapping=1 skbaddr=0xffff888107a2d200 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x0000 protocol=0x0800 ip_summed=3 hash=0x00000000 l4_hash=0 len=52 data_len=0 truesize=768 mac_header_valid=1 mac_header=-14 nr_frags=0 gso_size=0 gso_type=0
trace-gentoo.dat: -0 [001] 159685.803432: napi_gro_receive_exit: ret=3
trace-gentoo.dat: -0 [001] 159685.803432: netif_receive_skb: dev=enp1s0 skbaddr=0xffff888107a2d200x len=52
trace-gentoo.dat: -0 [001] 159685.803433: fib_table_lookup: table 254 oif 0 iif 2 proto 0 192.168.122.1/0 -> 192.168.122.169/0 tos 8 scope 0 flags 0 ==> dev enp1s0 gw 0.0.0.0/:: err 0
trace-gentoo.dat: -0 [001] 159685.803434: fib_table_lookup: table 254 oif 0 iif 1 proto 0 192.168.122.169/0 -> 192.168.122.1/0 tos 8 scope 0 flags 0 ==> dev enp1s0 gw 0.0.0.0/:: err 0
trace-gentoo.dat: -0 [002] 159685.803434: napi_poll: napi poll on napi struct 0xffff888106bda2b8 for device enp1s0 work 0 budget 64
trace-gentoo.dat: -0 [002] 159685.803434: softirq_exit: vec=3 [action=NET_RX]
trace-gentoo.dat: -0 [002] 159685.803434: cpu_idle: state=4294967295 cpu_id=2
trace-gentoo.dat: -0 [002] 159685.803434: cpu_idle: state=1 cpu_id=2
trace.dat: CPU 2/KVM-351642 [048] 159685.803435: kvm_eoi: apicid 2 vector 36
trace.dat: CPU 2/KVM-351642 [048] 159685.803435: kvm_pv_eoi: apicid 2 vector 36
trace.dat: CPU 2/KVM-351642 [048] 159685.803435: kvm_exit: reason EXIT_HLT rip 0xffffffff81618a4d info 0 0
trace.dat: CPU 2/KVM-351642 [048] 159685.803435: sched_stat_runtime: comm=CPU 2/KVM pid=351642 runtime=18234 [ns] vruntime=79672013 [ns]
trace-gentoo.dat: -0 [001] 159685.803436: kmem_cache_alloc: (sk_prot_alloc+0x2b) call_site=sk_prot_alloc+0x2b ptr=0xffff888106008900 bytes_req=2184 bytes_alloc=2240 gfp_flags=GFP_ATOMIC
trace.dat: CPU 2/KVM-351642 [048] 159685.803437: sched_switch: CPU 2/KVM:351642 [120] S ==> swapper/48:0 [120]
trace-gentoo.dat: -0 [001] 159685.803437: inet_sock_set_state: family=AF_INET protocol=IPPROTO_TCP sport=22 dport=0 saddr=0.0.0.0 daddr=0.0.0.0 saddrv6=::ffff:0.0.0.0 daddrv6=::ffff:0.0.0.0 oldstate=TCP_LISTEN newstate=TCP_SYN_RECV
trace-gentoo.dat: -0 [001] 159685.803438: timer_init: timer=0xffff888106008d20
trace-gentoo.dat: -0 [001] 159685.803438: timer_init: timer=0xffff888106008d48
trace-gentoo.dat: -0 [001] 159685.803438: timer_init: timer=0xffff888106008aa0
trace-gentoo.dat: -0 [001] 159685.803439: hrtimer_init: hrtimer=0xffff888106009010 clockid=CLOCK_MONOTONIC mode=0x6
trace-gentoo.dat: -0 [001] 159685.803439: hrtimer_init: hrtimer=0xffff888106009050 clockid=CLOCK_MONOTONIC mode=0x7
trace-gentoo.dat: -0 [001] 159685.803439: prandom_u32: ret=3062286827
trace-gentoo.dat: -0 [001] 159685.803440: fib_table_lookup: table 254 oif 0 iif 1 proto 6 192.168.122.169/22 -> 192.168.122.1/50788 tos 0 scope 0 flags 0 ==> dev enp1s0 gw 0.0.0.0/:: err 0
trace-gentoo.dat: -0 [001] 159685.803443: timer_cancel: timer=0xffff8881049f2ef8
trace-gentoo.dat: -0 [001] 159685.803448: inet_sock_set_state: family=AF_INET protocol=IPPROTO_TCP sport=22 dport=50788 saddr=192.168.122.169 daddr=192.168.122.1 saddrv6=::ffff:192.168.122.169 daddrv6=::ffff:192.168.122.1 oldstate=TCP_SYN_RECV newstate=TCP_ESTABLISHED
trace-gentoo.dat: -0 [001] 159685.803450: kfree: (skb_release_data+0x88) call_site=skb_release_data+0x88 ptr=0xffff888106235600
trace-gentoo.dat: -0 [001] 159685.803450: kmem_cache_free: (tcp_rcv_state_process+0xa9e) call_site=tcp_rcv_state_process+0xa9e ptr=0xffff888107a2d200 name=skbuff_head_cache
trace-gentoo.dat: -0 [001] 159685.803452: sched_waking: comm=sshd pid=421 prio=120 target_cpu=001
trace-gentoo.dat: -0 [001] 159685.803454: sched_wakeup: sshd:421 [120] CPU:001
trace-gentoo.dat: -0 [001] 159685.803455: napi_poll: napi poll on napi struct 0xffff888106b0a808 for device enp1s0 work 1 budget 64
trace-gentoo.dat: -0 [001] 159685.803455: softirq_exit: vec=3 [action=NET_RX]
trace-gentoo.dat: -0 [001] 159685.803455: cpu_idle: state=4294967295 cpu_id=1
trace-gentoo.dat: -0 [001] 159685.803456: rcu_utilization: Start context switch
trace-gentoo.dat: -0 [001] 159685.803456: rcu_utilization: End context switch
trace-gentoo.dat: -0 [001] 159685.803457: sched_switch: swapper/1:0 [120] R ==> sshd:421 [120]
trace-gentoo.dat: -0 [001] 159685.803458: tlb_flush: pages=-1 reason=flush on task switch (0)
trace-gentoo.dat: sshd-421 [001] 159685.803464: sys_exit: NR 270 = 1
trace-gentoo.dat: sshd-421 [001] 159685.803465: x86_fpu_regs_activated: x86/fpu: 0xffff88810687ee00 load: 1 xfeatures: 2 xcomp_bv: 8000000000000007
trace-gentoo.dat: sshd-421 [001] 159685.803468: sys_enter: NR 14 (2, 7ffcc43070c0, 0, 8, 7ffcc43070c0, 7ffcc4306ee0)
trace-gentoo.dat: sshd-421 [001] 159685.803468: sys_exit: NR 14 = 0
trace-gentoo.dat: sshd-421 [001] 159685.803470: sys_enter: NR 43 (3, 7ffcc4306fc0, 7ffcc4306fa8, 8, 7ffcc43070c0, 7ffcc4306ee0)
trace-gentoo.dat: sshd-421 [001] 159685.803471: kmem_cache_alloc: (sock_alloc_inode+0x12) call_site=sock_alloc_inode+0x12 ptr=0xffff888107db7c80 bytes_req=768 bytes_alloc=768 gfp_flags=GFP_KERNEL
trace-gentoo.dat: sshd-421 [001] 159685.803472: kmem_cache_alloc: (__d_alloc+0x1b) call_site=__d_alloc+0x1b ptr=0xffff888105615d80 bytes_req=192 bytes_alloc=192 gfp_flags=GFP_KERNEL
trace-gentoo.dat: sshd-421 [001] 159685.803473: kmem_cache_alloc: (__alloc_file+0x21) call_site=__alloc_file+0x21 ptr=0xffff888101cd8c00 bytes_req=256 bytes_alloc=256 gfp_flags=GFP_KERNEL|__GFP_ZERO
trace-gentoo.dat: sshd-421 [001] 159685.803474: kfree: (__reqsk_free+0x14) call_site=__reqsk_free+0x14 ptr=(nil)
trace-gentoo.dat: sshd-421 [001] 159685.803474: kfree: (__reqsk_free+0x2e) call_site=__reqsk_free+0x2e ptr=(nil)
trace-gentoo.dat: sshd-421 [001] 159685.803474: kmem_cache_free: (inet_csk_accept+0x1fd) call_site=inet_csk_accept+0x1fd ptr=0xffff8881049f2e60 name=request_sock_TCP
trace-gentoo.dat: sshd-421 [001] 159685.803476: sys_exit: NR 43 = 5
trace-gentoo.dat: sshd-421 [001] 159685.803477: sys_enter: NR 72 (5, 3, 7ffcc4306fa8, 8, 7ffcc43070c0, 7ffcc4306ee0)
trace-gentoo.dat: sshd-421 [001] 159685.803477: sys_exit: NR 72 = 2
trace-gentoo.dat: sshd-421 [001] 159685.803478: sys_enter: NR 39 (563efed3940f, 563efed3a120, 8b, 563efed3953b, 7, 0)
trace-gentoo.dat: sshd-421 [001] 159685.803479: sys_exit: NR 39 = 421
trace-gentoo.dat: sshd-421 [001] 159685.803485: sys_enter: NR 22 (7ffcc4306fb8, 5, 7ffcc4306e00, 7ffcc4306e00, 7ffcc4306e00, 7ffcc43066f0)
trace-gentoo.dat: sshd-421 [001] 159685.803485: kmem_cache_alloc: (alloc_inode+0x2b) call_site=alloc_inode+0x2b ptr=0xffff888107cd8a60 bytes_req=600 bytes_alloc=600 gfp_flags=GFP_KERNEL
trace-gentoo.dat: sshd-421 [001] 159685.803486: kmalloc: (alloc_pipe_info+0x62) call_site=alloc_pipe_info+0x62 ptr=0xffff888100b45240 bytes_req=168 bytes_alloc=192 gfp_flags=GFP_KERNEL_ACCOUNT|__GFP_ZERO
trace-gentoo.dat: sshd-421 [001] 159685.803487: kmalloc: (alloc_pipe_info+0xe8) call_site=alloc_pipe_info+0xe8 ptr=0xffff88810834f800 bytes_req=640 bytes_alloc=1024 gfp_flags=GFP_KERNEL_ACCOUNT|__GFP_ZERO
trace-gentoo.dat: sshd-421 [001] 159685.803487: kmem_cache_alloc: (__d_alloc+0x1b) call_site=__d_alloc+0x1b ptr=0xffff888105615cc0 bytes_req=192 bytes_alloc=192 gfp_flags=GFP_KERNEL
trace-gentoo.dat: sshd-421 [001] 159685.803487: kmem_cache_alloc: (__alloc_file+0x21) call_site=__alloc_file+0x21 ptr=0xffff888101cd8f00 bytes_req=256 bytes_alloc=256 gfp_flags=GFP_KERNEL|__GFP_ZERO
trace-gentoo.dat: sshd-421 [001] 159685.803488: kmem_cache_alloc: (__alloc_file+0x21) call_site=__alloc_file+0x21 ptr=0xffff888101cd8d00 bytes_req=256 bytes_alloc=256 gfp_flags=GFP_KERNEL|__GFP_ZERO
trace-gentoo.dat: sshd-421 [001] 159685.803488: sys_exit: NR 22 = 0
Finally, it would be good to visualize this with (KernelShark)[https://www.kernelshark.org].
KernelShark can connect a host and guest trace file with the append (-a) option.
kernelshark /tmp/trace.dat -a /tmp/trace-gentoo.dat
The above tells KernelShark that the /tmp/trace-gentoo.dat file is a guest file for
/tmp/trace.dat, which is the host, and something like the following will appear.
Turn off all the current CPUs for both the host and the guest(s). Note that if not all CPUs are selected
(as is the case if there's more than 16 CPUs, it will only show the first 16), you may need to select the all
checkbox once to select all the CPUs and then again to deselect them all.
Now all the CPUs should be off.
This time select the KVM Combo plots menu.
And then select the vCPUs you want to show (here I selected all for all of them).
Now you will see all the guest vCPUs plotted on top of the host threads that run them. Here I placed the mouse between the graph and the table (see the double arrow cursor) to expand the graph to see all 8 of the guest vCPUs.
The guest CPU 0 is on top of the host thread CPU 0/KVM which has process ID 351640.
Now zoom in to see a bit more detail. This is done by selecting the area that you want to
see and press and hold the left mouse button and move the cursor to the right to where you want
the area to stop. When you let go, the view will zoom in so that the window contains only what you
selected. You can also use the +, - buttons at the top to zoom in and out, as well as the ++ to zoom all
the way in and the -- to zoom all the way out.
And zoom in again.
Which gives us a much better detail of what is happening.
The above shows the KVM entry event for vCPU 5 is selected. This is seen in both the graph as well as the table. The first column in the table denotes the file that was read. Where 0 is the first file, 1 is the second, and so on. It is also color coded where the color of that number matches the CPU color in the graph. In this example, the darker shaded color represents the host CPUs and the lighter shaded color is the guest. Note that the colors may be different for different scenarios, but the color in the table column will still match the color in the graph for the same data file (host or guest).
Looking at CPU 5 on the graph, it starts with a hollow green rectangle. That represents the wake up time of
the host thread (CPU 6/KVM). The start of the green rectangle is at the time the task was woken up (as determined
by the sched_waking event), and the end of the green rectangle is the time it starts executing on the CPU (as
determined by the sched_switch event). Each upward tick is an event, and if you click on it, it will select the
same event that is in the table below.
The line that attaches the host plot to the guest plot above it (the one that is selected) is the KVM entry event
(VMENTER). This shows you when the physical CPU (39 as seen in the CPU column in the table) transferred from the
host to the guest. Now all the events that happen on that physical CPU will be in the context of the guest until it returns
back to the host. But wait! There's events on the host before the line from the guest comes back down to the host! How did that happen?
That's because KernelShark uses the kvm exit trace event to know when the CPU switches back to the host context.
Unfortunately, there's other KVM events (and possibly other low level events like MSR events) that get called after the
CPU transferred from guest to host context and before the kvm exit event was triggered. You will notice that you will not
see any guest events after the first host event up to the kvm exit event.