# tracer: nop # # entries-in-buffer/entries-written: 149482/110347295 #P:2 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | <...>-2147 [001] d..1 174.853824: user_exit: <...>-2147 [001] d.h1 174.853832: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h2 174.853835: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d.h1 174.853838: hrtimer_expire_entry: hrtimer=c172aa50 function=tick_sched_timer now=174845014498 <...>-2147 [001] d.h1 174.853841: softirq_raise: vec=1 [action=TIMER] <...>-2147 [001] d.h1 174.853843: rcu_utilization: Start scheduler-tick <...>-2147 [001] d.h1 174.853846: rcu_utilization: End scheduler-tick <...>-2147 [001] d.h2 174.853849: sched_stat_runtime: comm=stress pid=2147 runtime=4065015110 [ns] vruntime=14821335628 [ns] <...>-2147 [001] d.h1 174.853856: hrtimer_expire_exit: hrtimer=c172aa50 <...>-2147 [001] d.h2 174.853858: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=174850000000 softexpires=174850000000 <...>-2147 [001] d.h1 174.853862: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] ..s1 174.853867: softirq_entry: vec=1 [action=TIMER] <...>-2147 [001] d.s2 174.853874: timer_cancel: timer=c172bcf8 <...>-2147 [001] d.s1 174.853876: timer_expire_entry: timer=c172bcf8 function=delayed_work_timer_fn now=4294942266 <...>-2147 [001] d.s2 174.853880: workqueue_queue_work: work struct=c172bce8 function=vmstat_update workqueue=ef08f100 req_cpu=8 cpu=1 <...>-2147 [001] d.s2 174.853882: workqueue_activate_work: work struct c172bce8 <...>-2147 [001] d.s4 174.853887: sched_stat_runtime: comm=stress pid=2147 runtime=37625 [ns] vruntime=14821373253 [ns] <...>-2147 [001] dns4 174.853893: sched_wakeup: comm=kworker/1:1 pid=391 prio=120 success=1 target_cpu=001 <...>-2147 [001] dns1 174.853897: timer_expire_exit: timer=c172bcf8 <...>-2147 [001] dns2 174.853917: timer_cancel: timer=ee938234 <...>-2147 [001] dns1 174.853919: timer_expire_entry: timer=ee938234 function=delayed_work_timer_fn now=4294942266 <...>-2147 [001] dns2 174.853922: workqueue_queue_work: work struct=ee938224 function=bdi_writeback_workfn workqueue=ef227e00 req_cpu=8 cpu=4294967295 <...>-2147 [001] dns2 174.853924: workqueue_activate_work: work struct ee938224 <...>-2147 [001] dns1 174.853929: timer_expire_exit: timer=ee938234 <...>-2147 [001] dnH2 174.853935: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dnH3 174.853939: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] dnH3 174.853944: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=174850000000 softexpires=174850000000 <...>-2147 [001] .ns1 174.853950: softirq_exit: vec=1 [action=TIMER] <...>-2147 [001] dn.1 174.853954: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dn.2 174.853957: rcu_utilization: Start context switch <...>-2147 [001] dn.2 174.853959: rcu_utilization: End context switch <...>-2147 [001] d..3 174.853964: sched_switch: prev_comm=stress prev_pid=2147 prev_prio=120 prev_state=R ==> next_comm=kworker/1:1 next_pid=391 next_prio=120 <...>-391 [001] ...1 174.853975: workqueue_execute_start: work struct c172bce8: function vmstat_update <...>-391 [001] d..2 174.853990: timer_start: timer=c172bcf8 function=delayed_work_timer_fn expires=175104 [timeout=200134] <...>-391 [001] ...1 174.853993: workqueue_execute_end: work struct c172bce8 <...>-391 [001] ...2 174.853997: rcu_utilization: Start context switch <...>-391 [001] ...2 174.853999: rcu_utilization: End context switch <...>-391 [001] d..3 174.854002: sched_stat_runtime: comm=kworker/1:1 pid=391 runtime=115125 [ns] vruntime=14815488378 [ns] <...>-391 [001] d..3 174.854007: sched_switch: prev_comm=kworker/1:1 prev_pid=391 prev_prio=120 prev_state=S ==> next_comm=stress next_pid=2147 next_prio=120 <...>-2147 [001] d..1 174.854014: user_enter: <...>-2147 [001] d..1 174.854020: user_exit: <...>-2147 [001] d..1 174.854023: user_enter: <...>-2147 [001] d..1 174.858824: user_exit: <...>-2147 [001] d.h1 174.858830: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h2 174.858834: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d.h1 174.858836: hrtimer_expire_entry: hrtimer=c172aa50 function=tick_sched_timer now=174850012915 <...>-2147 [001] d.h1 174.858841: softirq_raise: vec=1 [action=TIMER] <...>-2147 [001] d.h1 174.858843: rcu_utilization: Start scheduler-tick <...>-2147 [001] d.h1 174.858846: rcu_utilization: End scheduler-tick <...>-2147 [001] d.h2 174.858850: sched_stat_runtime: comm=stress pid=2147 runtime=4847625 [ns] vruntime=14826220878 [ns] <...>-2147 [001] d.h1 174.858857: hrtimer_expire_exit: hrtimer=c172aa50 <...>-2147 [001] d.h2 174.858859: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=174855000000 softexpires=174855000000 <...>-2147 [001] d.h1 174.858863: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] ..s1 174.858868: softirq_entry: vec=1 [action=TIMER] <...>-2147 [001] ..s1 174.858871: softirq_exit: vec=1 [action=TIMER] <...>-2147 [001] d..1 174.858884: tick_stop: success=yes msg= <...>-2147 [001] d..2 174.858887: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d..2 174.858890: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=240820000000 softexpires=240820000000 <...>-2147 [001] d..1 174.858894: user_enter: <...>-2147 [001] d..1 186.385626: user_exit: <...>-2147 [001] d.h1 186.385631: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h2 186.385634: hrtimer_cancel: hrtimer=ee853f20 <...>-2147 [001] d.h1 186.385637: hrtimer_expire_entry: hrtimer=ee853f20 function=hrtimer_wakeup now=186376813546 <...>-2147 [001] d.h2 186.385642: sched_migrate_task: comm=sleep pid=1977 prio=120 orig_cpu=1 dest_cpu=0 <...>-2147 [001] d.h1 186.385647: hrtimer_expire_exit: hrtimer=ee853f20 <...>-2147 [001] d.h1 186.385650: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] d..1 186.385660: user_enter: <...>-2147 [001] d..1 240.828823: user_exit: <...>-2147 [001] d.h1 240.828829: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h2 240.828832: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d.h1 240.828835: hrtimer_expire_entry: hrtimer=c172aa50 function=tick_sched_timer now=240820011613 <...>-2147 [001] d.h1 240.828838: softirq_raise: vec=1 [action=TIMER] <...>-2147 [001] d.h1 240.828840: rcu_utilization: Start scheduler-tick <...>-2147 [001] d.h1 240.828842: rcu_utilization: End scheduler-tick <...>-2147 [001] d.h2 240.828847: sched_stat_runtime: comm=stress pid=2147 runtime=65969996540 [ns] vruntime=80796217418 [ns] <...>-2147 [001] d.h1 240.828854: hrtimer_expire_exit: hrtimer=c172aa50 <...>-2147 [001] d.h2 240.828856: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=240825000000 softexpires=240825000000 <...>-2147 [001] d.h1 240.828859: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] ..s1 240.828864: softirq_entry: vec=1 [action=TIMER] <...>-2147 [001] d.s2 240.828921: timer_cancel: timer=c068da58 <...>-2147 [001] d.s1 240.828923: timer_expire_entry: timer=c068da58 function=delayed_work_timer_fn now=4294955461 <...>-2147 [001] d.s2 240.828927: workqueue_queue_work: work struct=c068da48 function=neigh_periodic_work workqueue=ef08f600 req_cpu=8 cpu=1 <...>-2147 [001] d.s2 240.828929: workqueue_activate_work: work struct c068da48 <...>-2147 [001] d.s4 240.828933: sched_stat_runtime: comm=stress pid=2147 runtime=87291 [ns] vruntime=80796304709 [ns] <...>-2147 [001] dns4 240.828940: sched_wakeup: comm=kworker/1:1 pid=391 prio=120 success=1 target_cpu=001 <...>-2147 [001] dns1 240.828943: timer_expire_exit: timer=c068da58 <...>-2147 [001] dns2 240.829244: timer_cancel: timer=ef371ea4 <...>-2147 [001] dnH2 240.829252: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dnH3 240.829256: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] dnH3 240.829262: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=240825000000 softexpires=240825000000 <...>-2147 [001] .ns1 240.829270: timer_expire_entry: timer=ef371ea4 function=process_timeout now=4294955461 <...>-2147 [001] dns2 240.829274: sched_migrate_task: comm=khungtaskd pid=401 prio=120 orig_cpu=1 dest_cpu=0 <...>-2147 [001] .ns1 240.829278: timer_expire_exit: timer=ef371ea4 <...>-2147 [001] .ns1 240.829281: softirq_exit: vec=1 [action=TIMER] <...>-2147 [001] dn.1 240.829285: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dn.2 240.829288: rcu_utilization: Start context switch <...>-2147 [001] dn.2 240.829290: rcu_utilization: End context switch <...>-2147 [001] d..3 240.829294: sched_switch: prev_comm=stress prev_pid=2147 prev_prio=120 prev_state=R ==> next_comm=kworker/1:1 next_pid=391 next_prio=120 <...>-391 [001] ...1 240.829304: workqueue_execute_start: work struct c068da48: function neigh_periodic_work <...>-391 [001] d.s3 240.829310: timer_start: timer=c068da58 function=delayed_work_timer_fn expires=4294958464 [timeout=3003] <...>-391 [001] ...1 240.829315: workqueue_execute_end: work struct c068da48 <...>-391 [001] ...2 240.829319: rcu_utilization: Start context switch <...>-391 [001] ...2 240.829321: rcu_utilization: End context switch <...>-391 [001] d..3 240.829323: sched_stat_runtime: comm=kworker/1:1 pid=391 runtime=390000 [ns] vruntime=80790694709 [ns] <...>-391 [001] d..3 240.829327: sched_switch: prev_comm=kworker/1:1 prev_pid=391 prev_prio=120 prev_state=S ==> next_comm=stress next_pid=2147 next_prio=120 <...>-2147 [001] d..1 240.829334: user_enter: <...>-2147 [001] d..1 240.829341: user_exit: <...>-2147 [001] d..1 240.829343: user_enter: <...>-2147 [001] d..1 240.833824: user_exit: <...>-2147 [001] d.h1 240.833829: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h2 240.833832: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d.h1 240.833835: hrtimer_expire_entry: hrtimer=c172aa50 function=tick_sched_timer now=240825011905 <...>-2147 [001] d.h1 240.833839: softirq_raise: vec=1 [action=TIMER] <...>-2147 [001] d.h1 240.833841: rcu_utilization: Start scheduler-tick <...>-2147 [001] d.h1 240.833844: rcu_utilization: End scheduler-tick <...>-2147 [001] d.h2 240.833848: sched_stat_runtime: comm=stress pid=2147 runtime=4523834 [ns] vruntime=80800828543 [ns] <...>-2147 [001] d.h1 240.833854: hrtimer_expire_exit: hrtimer=c172aa50 <...>-2147 [001] d.h2 240.833856: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=240830000000 softexpires=240830000000 <...>-2147 [001] d.h1 240.833859: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] ..s1 240.833864: softirq_entry: vec=1 [action=TIMER] <...>-2147 [001] ..s1 240.833867: softirq_exit: vec=1 [action=TIMER] <...>-2147 [001] d..1 240.833878: tick_stop: success=yes msg= <...>-2147 [001] d..2 240.833881: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d..2 240.833884: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=602075000000 softexpires=602075000000 <...>-2147 [001] d..1 240.833888: user_enter: <...>-2147 [001] d..1 302.563901: user_exit: <...>-2147 [001] d.h2 302.563909: sched_stat_runtime: comm=stress pid=2147 runtime=61730061806 [ns] vruntime=142530890349 [ns] <...>-2147 [001] dnh2 302.563917: sched_wakeup: comm=kworker/u4:1 pid=24 prio=120 success=1 target_cpu=001 <...>-2147 [001] dn.1 302.563923: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dnh1 302.563928: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dnh2 302.563934: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] dnh2 302.563940: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=302560000000 softexpires=302560000000 <...>-2147 [001] dn.1 302.563945: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dn.2 302.563948: rcu_utilization: Start context switch <...>-2147 [001] dn.2 302.563950: rcu_utilization: End context switch <...>-2147 [001] d..3 302.563954: sched_switch: prev_comm=stress prev_pid=2147 prev_prio=120 prev_state=R ==> next_comm=kworker/u4:1 next_pid=24 next_prio=120 <...>-24 [001] ...1 302.563967: sched_kthread_stop: comm=kworker/u4:3 pid=1202 <...>-24 [001] ...2 302.563976: rcu_utilization: Start context switch <...>-24 [001] ...2 302.563978: rcu_utilization: End context switch <...>-24 [001] d..3 302.563981: sched_stat_runtime: comm=kworker/u4:1 pid=24 runtime=71333 [ns] vruntime=142524961682 [ns] <...>-24 [001] d..3 302.563985: sched_switch: prev_comm=kworker/u4:1 prev_pid=24 prev_prio=120 prev_state=D ==> next_comm=stress next_pid=2147 next_prio=120 <...>-2147 [001] d..1 302.563991: user_enter: <...>-2147 [001] d..1 302.563997: user_exit: <...>-2147 [001] d..1 302.564000: user_enter: <...>-2147 [001] d..1 302.564007: user_exit: <...>-2147 [001] d.h2 302.564013: sched_stat_runtime: comm=stress pid=2147 runtime=31875 [ns] vruntime=142530922224 [ns] <...>-2147 [001] dnh2 302.564018: sched_wakeup: comm=kworker/u4:1 pid=24 prio=120 success=1 target_cpu=001 <...>-2147 [001] dn.1 302.564023: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dn.1 302.564035: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dn.2 302.564038: rcu_utilization: Start context switch <...>-2147 [001] dn.2 302.564041: rcu_utilization: End context switch <...>-2147 [001] d..3 302.564045: sched_switch: prev_comm=stress prev_pid=2147 prev_prio=120 prev_state=R ==> next_comm=kworker/u4:1 next_pid=24 next_prio=120 <...>-24 [001] ...1 302.564054: sched_kthread_stop_ret: ret=0 <...>-24 [001] ...1 302.564056: kfree: call_site=c0036664 ptr=ef12bb80 <...>-24 [001] ...1 302.564061: sched_kthread_stop: comm=kworker/u4:2 pid=1177 <...>-24 [001] ...2 302.564068: rcu_utilization: Start context switch <...>-24 [001] ...2 302.564070: rcu_utilization: End context switch <...>-24 [001] d..3 302.564073: sched_stat_runtime: comm=kworker/u4:1 pid=24 runtime=60542 [ns] vruntime=142525022224 [ns] <...>-24 [001] d..3 302.564076: sched_switch: prev_comm=kworker/u4:1 prev_pid=24 prev_prio=120 prev_state=D ==> next_comm=stress next_pid=2147 next_prio=120 <...>-2147 [001] d..1 302.564082: user_enter: <...>-2147 [001] d..1 302.564088: user_exit: <...>-2147 [001] d..1 302.564090: user_enter: <...>-2147 [001] d..1 302.564128: user_exit: <...>-2147 [001] d.h2 302.564133: sched_stat_runtime: comm=stress pid=2147 runtime=59917 [ns] vruntime=142530982141 [ns] <...>-2147 [001] dnh2 302.564138: sched_wakeup: comm=kworker/u4:1 pid=24 prio=120 success=1 target_cpu=001 <...>-2147 [001] dn.1 302.564143: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dn.1 302.564149: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dn.2 302.564152: rcu_utilization: Start context switch <...>-2147 [001] dn.2 302.564154: rcu_utilization: End context switch <...>-2147 [001] d..3 302.564157: sched_switch: prev_comm=stress prev_pid=2147 prev_prio=120 prev_state=R ==> next_comm=kworker/u4:1 next_pid=24 next_prio=120 <...>-24 [001] ...1 302.564165: sched_kthread_stop_ret: ret=0 <...>-24 [001] ...1 302.564167: kfree: call_site=c0036664 ptr=ef25bc00 <...>-24 [001] ...2 302.564172: rcu_utilization: Start context switch <...>-24 [001] ...2 302.564174: rcu_utilization: End context switch <...>-24 [001] d..3 302.564177: sched_stat_runtime: comm=kworker/u4:1 pid=24 runtime=44125 [ns] vruntime=142525066349 [ns] <...>-24 [001] d..3 302.564180: sched_switch: prev_comm=kworker/u4:1 prev_pid=24 prev_prio=120 prev_state=S ==> next_comm=stress next_pid=2147 next_prio=120 <...>-2147 [001] d..1 302.564186: user_enter: <...>-2147 [001] d..1 302.564191: user_exit: <...>-2147 [001] d..1 302.564193: user_enter: <...>-2147 [001] d..1 302.568823: user_exit: <...>-2147 [001] d.h1 302.568829: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h2 302.568833: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d.h1 302.568836: hrtimer_expire_entry: hrtimer=c172aa50 function=tick_sched_timer now=302560012976 <...>-2147 [001] d.h1 302.568840: softirq_raise: vec=1 [action=TIMER] <...>-2147 [001] d.h1 302.568842: rcu_utilization: Start scheduler-tick <...>-2147 [001] d.h1 302.568845: rcu_utilization: End scheduler-tick <...>-2147 [001] d.h2 302.568849: sched_stat_runtime: comm=stress pid=2147 runtime=4671791 [ns] vruntime=142535653932 [ns] <...>-2147 [001] d.h1 302.568856: hrtimer_expire_exit: hrtimer=c172aa50 <...>-2147 [001] d.h2 302.568858: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=302565000000 softexpires=302565000000 <...>-2147 [001] d.h1 302.568861: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] ..s1 302.568867: softirq_entry: vec=1 [action=TIMER] <...>-2147 [001] d.s2 302.568950: timer_cancel: timer=c068da58 <...>-2147 [001] d.s1 302.568952: timer_expire_entry: timer=c068da58 function=delayed_work_timer_fn now=513 <...>-2147 [001] d.s2 302.568955: workqueue_queue_work: work struct=c068da48 function=neigh_periodic_work workqueue=ef08f600 req_cpu=8 cpu=1 <...>-2147 [001] d.s2 302.568957: workqueue_activate_work: work struct c068da48 <...>-2147 [001] d.s4 302.568962: sched_stat_runtime: comm=stress pid=2147 runtime=112625 [ns] vruntime=142535766557 [ns] <...>-2147 [001] dns4 302.568968: sched_wakeup: comm=kworker/1:1 pid=391 prio=120 success=1 target_cpu=001 <...>-2147 [001] dns1 302.568971: timer_expire_exit: timer=c068da58 <...>-2147 [001] .ns1 302.569224: softirq_exit: vec=1 [action=TIMER] <...>-2147 [001] dn.1 302.569228: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dn.2 302.569232: rcu_utilization: Start context switch <...>-2147 [001] dn.2 302.569234: rcu_utilization: End context switch <...>-2147 [001] d..3 302.569237: sched_switch: prev_comm=stress prev_pid=2147 prev_prio=120 prev_state=R ==> next_comm=kworker/1:1 next_pid=391 next_prio=120 <...>-391 [001] ...1 302.569246: workqueue_execute_start: work struct c068da48: function neigh_periodic_work <...>-391 [001] d.s3 302.569251: timer_start: timer=c068da58 function=delayed_work_timer_fn expires=3520 [timeout=3007] <...>-391 [001] ...1 302.569255: workqueue_execute_end: work struct c068da48 <...>-391 [001] ...2 302.569259: rcu_utilization: Start context switch <...>-391 [001] ...2 302.569261: rcu_utilization: End context switch <...>-391 [001] d..3 302.569264: sched_stat_runtime: comm=kworker/1:1 pid=391 runtime=302417 [ns] vruntime=142530068974 [ns] <...>-391 [001] d..3 302.569268: sched_switch: prev_comm=kworker/1:1 prev_pid=391 prev_prio=120 prev_state=S ==> next_comm=stress next_pid=2147 next_prio=120 <...>-2147 [001] d..1 302.569274: user_enter: <...>-2147 [001] d..1 302.569280: user_exit: <...>-2147 [001] d..1 302.569282: user_enter: <...>-2147 [001] d..1 302.573823: user_exit: <...>-2147 [001] d.h1 302.573828: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h2 302.573832: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d.h1 302.573835: hrtimer_expire_entry: hrtimer=c172aa50 function=tick_sched_timer now=302565011476 <...>-2147 [001] d.h1 302.573838: softirq_raise: vec=1 [action=TIMER] <...>-2147 [001] d.h1 302.573840: rcu_utilization: Start scheduler-tick <...>-2147 [001] d.h1 302.573843: rcu_utilization: End scheduler-tick <...>-2147 [001] d.h2 302.573847: sched_stat_runtime: comm=stress pid=2147 runtime=4582667 [ns] vruntime=142540349224 [ns] <...>-2147 [001] d.h1 302.573853: hrtimer_expire_exit: hrtimer=c172aa50 <...>-2147 [001] d.h2 302.573855: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=302570000000 softexpires=302570000000 <...>-2147 [001] d.h1 302.573858: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] ..s1 302.573864: softirq_entry: vec=1 [action=TIMER] <...>-2147 [001] ..s1 302.573866: softirq_exit: vec=1 [action=TIMER] <...>-2147 [001] d..1 302.573875: tick_stop: success=yes msg= <...>-2147 [001] d..2 302.573878: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d..2 302.573881: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=602075000000 softexpires=602075000000 <...>-2147 [001] d..1 302.573885: user_enter: <...>-2147 [001] d..1 392.052372: user_exit: <...>-2147 [001] d.h1 392.052379: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h1 392.052384: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] d..1 392.052393: user_enter: <...>-2147 [001] d..1 481.530871: user_exit: <...>-2147 [001] d.h1 481.530877: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h1 481.530881: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] d..1 481.530890: user_enter: <...>-2147 [001] d..1 571.009368: user_exit: <...>-2147 [001] d.h1 571.009374: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h1 571.009378: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] d..1 571.009386: user_enter: <...>-2147 [001] d..1 602.083822: user_exit: <...>-2147 [001] d.h1 602.083828: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h2 602.083831: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d.h1 602.083833: hrtimer_expire_entry: hrtimer=c172aa50 function=tick_sched_timer now=602075012411 <...>-2147 [001] d.h1 602.083838: softirq_raise: vec=1 [action=TIMER] <...>-2147 [001] d.h1 602.083840: rcu_utilization: Start scheduler-tick <...>-2147 [001] d.h1 602.083843: rcu_utilization: End scheduler-tick <...>-2147 [001] d.h2 602.083847: sched_stat_runtime: comm=stress pid=2147 runtime=299509999857 [ns] vruntime=442050349081 [ns] <...>-2147 [001] d.h1 602.083860: hrtimer_expire_exit: hrtimer=c172aa50 <...>-2147 [001] d.h2 602.083862: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=602080000000 softexpires=602080000000 <...>-2147 [001] d.h1 602.083865: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] ..s1 602.083870: softirq_entry: vec=1 [action=TIMER] <...>-2147 [001] d.s2 602.083953: timer_cancel: timer=c068da58 <...>-2147 [001] d.s1 602.083956: timer_expire_entry: timer=c068da58 function=delayed_work_timer_fn now=60416 <...>-2147 [001] d.s2 602.083959: workqueue_queue_work: work struct=c068da48 function=neigh_periodic_work workqueue=ef08f600 req_cpu=8 cpu=1 <...>-2147 [001] d.s2 602.083961: workqueue_activate_work: work struct c068da48 <...>-2147 [001] d.s4 602.083966: sched_stat_runtime: comm=stress pid=2147 runtime=119500 [ns] vruntime=442050468581 [ns] <...>-2147 [001] dns4 602.083973: sched_wakeup: comm=kworker/1:1 pid=391 prio=120 success=1 target_cpu=001 <...>-2147 [001] dns1 602.083976: timer_expire_exit: timer=c068da58 <...>-2147 [001] dns2 602.085485: timer_cancel: timer=c06fc254 <...>-2147 [001] dnH2 602.085492: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dnH3 602.085497: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] dnH3 602.085503: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=602080000000 softexpires=602080000000 <...>-2147 [001] .ns1 602.085510: timer_expire_entry: timer=c06fc254 function=inet_frag_secret_rebuild now=60416 <...>-2147 [001] .ns2 602.085513: get_random_bytes: nbytes 4 caller inet_frag_secret_rebuild+0x60/0x114 <...>-2147 [001] .ns2 602.085516: extract_entropy: nonblocking pool: nbytes 4 entropy_count 43 caller get_random_bytes+0x4c/0xc8 <...>-2147 [001] .ns2 602.085519: debit_entropy: nonblocking: debit_bits 32 <...>-2147 [001] dns3 602.085528: mix_pool_bytes_nolock: nonblocking pool: bytes 20 caller extract_buf+0x8c/0x120 <...>-2147 [001] dns2 602.085546: timer_start: timer=c06fc254 function=inet_frag_secret_rebuild expires=180736 [timeout=120320] <...>-2147 [001] .ns1 602.085549: timer_expire_exit: timer=c06fc254 <...>-2147 [001] .ns1 602.085551: softirq_exit: vec=1 [action=TIMER] <...>-2147 [001] dn.1 602.085556: tick_stop: success=no msg=more than 1 task in runqueue <...>-2147 [001] dn.2 602.085559: rcu_utilization: Start context switch <...>-2147 [001] dn.2 602.085561: rcu_utilization: End context switch <...>-2147 [001] d..3 602.085566: sched_switch: prev_comm=stress prev_pid=2147 prev_prio=120 prev_state=R ==> next_comm=kworker/1:1 next_pid=391 next_prio=120 <...>-391 [001] ...1 602.085576: workqueue_execute_start: work struct c068da48: function neigh_periodic_work <...>-391 [001] d.s3 602.085581: timer_start: timer=c068da58 function=delayed_work_timer_fn expires=63424 [timeout=3008] <...>-391 [001] ...1 602.085584: workqueue_execute_end: work struct c068da48 <...>-391 [001] ...2 602.085587: rcu_utilization: Start context switch <...>-391 [001] ...2 602.085589: rcu_utilization: End context switch <...>-391 [001] d..3 602.085592: sched_stat_runtime: comm=kworker/1:1 pid=391 runtime=1626167 [ns] vruntime=442046094748 [ns] <...>-391 [001] d..3 602.085598: sched_switch: prev_comm=kworker/1:1 prev_pid=391 prev_prio=120 prev_state=S ==> next_comm=stress next_pid=2147 next_prio=120 <...>-2147 [001] d..1 602.085604: user_enter: <...>-2147 [001] d..1 602.085610: user_exit: <...>-2147 [001] d..1 602.085612: user_enter: <...>-2147 [001] d..1 602.088822: user_exit: <...>-2147 [001] d.h1 602.088828: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h2 602.088831: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d.h1 602.088834: hrtimer_expire_entry: hrtimer=c172aa50 function=tick_sched_timer now=602080012327 <...>-2147 [001] d.h1 602.088838: softirq_raise: vec=1 [action=TIMER] <...>-2147 [001] d.h1 602.088841: rcu_utilization: Start scheduler-tick <...>-2147 [001] d.h1 602.088843: rcu_utilization: End scheduler-tick <...>-2147 [001] d.h2 602.088847: sched_stat_runtime: comm=stress pid=2147 runtime=3254916 [ns] vruntime=442053723497 [ns] <...>-2147 [001] d.h1 602.088854: hrtimer_expire_exit: hrtimer=c172aa50 <...>-2147 [001] d.h2 602.088856: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=602085000000 softexpires=602085000000 <...>-2147 [001] d.h1 602.088859: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] ..s1 602.088864: softirq_entry: vec=1 [action=TIMER] <...>-2147 [001] ..s1 602.088867: softirq_exit: vec=1 [action=TIMER] <...>-2147 [001] d..1 602.088879: tick_stop: success=yes msg= <...>-2147 [001] d..2 602.088881: hrtimer_cancel: hrtimer=c172aa50 <...>-2147 [001] d..2 602.088886: hrtimer_start: hrtimer=c172aa50 function=tick_sched_timer expires=1203675000000 softexpires=1203675000000 <...>-2147 [001] d..1 602.088890: user_enter: <...>-2147 [001] d..1 691.567378: user_exit: <...>-2147 [001] d.h1 691.567384: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h1 691.567390: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] d..1 691.567400: user_enter: <...>-2147 [001] d..1 781.045878: user_exit: <...>-2147 [001] d.h1 781.045884: irq_handler_entry: irq=30 name=arch_timer <...>-2147 [001] d.h1 781.045888: irq_handler_exit: irq=30 ret=handled <...>-2147 [001] d..1 781.045897: user_enter: ##### CPU 0 buffer started #### <...>-336 [000] ...1 869.604402: sys_exit: NR 192 = -1224941568