Ubuntu lost irq more about 200ms

We use TX2 to do Vslam. There are two process:

  1. vslam_proc cost CPU about 400%-500% and also use GPU resource.
  2. hrtimer_handler is a high resolution kernel timer thread. Period is 10ms.

We use kernel trace to log irq/hrtimer/sched items.

echo 1 > /sys/kernel/debug/tracing/events/irq/enable
echo 1 > /sys/kernel/debug/tracing/events/timer/hrtimer_expire_entry/enable
echo 1 > /sys/kernel/debug/tracing/events/timer/hrtimer_expire_exit/enable
echo 1 > /sys/kernel/debug/tracing/events/sched/sched_switch/enable

Run with long term, we found sometimes hrtimer_handler doesn’t execute every 10ms. And the same time, we found irq and sched_switch are lost. The whole trace message already attached below.

Here are some clue we found.

  1. hrtimer_handler execute timing 29319.875371->29319.885368(delta 10ms)->29320.080065(delta 200ms)->29320.085381 (delta 5 ms). hrtimer_handler internal is 200ms which we don’t want.
vslam_proc-25022 [005] d.h1 29319.875371: hrtimer_expire_entry: hrtimer=ffffffbffcf66c10 function=hrtimer_handler [uice] now=29319239325331
 vslam_proc-25022 [005] d.h1 29319.885368: hrtimer_expire_entry: hrtimer=ffffffbffcf66c10 function=hrtimer_handler [uice] now=29319249322277
 vslam_proc-25022 [005] d.h1 29320.080065: hrtimer_expire_entry: hrtimer=ffffffbffcf66c10 function=hrtimer_handler [uice] now=29319443997642
 vslam_proc-25022 [005] d.h1 29320.085381: hrtimer_expire_entry: hrtimer=ffffffbffcf66c10 function=hrtimer_handler [uice] now=29319449325332
  1. Both irq and sched_switch are lost 200ms. See log below 29319.887224->29320.080049.
    Why irq lost 200ms? kernel space spin_lock or disable irq global?
334  vslam_proc-7964  [004] d..3 29319.886923: sched_switch: prev_comm=vslam_proc prev_pid=7964 prev_prio=120 prev_state=S ==> next_comm=vslam_proc ne
335  vslam_proc-8060  [000] d.h1 29319.886925: softirq_raise: vec=3 [action=NET_RX]
336  vslam_proc-8060  [000] d.h1 29319.886931: irq_handler_exit: irq=45 ret=handled
337  vslam_proc-8060  [000] d.H1 29319.886932: irq_handler_entry: irq=42 name=ether_qos.common_irq
338  vslam_proc-8060  [000] d.H1 29319.886937: irq_handler_exit: irq=42 ret=handled
339  vslam_proc-8060  [000] ..s1 29319.886941: softirq_entry: vec=3 [action=NET_RX]
340  vslam_proc-8060  [000] ..s1 29319.886955: softirq_exit: vec=3 [action=NET_RX]
341  vslam_proc-8059  [001] d..3 29319.887223: sched_switch: prev_comm=vslam_proc prev_pid=8059 prev_prio=120 prev_state=S ==> next_comm=swapper/1 nex
342  vslam_proc-25021 [002] d..3 29319.887224: sched_switch: prev_comm=vslam_proc prev_pid=25021 prev_prio=120 prev_state=S ==> next_comm=swapper/2 ne
343  vslam_proc-25023 [004] d.h1 29320.080049: irq_handler_entry: irq=10 name=tegra186_timer4
344  vslam_proc-8024  [003] d.h1 29320.080050: irq_handler_entry: irq=9 name=tegra186_timer3
345  vslam_proc-8060  [000] d.h1 29320.080050: irq_handler_entry: irq=6 name=tegra186_timer0
346  vslam_proc-25022 [005] d.h1 29320.080050: irq_handler_entry: irq=11 name=tegra186_timer5

My question is how to locate the root cause of irq lost more than 200ms?
Does kernel provide more useful tool to debug such kind of issue?
Maybe our vslam_proc cpu load is too high(400%-500%)?

The whole log is below:

vslam_proc-25022 [005] d.h1 29319.875371: hrtimer_expire_entry: hrtimer=ffffffbffcf66c10 function=hrtimer_handler [uice] now=29319239325331
 vslam_proc-25022 [005] d.h1 29319.875399: hrtimer_expire_exit: hrtimer=ffffffbffcf66c10
 vslam_proc-25022 [005] d.h1 29319.875401: irq_handler_exit: irq=11 ret=handled
 vslam_proc-8023  [000] d.h1 29319.875645: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_proc-8023  [000] d.h1 29319.875654: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8023  [000] d.h1 29319.875659: irq_handler_exit: irq=45 ret=handled
 vslam_proc-8135  [003] d..3 29319.875659: sched_switch: prev_comm=vslam_proc prev_pid=8135 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=7965 next_prio=120
 vslam_proc-8023  [000] d.H1 29319.875662: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8023  [000] d.H1 29319.875667: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8023  [000] ..s1 29319.875668: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8023  [000] ..s1 29319.875682: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8023  [000] d.h1 29319.875777: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_proc-8023  [000] d.h1 29319.875785: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8023  [000] d.h1 29319.875790: irq_handler_exit: irq=45 ret=handled
 vslam_proc-8023  [000] d.H1 29319.875791: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8023  [000] d.H1 29319.875796: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8023  [000] ..s1 29319.875797: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-7965  [003] d..3 29319.875800: sched_switch: prev_comm=vslam_proc prev_pid=7965 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8022 next_prio=120
 vslam_proc-8023  [000] ..s1 29319.875805: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8023  [000] d.h1 29319.875926: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8023  [000] d.h1 29319.875931: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8023  [000] d.h1 29319.876008: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_proc-8023  [000] d.h1 29319.876017: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8023  [000] d.h1 29319.876022: irq_handler_exit: irq=44 ret=handled
 vslam_proc-8023  [000] ..s1 29319.876023: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8023  [000] d.s2 29319.876040: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-25022 [005] d.h1 29319.876047: irq_handler_entry: irq=11 name=tegra186_timer5
 vslam_proc-8023  [000] d.H1 29319.876047: irq_handler_entry: irq=6 name=tegra186_timer0
 vslam_proc-8022  [003] d.h1 29319.876048: irq_handler_entry: irq=9 name=tegra186_timer3
 vslam_proc-25023 [004] d.h1 29319.876049: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_proc-25021 [002] d.h1 29319.876050: irq_handler_entry: irq=8 name=tegra186_timer2
 vslam_proc-8059  [001] d.h1 29319.876050: irq_handler_entry: irq=7 name=tegra186_timer1
 vslam_proc-25022 [005] d.h1 29319.876050: hrtimer_expire_entry: hrtimer=ffffffc1f5c1b110 function=tick_sched_timer now=29319240004595
 vslam_proc-8022  [003] d.h1 29319.876051: hrtimer_expire_entry: hrtimer=ffffffc1f5bf9110 function=tick_sched_timer now=29319240005427
 vslam_proc-8023  [000] d.H1 29319.876051: hrtimer_expire_entry: hrtimer=ffffffc1f5bc6110 function=tick_sched_timer now=29319240005523
 vslam_proc-25023 [004] d.h1 29319.876053: hrtimer_expire_entry: hrtimer=ffffffc1f5c0a110 function=tick_sched_timer now=29319240007795
 vslam_proc-8023  [000] d.H1 29319.876053: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8022  [003] d.h1 29319.876053: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8023  [000] d.H1 29319.876055: softirq_raise: vec=9 [action=RCU]
 vslam_proc-8022  [003] d.h1 29319.876055: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25022 [005] d.h1 29319.876055: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25023 [004] d.h1 29319.876055: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8059  [001] d.h1 29319.876056: hrtimer_expire_entry: hrtimer=ffffffc1f5bd7110 function=tick_sched_timer now=29319240010899
 vslam_proc-25021 [002] d.h1 29319.876056: hrtimer_expire_entry: hrtimer=ffffffc1f5be8110 function=tick_sched_timer now=29319240010931
 vslam_proc-25023 [004] d.h1 29319.876056: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25022 [005] d.h1 29319.876056: softirq_raise: vec=9 [action=RCU]
 vslam_proc-8059  [001] d.h1 29319.876057: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25021 [002] d.h1 29319.876057: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8059  [001] d.h1 29319.876059: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25021 [002] d.h1 29319.876059: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25022 [005] d.h1 29319.876061: hrtimer_expire_exit: hrtimer=ffffffc1f5c1b110
 vslam_proc-25023 [004] d.h1 29319.876061: hrtimer_expire_exit: hrtimer=ffffffc1f5c0a110
 vslam_proc-8022  [003] d.h1 29319.876061: hrtimer_expire_exit: hrtimer=ffffffc1f5bf9110
 vslam_proc-8023  [000] d.H1 29319.876061: hrtimer_expire_exit: hrtimer=ffffffc1f5bc6110
 vslam_proc-25022 [005] d.h1 29319.876062: irq_handler_exit: irq=11 ret=handled
 vslam_proc-8023  [000] d.H1 29319.876062: irq_handler_exit: irq=6 ret=handled
 vslam_proc-8022  [003] d.h1 29319.876062: irq_handler_exit: irq=9 ret=handled
 vslam_proc-25023 [004] d.h1 29319.876062: irq_handler_exit: irq=10 ret=handled
 vslam_proc-8059  [001] d.h1 29319.876063: hrtimer_expire_exit: hrtimer=ffffffc1f5bd7110
 vslam_proc-25021 [002] d.h1 29319.876063: hrtimer_expire_exit: hrtimer=ffffffc1f5be8110
 vslam_proc-25022 [005] ..s1 29319.876064: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-8059  [001] d.h1 29319.876064: irq_handler_exit: irq=7 ret=handled
 vslam_proc-25021 [002] d.h1 29319.876064: irq_handler_exit: irq=8 ret=handled
 vslam_proc-8022  [003] ..s1 29319.876065: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-25023 [004] ..s1 29319.876065: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-25022 [005] ..s1 29319.876065: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25022 [005] ..s1 29319.876065: softirq_entry: vec=9 [action=RCU]
 vslam_proc-25023 [004] ..s1 29319.876065: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-8059  [001] ..s1 29319.876065: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-8022  [003] ..s1 29319.876065: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25021 [002] ..s1 29319.876066: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-8022  [003] ..s1 29319.876066: softirq_entry: vec=9 [action=RCU]
 vslam_proc-25023 [004] ..s1 29319.876066: softirq_entry: vec=9 [action=RCU]
 vslam_proc-8059  [001] ..s1 29319.876066: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25021 [002] ..s1 29319.876066: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25021 [002] ..s1 29319.876067: softirq_entry: vec=9 [action=RCU]
 vslam_proc-8059  [001] ..s1 29319.876067: softirq_entry: vec=9 [action=RCU]
 vslam_proc-8022  [003] ..s1 29319.876067: softirq_exit: vec=9 [action=RCU]
 vslam_proc-25023 [004] ..s1 29319.876067: softirq_exit: vec=9 [action=RCU]
 vslam_proc-25022 [005] ..s1 29319.876068: softirq_exit: vec=9 [action=RCU]
 vslam_proc-25021 [002] ..s1 29319.876069: softirq_exit: vec=9 [action=RCU]
 vslam_proc-8059  [001] ..s1 29319.876074: softirq_exit: vec=9 [action=RCU]
 vslam_proc-8023  [000] ..s1 29319.876088: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8023  [000] ..s2 29319.878070: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-8023  [000] .ns2 29319.878088: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-8023  [000] .ns2 29319.878088: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8022  [003] d..3 29319.878123: sched_switch: prev_comm=vslam_proc prev_pid=8022 prev_prio=120 prev_state=R ==> next_comm=vslam_proc next_pid=8135 next_prio=120
 vslam_proc-8023  [000] .ns2 29319.878151: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8023  [000] .ns2 29319.878153: softirq_entry: vec=9 [action=RCU]
 vslam_proc-8023  [000] .ns2 29319.878156: softirq_exit: vec=9 [action=RCU]
 vslam_proc-8023  [000] d..3 29319.878161: sched_switch: prev_comm=vslam_proc prev_pid=8023 prev_prio=120 prev_state=R+ ==> next_comm=rcu_preempt next_pid=7 next_prio=120
     rcu_preempt-7     [000] d..3 29319.878174: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=ksoftirqd/0 next_pid=3 next_prio=120
     ksoftirqd/0-3     [000] d..3 29319.878178: sched_switch: prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8023 next_prio=120
 vslam_proc-8023  [000] d..3 29319.878230: sched_switch: prev_comm=vslam_proc prev_pid=8023 prev_prio=120 prev_state=R ==> next_comm=uice_log_daemo next_pid=6177 next_prio=120
 uice_log_daemo-6177  [000] d..3 29319.878287: sched_switch: prev_comm=uice_log_daemo prev_pid=6177 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8023 next_prio=120
 vslam_proc-25023 [004] d.h1 29319.878752: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_proc-25023 [004] d.h1 29319.878759: hrtimer_expire_entry: hrtimer=ffffffc1ca737890 function=hrtimer_wakeup now=29319242711926
 vslam_proc-25023 [004] dnh1 29319.878774: hrtimer_expire_exit: hrtimer=ffffffc1ca737890
 vslam_proc-25023 [004] dnh1 29319.878776: irq_handler_exit: irq=10 ret=handled
 vslam_proc-25023 [004] d..3 29319.878786: sched_switch: prev_comm=vslam_proc prev_pid=25023 prev_prio=120 prev_state=R ==> next_comm=vslam_proc next_pid=7957 next_prio=120
 vslam_proc-8023  [000] d.h1 29319.878786: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8023  [000] d.h1 29319.878793: irq_handler_exit: irq=42 ret=handled
 vslam_proc-7957  [004] d..3 29319.878852: sched_switch: prev_comm=vslam_proc prev_pid=7957 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25023 next_prio=120
 vslam_proc-25023 [004] d.h1 29319.879218: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_proc-25023 [004] d.h1 29319.879223: hrtimer_expire_entry: hrtimer=ffffffc1e35efe30 function=hrtimer_wakeup now=29319243176769
 vslam_proc-25023 [004] dnh1 29319.879235: hrtimer_expire_exit: hrtimer=ffffffc1e35efe30
 vslam_proc-25023 [004] dnh1 29319.879237: irq_handler_exit: irq=10 ret=handled
 vslam_proc-25023 [004] d..3 29319.879242: sched_switch: prev_comm=vslam_proc prev_pid=25023 prev_prio=120 prev_state=R ==> next_comm=rtkproc next_pid=742 next_prio=120
 vslam_proc-8023  [000] d..3 29319.879250: sched_switch: prev_comm=vslam_proc prev_pid=8023 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8060 next_prio=120
         rtkproc-742   [004] d..3 29319.879277: sched_switch: prev_comm=rtkproc prev_pid=742 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25023 next_prio=120
 vslam_proc-8060  [000] d.h1 29319.879339: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_proc-8060  [000] d.h1 29319.879348: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.h1 29319.879353: irq_handler_exit: irq=45 ret=handled
 vslam_proc-8060  [000] ..s1 29319.879355: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-25021 [002] d..3 29319.879393: sched_switch: prev_comm=vslam_proc prev_pid=25021 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=7965 next_prio=120
 vslam_proc-8060  [000] d.s2 29319.879456: softirq_raise: vec=6 [action=TASKLET]
 vslam_proc-8060  [000] ..s1 29319.879497: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.879498: softirq_entry: vec=6 [action=TASKLET]
 vslam_proc-8060  [000] ..s1 29319.879590: softirq_exit: vec=6 [action=TASKLET]
 vslam_proc-7965  [002] d..3 29319.879612: sched_switch: prev_comm=vslam_proc prev_pid=7965 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25021 next_prio=120
 vslam_proc-8060  [000] d.h1 29319.879870: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_proc-8060  [000] d.h1 29319.879879: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.h1 29319.879884: irq_handler_exit: irq=44 ret=handled
 vslam_proc-8060  [000] ..s1 29319.879886: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.s2 29319.880001: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.880021: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.H3 29319.880021: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_proc-8060  [000] d.H3 29319.880021: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.H3 29319.880021: irq_handler_exit: irq=45 ret=handled
 vslam_proc-8060  [000] ..s1 29319.880039: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.H1 29319.880046: irq_handler_entry: irq=6 name=tegra186_timer0
 vslam_proc-25022 [005] d.h1 29319.880048: irq_handler_entry: irq=11 name=tegra186_timer5
 vslam_proc-25023 [004] d.h1 29319.880048: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_proc-8135  [003] d.h1 29319.880049: irq_handler_entry: irq=9 name=tegra186_timer3
 vslam_proc-8060  [000] d.H1 29319.880050: hrtimer_expire_entry: hrtimer=ffffffc1f5bc6110 function=tick_sched_timer now=29319244003387
 vslam_proc-25022 [005] d.h1 29319.880050: hrtimer_expire_entry: hrtimer=ffffffc1f5c1b110 function=tick_sched_timer now=29319244005147
 vslam_proc-25023 [004] d.h1 29319.880051: hrtimer_expire_entry: hrtimer=ffffffc1f5c0a110 function=tick_sched_timer now=29319244005723
 vslam_proc-8135  [003] d.h1 29319.880052: hrtimer_expire_entry: hrtimer=ffffffc1f5bf9110 function=tick_sched_timer now=29319244006811
 vslam_proc-8060  [000] d.H1 29319.880052: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25023 [004] d.h1 29319.880053: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25023 [004] d.h1 29319.880054: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25022 [005] d.h1 29319.880054: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8135  [003] d.h1 29319.880055: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25022 [005] d.h1 29319.880055: softirq_raise: vec=9 [action=RCU]
 vslam_proc-8135  [003] d.h1 29319.880056: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25021 [002] d.h1 29319.880058: irq_handler_entry: irq=8 name=tegra186_timer2
 vslam_proc-25022 [005] d.h1 29319.880060: hrtimer_expire_exit: hrtimer=ffffffc1f5c1b110
 vslam_proc-8060  [000] d.H1 29319.880060: hrtimer_expire_exit: hrtimer=ffffffc1f5bc6110
 vslam_proc-8135  [003] d.h1 29319.880060: hrtimer_expire_exit: hrtimer=ffffffc1f5bf9110
 vslam_proc-25023 [004] d.h1 29319.880060: hrtimer_expire_exit: hrtimer=ffffffc1f5c0a110
 vslam_proc-8059  [001] d.h1 29319.880061: irq_handler_entry: irq=7 name=tegra186_timer1
 vslam_proc-25023 [004] d.h1 29319.880061: irq_handler_exit: irq=10 ret=handled
 vslam_proc-25022 [005] d.h1 29319.880061: irq_handler_exit: irq=11 ret=handled
 vslam_proc-8135  [003] d.h1 29319.880061: irq_handler_exit: irq=9 ret=handled
 vslam_proc-8060  [000] d.H1 29319.880062: irq_handler_exit: irq=6 ret=handled
 vslam_proc-25023 [004] ..s1 29319.880063: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-25022 [005] ..s1 29319.880063: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-8135  [003] ..s1 29319.880064: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-25022 [005] ..s1 29319.880064: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25023 [004] ..s1 29319.880064: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25022 [005] ..s1 29319.880064: softirq_entry: vec=9 [action=RCU]
 vslam_proc-25023 [004] ..s1 29319.880064: softirq_entry: vec=9 [action=RCU]
 vslam_proc-8135  [003] ..s1 29319.880064: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-8135  [003] ..s1 29319.880065: softirq_entry: vec=9 [action=RCU]
 vslam_proc-25021 [002] d.h1 29319.880066: hrtimer_expire_entry: hrtimer=ffffffc1f5be8110 function=tick_sched_timer now=29319244018618
 vslam_proc-8135  [003] ..s1 29319.880066: softirq_exit: vec=9 [action=RCU]
 vslam_proc-25022 [005] ..s1 29319.880066: softirq_exit: vec=9 [action=RCU]
 vslam_proc-8059  [001] d.h1 29319.880066: hrtimer_expire_entry: hrtimer=ffffffc1f5bd7110 function=tick_sched_timer now=29319244019546
 vslam_proc-25023 [004] ..s1 29319.880066: softirq_exit: vec=9 [action=RCU]
 vslam_proc-8059  [001] d.h1 29319.880070: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25021 [002] d.h1 29319.880070: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8059  [001] d.h1 29319.880073: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25021 [002] d.h1 29319.880074: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25021 [002] d.h1 29319.880080: softirq_raise: vec=7 [action=SCHED]
 vslam_proc-8059  [001] d.h1 29319.880080: hrtimer_expire_exit: hrtimer=ffffffc1f5bd7110
 vslam_proc-25021 [002] d.h1 29319.880081: hrtimer_expire_exit: hrtimer=ffffffc1f5be8110
 vslam_proc-8059  [001] d.h1 29319.880083: irq_handler_exit: irq=7 ret=handled
 vslam_proc-25021 [002] d.h1 29319.880083: irq_handler_exit: irq=8 ret=handled
 vslam_proc-8059  [001] ..s1 29319.880086: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-25021 [002] ..s1 29319.880086: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-8059  [001] ..s1 29319.880088: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25021 [002] ..s1 29319.880088: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-8059  [001] ..s1 29319.880089: softirq_entry: vec=9 [action=RCU]
 vslam_proc-25021 [002] ..s1 29319.880089: softirq_entry: vec=7 [action=SCHED]
 vslam_proc-8059  [001] ..s1 29319.880093: softirq_exit: vec=9 [action=RCU]
 vslam_proc-25021 [002] ..s1 29319.880093: softirq_exit: vec=7 [action=SCHED]
 vslam_proc-25021 [002] ..s1 29319.880093: softirq_entry: vec=9 [action=RCU]
 vslam_proc-25021 [002] ..s1 29319.880095: softirq_exit: vec=9 [action=RCU]
 vslam_proc-8060  [000] ..s1 29319.880128: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d..3 29319.880142: sched_switch: prev_comm=vslam_proc prev_pid=8060 prev_prio=120 prev_state=R+ ==> next_comm=ksoftirqd/0 next_pid=3 next_prio=120
     ksoftirqd/0-3     [000] ..s1 29319.880146: softirq_entry: vec=1 [action=TIMER]
     ksoftirqd/0-3     [000] ..s1 29319.880158: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25023 [004] d..3 29319.880160: sched_switch: prev_comm=vslam_proc prev_pid=25023 prev_prio=120 prev_state=R ==> next_comm=kworker/u12:3 next_pid=13719 next_prio=120
     ksoftirqd/0-3     [000] d..3 29319.880162: sched_switch: prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=120 prev_state=S ==> next_comm=rcu_preempt next_pid=7 next_prio=120
     rcu_preempt-7     [000] d..3 29319.880169: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8060 next_prio=120
   kworker/u12:3-13719 [004] d..3 29319.880180: sched_switch: prev_comm=kworker/u12:3 prev_pid=13719 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25023 next_prio=120
 vslam_proc-8060  [000] d.h1 29319.880213: irq_handler_entry: irq=389 name=Tegra PCIe MSI
 vslam_proc-8060  [000] d.h1 29319.880217: irq_handler_entry: irq=452 name=uice:7014
 vslam_proc-8135  [003] d..3 29319.880235: sched_switch: prev_comm=vslam_proc prev_pid=8135 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8022 next_prio=120
 vslam_proc-8060  [000] d.h2 29319.880245: softirq_raise: vec=6 [action=TASKLET]
 vslam_proc-8060  [000] d.h1 29319.880271: irq_handler_exit: irq=452 ret=handled
 vslam_proc-8060  [000] d.h1 29319.880279: irq_handler_exit: irq=389 ret=handled
 vslam_proc-8060  [000] ..s1 29319.880280: softirq_entry: vec=6 [action=TASKLET]
 vslam_proc-25021 [002] d..3 29319.880387: sched_switch: prev_comm=vslam_proc prev_pid=25021 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
 vslam_proc-8060  [000] d.H1 29319.880450: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_proc-8060  [000] d.H1 29319.880458: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.H1 29319.880463: irq_handler_exit: irq=45 ret=handled
 vslam_proc-8060  [000] d.H1 29319.881121: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8060  [000] d.H1 29319.881127: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8060  [000] d.H1 29319.881311: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8060  [000] d.H1 29319.881315: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8060  [000] d.H1 29319.882941: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8060  [000] d.H1 29319.882945: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8059  [001] d..3 29319.883306: sched_switch: prev_comm=vslam_proc prev_pid=8059 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
 vslam_proc-8060  [000] d.H1 29319.884047: irq_handler_entry: irq=6 name=tegra186_timer0
 vslam_proc-8022  [003] d.h1 29319.884049: irq_handler_entry: irq=9 name=tegra186_timer3
 vslam_proc-25022 [005] d.h1 29319.884049: irq_handler_entry: irq=11 name=tegra186_timer5
 vslam_proc-25023 [004] d.h1 29319.884049: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_proc-8060  [000] d.H1 29319.884050: hrtimer_expire_entry: hrtimer=ffffffc1f5bc6110 function=tick_sched_timer now=29319248004642
 vslam_proc-8022  [003] d.h1 29319.884051: hrtimer_expire_entry: hrtimer=ffffffc1f5bf9110 function=tick_sched_timer now=29319248005538
 vslam_proc-25023 [004] d.h1 29319.884052: hrtimer_expire_entry: hrtimer=ffffffc1f5c0a110 function=tick_sched_timer now=29319248006530
 vslam_proc-25022 [005] d.h1 29319.884052: hrtimer_expire_entry: hrtimer=ffffffc1f5c1b110 function=tick_sched_timer now=29319248006402
 vslam_proc-8060  [000] d.H1 29319.884053: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8022  [003] d.h1 29319.884053: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25023 [004] d.h1 29319.884053: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25023 [004] d.h1 29319.884055: softirq_raise: vec=9 [action=RCU]
 vslam_proc-8022  [003] d.h1 29319.884055: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25022 [005] d.h1 29319.884058: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25022 [005] d.h1 29319.884063: hrtimer_expire_exit: hrtimer=ffffffc1f5c1b110
 vslam_proc-8060  [000] d.H1 29319.884063: hrtimer_expire_exit: hrtimer=ffffffc1f5bc6110
 vslam_proc-25023 [004] d.h1 29319.884063: hrtimer_expire_exit: hrtimer=ffffffc1f5c0a110
 vslam_proc-8022  [003] d.h1 29319.884064: hrtimer_expire_exit: hrtimer=ffffffc1f5bf9110
 vslam_proc-25022 [005] d.h1 29319.884064: irq_handler_exit: irq=11 ret=handled
 vslam_proc-8022  [003] d.h1 29319.884064: irq_handler_exit: irq=9 ret=handled
 vslam_proc-25023 [004] d.h1 29319.884065: irq_handler_exit: irq=10 ret=handled
 vslam_proc-8060  [000] d.H1 29319.884065: irq_handler_exit: irq=6 ret=handled
 vslam_proc-25022 [005] ..s1 29319.884066: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-8022  [003] ..s1 29319.884066: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-25023 [004] ..s1 29319.884066: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-25022 [005] ..s1 29319.884067: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25023 [004] ..s1 29319.884067: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-8022  [003] ..s1 29319.884067: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-8022  [003] ..s1 29319.884068: softirq_entry: vec=9 [action=RCU]
 vslam_proc-25023 [004] ..s1 29319.884068: softirq_entry: vec=9 [action=RCU]
 vslam_proc-8022  [003] ..s1 29319.884070: softirq_exit: vec=9 [action=RCU]
 vslam_proc-25023 [004] ..s1 29319.884070: softirq_exit: vec=9 [action=RCU]
          <idle>-0     [001] d.h2 29319.884079: softirq_raise: vec=7 [action=SCHED]
          <idle>-0     [001] ..s2 29319.884081: softirq_entry: vec=7 [action=SCHED]
          <idle>-0     [001] ..s2 29319.884097: softirq_exit: vec=7 [action=SCHED]
          <idle>-0     [001] d.h2 29319.884344: irq_handler_entry: irq=7 name=tegra186_timer1
          <idle>-0     [001] d.h2 29319.884347: hrtimer_expire_entry: hrtimer=ffffffc1b9f4b9b0 function=hrtimer_wakeup now=29319248301300
          <idle>-0     [001] dnh2 29319.884360: hrtimer_expire_exit: hrtimer=ffffffc1b9f4b9b0
          <idle>-0     [001] dnh2 29319.884362: irq_handler_exit: irq=7 ret=handled
          <idle>-0     [001] d..3 29319.884374: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=vslam_proc next_pid=8059 next_prio=120
 vslam_proc-8059  [001] d..3 29319.884418: sched_switch: prev_comm=vslam_proc prev_pid=8059 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
 vslam_proc-8060  [000] ..s1 29319.884510: softirq_exit: vec=6 [action=TASKLET]
 vslam_proc-8022  [003] d..3 29319.884512: sched_switch: prev_comm=vslam_proc prev_pid=8022 prev_prio=120 prev_state=R ==> next_comm=vslam_proc next_pid=8024 next_prio=120
 vslam_proc-8060  [000] d..3 29319.884516: sched_switch: prev_comm=vslam_proc prev_pid=8060 prev_prio=120 prev_state=R+ ==> next_comm=ksoftirqd/0 next_pid=3 next_prio=120
     ksoftirqd/0-3     [000] ..s1 29319.884519: softirq_entry: vec=1 [action=TIMER]
     ksoftirqd/0-3     [000] ..s1 29319.884523: softirq_exit: vec=1 [action=TIMER]
     ksoftirqd/0-3     [000] ..s1 29319.884523: softirq_entry: vec=3 [action=NET_RX]
     ksoftirqd/0-3     [000] d.H3 29319.884881: irq_handler_entry: irq=42 name=ether_qos.common_irq
     ksoftirqd/0-3     [000] d.H3 29319.884887: irq_handler_exit: irq=42 ret=handled
     ksoftirqd/0-3     [000] d.s2 29319.884951: softirq_raise: vec=6 [action=TASKLET]
     ksoftirqd/0-3     [000] d.s2 29319.884970: softirq_raise: vec=3 [action=NET_RX]
     ksoftirqd/0-3     [000] d.H1 29319.884986: irq_handler_entry: irq=42 name=ether_qos.common_irq
     ksoftirqd/0-3     [000] d.H1 29319.884990: irq_handler_exit: irq=42 ret=handled
     ksoftirqd/0-3     [000] d.H2 29319.885070: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
     ksoftirqd/0-3     [000] d.H2 29319.885082: softirq_raise: vec=3 [action=NET_RX]
     ksoftirqd/0-3     [000] d.H2 29319.885088: irq_handler_exit: irq=45 ret=handled
     ksoftirqd/0-3     [000] ..s1 29319.885089: softirq_exit: vec=3 [action=NET_RX]
     ksoftirqd/0-3     [000] ..s1 29319.885090: softirq_entry: vec=3 [action=NET_RX]
     ksoftirqd/0-3     [000] d.H2 29319.885239: irq_handler_entry: irq=42 name=ether_qos.common_irq
     ksoftirqd/0-3     [000] d.H2 29319.885246: irq_handler_exit: irq=42 ret=handled
 vslam_proc-25023 [004] d..3 29319.885311: sched_switch: prev_comm=vslam_proc prev_pid=25023 prev_prio=120 prev_state=R ==> next_comm=vslam_proc next_pid=7964 next_prio=120
 vslam_proc-25022 [005] d.h1 29319.885364: irq_handler_entry: irq=11 name=tegra186_timer5
 vslam_proc-25022 [005] d.h1 29319.885368: hrtimer_expire_entry: hrtimer=ffffffbffcf66c10 function=hrtimer_handler [uice] now=29319249322277
     ksoftirqd/0-3     [000] ..s1 29319.885380: softirq_exit: vec=3 [action=NET_RX]
     ksoftirqd/0-3     [000] ..s1 29319.885383: softirq_entry: vec=6 [action=TASKLET]
     ksoftirqd/0-3     [000] ..s1 29319.885385: softirq_exit: vec=6 [action=TASKLET]
 vslam_proc-25022 [005] d.h1 29319.885396: hrtimer_expire_exit: hrtimer=ffffffbffcf66c10
 vslam_proc-25022 [005] d.h1 29319.885397: irq_handler_exit: irq=11 ret=handled
     ksoftirqd/0-3     [000] d..3 29319.885398: sched_switch: prev_comm=ksoftirqd/0 prev_pid=3 prev_prio=120 prev_state=S ==> next_comm=rcu_preempt next_pid=7 next_prio=120
     rcu_preempt-7     [000] d..3 29319.885407: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8060 next_prio=120
 vslam_proc-7964  [004] d..3 29319.885449: sched_switch: prev_comm=vslam_proc prev_pid=7964 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25023 next_prio=120
 vslam_proc-8060  [000] d.h1 29319.885536: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_proc-8060  [000] d.h1 29319.885546: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.h1 29319.885551: irq_handler_exit: irq=45 ret=handled
 vslam_proc-8060  [000] ..s1 29319.885553: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.885592: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.h1 29319.885789: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8060  [000] d.h1 29319.885795: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8060  [000] d.h1 29319.885870: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_proc-8060  [000] d.h1 29319.885878: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.h1 29319.885883: irq_handler_exit: irq=44 ret=handled
 vslam_proc-8060  [000] ..s1 29319.885884: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.s2 29319.885901: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.H1 29319.885913: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8060  [000] d.H1 29319.885918: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8060  [000] ..s1 29319.885919: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.885920: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.885958: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.h1 29319.885994: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_proc-8060  [000] d.h1 29319.886005: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.h1 29319.886009: irq_handler_exit: irq=44 ret=handled
 vslam_proc-8060  [000] ..s1 29319.886010: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.s2 29319.886025: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.886033: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.886034: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.886066: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-25023 [004] d..3 29319.886070: sched_switch: prev_comm=vslam_proc prev_pid=25023 prev_prio=120 prev_state=R ==> next_comm=vslam_proc next_pid=7964 next_prio=120
 vslam_proc-8060  [000] d.h1 29319.886178: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_proc-8060  [000] d.h1 29319.886187: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-7964  [004] d..3 29319.886192: sched_switch: prev_comm=vslam_proc prev_pid=7964 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25023 next_prio=120
 vslam_proc-8060  [000] d.h1 29319.886192: irq_handler_exit: irq=45 ret=handled
 vslam_proc-8060  [000] d.H1 29319.886194: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8060  [000] d.H1 29319.886199: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8060  [000] ..s1 29319.886200: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.886212: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.h1 29319.886646: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8060  [000] d.h1 29319.886651: irq_handler_exit: irq=42 ret=handled
          <idle>-0     [001] d..3 29319.886678: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=vslam_proc next_pid=8059 next_prio=120
          <idle>-0     [002] d..3 29319.886685: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=vslam_proc next_pid=25021 next_prio=120
 vslam_proc-8060  [000] d.h1 29319.886725: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_proc-8060  [000] d.h1 29319.886734: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.h1 29319.886739: irq_handler_exit: irq=44 ret=handled
 vslam_proc-8060  [000] ..s1 29319.886740: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.s2 29319.886756: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.886765: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.886766: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.886799: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-25023 [004] d..3 29319.886804: sched_switch: prev_comm=vslam_proc prev_pid=25023 prev_prio=120 prev_state=R ==> next_comm=vslam_proc next_pid=7964 next_prio=120
 vslam_proc-8060  [000] d.h1 29319.886915: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_proc-7964  [004] d..3 29319.886923: sched_switch: prev_comm=vslam_proc prev_pid=7964 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25023 next_prio=120
 vslam_proc-8060  [000] d.h1 29319.886925: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] d.h1 29319.886931: irq_handler_exit: irq=45 ret=handled
 vslam_proc-8060  [000] d.H1 29319.886932: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8060  [000] d.H1 29319.886937: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8060  [000] ..s1 29319.886941: softirq_entry: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] ..s1 29319.886955: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8059  [001] d..3 29319.887223: sched_switch: prev_comm=vslam_proc prev_pid=8059 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
 vslam_proc-25021 [002] d..3 29319.887224: sched_switch: prev_comm=vslam_proc prev_pid=25021 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
 vslam_proc-25023 [004] d.h1 29320.080049: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_proc-8024  [003] d.h1 29320.080050: irq_handler_entry: irq=9 name=tegra186_timer3
 vslam_proc-8060  [000] d.h1 29320.080050: irq_handler_entry: irq=6 name=tegra186_timer0
 vslam_proc-25022 [005] d.h1 29320.080050: irq_handler_entry: irq=11 name=tegra186_timer5
 vslam_proc-25022 [005] d.h1 29320.080052: hrtimer_expire_entry: hrtimer=ffffffc1f5c1b110 function=tick_sched_timer now=29319443997642
 vslam_proc-25023 [004] d.h1 29320.080053: hrtimer_expire_entry: hrtimer=ffffffc1f5c0a110 function=tick_sched_timer now=29319443998442
 vslam_proc-8060  [000] d.h1 29320.080053: hrtimer_expire_entry: hrtimer=ffffffc1f5bc6110 function=tick_sched_timer now=29319443998698
 vslam_proc-8024  [003] d.h1 29320.080053: hrtimer_expire_entry: hrtimer=ffffffc1f5bf9110 function=tick_sched_timer now=29319443998634
 vslam_proc-8024  [003] d.h1 29320.080056: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25023 [004] d.h1 29320.080056: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8060  [000] d.h1 29320.080056: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25023 [004] d.h1 29320.080057: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25022 [005] d.h1 29320.080057: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8024  [003] d.h1 29320.080057: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25022 [005] d.h1 29320.080062: softirq_raise: vec=7 [action=SCHED]
          <idle>-0     [002] d.h2 29320.080062: irq_handler_entry: irq=8 name=tegra186_timer2
 vslam_proc-8024  [003] dnh1 29320.080063: softirq_raise: vec=7 [action=SCHED]
 vslam_proc-25022 [005] d.h1 29320.080063: hrtimer_expire_exit: hrtimer=ffffffc1f5c1b110
 vslam_proc-8024  [003] dnh1 29320.080063: hrtimer_expire_exit: hrtimer=ffffffc1f5bf9110
 vslam_proc-8060  [000] d.h1 29320.080063: hrtimer_expire_exit: hrtimer=ffffffc1f5bc6110
 vslam_proc-25023 [004] d.h1 29320.080064: hrtimer_expire_exit: hrtimer=ffffffc1f5c0a110
 vslam_proc-8060  [000] d.h1 29320.080064: hrtimer_expire_entry: hrtimer=ffffffc06c017e30 function=hrtimer_wakeup now=29319443998698
 vslam_proc-25023 [004] d.h1 29320.080065: hrtimer_expire_entry: hrtimer=ffffffc1e35efe30 function=hrtimer_wakeup now=29319443998442
 vslam_proc-25022 [005] d.h1 29320.080065: hrtimer_expire_entry: hrtimer=ffffffbffcf66c10 function=hrtimer_handler [uice] now=29319443997642
 vslam_proc-8024  [003] dnh1 29320.080065: irq_handler_exit: irq=9 ret=handled
 vslam_proc-8024  [003] .ns1 29320.080067: softirq_entry: vec=1 [action=TIMER]
          <idle>-0     [002] d.h2 29320.080070: hrtimer_expire_entry: hrtimer=ffffffc1f5be8110 function=tick_sched_timer now=29319444014921
          <idle>-0     [001] d.h2 29320.080071: softirq_raise: vec=7 [action=SCHED]
 vslam_proc-8060  [000] dnh1 29320.080072: hrtimer_expire_exit: hrtimer=ffffffc06c017e30
 vslam_proc-25023 [004] dnh1 29320.080072: hrtimer_expire_exit: hrtimer=ffffffc1e35efe30
 vslam_proc-25023 [004] dnh1 29320.080073: hrtimer_expire_entry: hrtimer=ffffffc1ca737890 function=hrtimer_wakeup now=29319443998442
          <idle>-0     [002] d.h2 29320.080073: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8060  [000] dnh1 29320.080073: irq_handler_exit: irq=6 ret=handled
          <idle>-0     [001] ..s2 29320.080074: softirq_entry: vec=7 [action=SCHED]
 vslam_proc-25023 [004] dnh1 29320.080075: hrtimer_expire_exit: hrtimer=ffffffc1ca737890
          <idle>-0     [002] d.h2 29320.080076: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25023 [004] dnh1 29320.080076: hrtimer_expire_entry: hrtimer=ffffffc1e0c7fe30 function=hrtimer_wakeup now=29319443998442
 vslam_proc-8060  [000] dnH1 29320.080076: irq_handler_entry: irq=389 name=Tegra PCIe MSI
 vslam_proc-8024  [003] .ns1 29320.080078: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25023 [004] dnh1 29320.080078: hrtimer_expire_exit: hrtimer=ffffffc1e0c7fe30
 vslam_proc-8024  [003] .ns1 29320.080078: softirq_entry: vec=7 [action=SCHED]
 vslam_proc-25023 [004] dnh1 29320.080079: irq_handler_exit: irq=10 ret=handled
 vslam_proc-8060  [000] dnH1 29320.080080: irq_handler_entry: irq=452 name=uice:7014
 vslam_proc-25023 [004] .ns1 29320.080080: softirq_entry: vec=1 [action=TIMER]
          <idle>-0     [002] d.h2 29320.080081: softirq_raise: vec=7 [action=SCHED]
          <idle>-0     [002] d.h2 29320.080082: hrtimer_expire_exit: hrtimer=ffffffc1f5be8110
 vslam_proc-8024  [003] .ns1 29320.080082: softirq_exit: vec=7 [action=SCHED]
 vslam_proc-8024  [003] .ns1 29320.080082: softirq_entry: vec=9 [action=RCU]
          <idle>-0     [002] d.h2 29320.080083: irq_handler_exit: irq=8 ret=handled
 vslam_proc-8024  [003] .ns1 29320.080084: softirq_exit: vec=9 [action=RCU]
          <idle>-0     [002] ..s2 29320.080086: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-25023 [004] .ns1 29320.080089: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25023 [004] .ns1 29320.080089: softirq_entry: vec=9 [action=RCU]
 vslam_proc-25022 [005] d.h1 29320.080090: hrtimer_expire_exit: hrtimer=ffffffbffcf66c10
          <idle>-0     [002] ..s2 29320.080090: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25022 [005] d.h1 29320.080090: hrtimer_expire_entry: hrtimer=ffffffc1e094fe30 function=hrtimer_wakeup now=29319443997642
 vslam_proc-8024  [003] d..3 29320.080091: sched_switch: prev_comm=vslam_proc prev_pid=8024 prev_prio=120 prev_state=R ==> next_comm=vslam_proc next_pid=8022 next_prio=120
          <idle>-0     [002] ..s2 29320.080091: softirq_entry: vec=7 [action=SCHED]
 vslam_proc-25023 [004] .ns1 29320.080091: softirq_exit: vec=9 [action=RCU]
 vslam_proc-8060  [000] dnH2 29320.080091: softirq_raise: vec=6 [action=TASKLET]
          <idle>-0     [002] ..s2 29320.080092: softirq_exit: vec=7 [action=SCHED]
          <idle>-0     [002] ..s2 29320.080092: softirq_entry: vec=9 [action=RCU]
 vslam_proc-25023 [004] d..3 29320.080093: sched_switch: prev_comm=vslam_proc prev_pid=25023 prev_prio=120 prev_state=R ==> next_comm=rtkproc next_pid=742 next_prio=120
 vslam_proc-25022 [005] dnh1 29320.080095: hrtimer_expire_exit: hrtimer=ffffffc1e094fe30
          <idle>-0     [002] ..s2 29320.080095: softirq_exit: vec=9 [action=RCU]
 vslam_proc-25022 [005] dnh1 29320.080096: hrtimer_expire_entry: hrtimer=ffffffc1f5c1b110 function=tick_sched_timer now=29319444042088
 vslam_proc-25022 [005] dnh1 29320.080096: softirq_raise: vec=1 [action=TIMER]
          <idle>-0     [001] ..s2 29320.080096: softirq_exit: vec=7 [action=SCHED]
 vslam_proc-25022 [005] dnh1 29320.080098: softirq_raise: vec=7 [action=SCHED]
 vslam_proc-25022 [005] dnh1 29320.080098: hrtimer_expire_exit: hrtimer=ffffffc1f5c1b110
 vslam_proc-25022 [005] dnh1 29320.080099: irq_handler_exit: irq=11 ret=handled
 vslam_proc-25022 [005] .ns1 29320.080100: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-25022 [005] .ns1 29320.080102: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25022 [005] .ns1 29320.080102: softirq_entry: vec=7 [action=SCHED]
 vslam_proc-8060  [000] dnH2 29320.080106: softirq_raise: vec=6 [action=TASKLET]
 vslam_proc-25022 [005] .ns1 29320.080107: softirq_exit: vec=7 [action=SCHED]
 vslam_proc-25022 [005] d..3 29320.080109: sched_switch: prev_comm=vslam_proc prev_pid=25022 prev_prio=120 prev_state=R ==> next_comm=sleep next_pid=28021 next_prio=120
 vslam_proc-8060  [000] dnH2 29320.080115: softirq_raise: vec=6 [action=TASKLET]
         rtkproc-742   [004] d..3 29320.080128: sched_switch: prev_comm=rtkproc prev_pid=742 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=7957 next_prio=120
 vslam_proc-8060  [000] dnH1 29320.080143: irq_handler_exit: irq=452 ret=handled
 vslam_proc-8060  [000] dnH1 29320.080151: irq_handler_exit: irq=389 ret=handled
 vslam_proc-8060  [000] dnH1 29320.080153: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_proc-8060  [000] dnH1 29320.080161: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8060  [000] dnH1 29320.080167: irq_handler_exit: irq=44 ret=handled
 vslam_proc-8060  [000] dnH1 29320.080168: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8022  [003] d..3 29320.080171: sched_switch: prev_comm=vslam_proc prev_pid=8022 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=7950 next_prio=120
 vslam_proc-8060  [000] dnH1 29320.080173: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8060  [000] dnH1 29320.080174: irq_handler_entry: irq=53 name=d230000.actmon
 vslam_proc-8060  [000] dnH1 29320.080186: irq_handler_exit: irq=53 ret=handled
 vslam_proc-8060  [000] .ns1 29320.080193: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-8060  [000] .ns1 29320.080209: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-8060  [000] d..3 29320.080214: sched_switch: prev_comm=vslam_proc prev_pid=8060 prev_prio=120 prev_state=R ==> next_comm=irq/53-d230000. next_pid=184 next_prio=49
 irq/53-d230000.-184   [000] d..3 29320.080231: sched_switch: prev_comm=irq/53-d230000. prev_pid=184 prev_prio=49 prev_state=D ==> next_comm=vslam_proc next_pid=8133 next_prio=120
 vslam_proc-8133  [000] d.h2 29320.080262: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8133  [000] d.h2 29320.080267: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8133  [000] ..s2 29320.080268: softirq_entry: vec=3 [action=NET_RX]
            sshd-7950  [003] d..3 29320.080277: sched_switch: prev_comm=sshd prev_pid=7950 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8022 next_prio=120
           sleep-28021 [005] d..3 29320.080285: sched_switch: prev_comm=sleep prev_pid=28021 prev_prio=120 prev_state=x ==> next_comm=process_stats.s next_pid=7798 next_prio=120
 vslam_proc-8133  [000] d.s3 29320.080288: softirq_raise: vec=6 [action=TASKLET]
 vslam_proc-8133  [000] d.H2 29320.080290: irq_handler_entry: irq=12 name=hsp
 vslam_proc-8133  [000] dnH2 29320.080297: irq_handler_exit: irq=12 ret=handled
 vslam_proc-8133  [000] dns3 29320.080313: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8022  [003] d..3 29320.080384: sched_switch: prev_comm=vslam_proc prev_pid=8022 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=7950 next_prio=120
 vslam_proc-8133  [000] dnH2 29320.080437: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8133  [000] dnH2 29320.080442: irq_handler_exit: irq=42 ret=handled
            sshd-7950  [003] d..3 29320.080447: sched_switch: prev_comm=sshd prev_pid=7950 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8022 next_prio=120
 vslam_proc-7957  [004] d..3 29320.080471: sched_switch: prev_comm=vslam_proc prev_pid=7957 prev_prio=120 prev_state=S ==> next_comm=sleep next_pid=28138 next_prio=120
 vslam_proc-8133  [000] .ns2 29320.080471: softirq_exit: vec=3 [action=NET_RX]
 vslam_proc-8133  [000] dnH4 29320.080471: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_proc-8133  [000] dnH4 29320.080471: softirq_raise: vec=3 [action=NET_RX]
 vslam_proc-8133  [000] dnH4 29320.080471: irq_handler_exit: irq=45 ret=handled
 vslam_proc-8133  [000] .ns2 29320.080487: softirq_entry: vec=6 [action=TASKLET]
 vslam_proc-8133  [000] dnH2 29320.080569: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8133  [000] dnH2 29320.080573: irq_handler_exit: irq=42 ret=handled
          <idle>-0     [001] d..3 29320.080596: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=process_stats.s next_pid=28139 next_prio=120
 vslam_proc-8022  [003] d..3 29320.080610: sched_switch: prev_comm=vslam_proc prev_pid=8022 prev_prio=120 prev_state=R ==> next_comm=log_camera.sh next_pid=6384 next_prio=120
           sleep-28138 [004] d..3 29320.080613: sched_switch: prev_comm=sleep prev_pid=28138 prev_prio=120 prev_state=x ==> next_comm=kworker/u12:3 next_pid=13719 next_prio=120
   kworker/u12:3-13719 [004] d..3 29320.080629: sched_switch: prev_comm=kworker/u12:3 prev_pid=13719 prev_prio=120 prev_state=D ==> next_comm=kworker/4:1 next_pid=19968 next_prio=120
     kworker/4:1-19968 [004] d..3 29320.080640: sched_switch: prev_comm=kworker/4:1 prev_pid=19968 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25023 next_prio=120
          <idle>-0     [002] d..3 29320.080888: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=log_camera.sh next_pid=28140 next_prio=120
 vslam_proc-8133  [000] dnH2 29320.081236: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8133  [000] dnH2 29320.081241: irq_handler_exit: irq=42 ret=handled
 process_stats.s-7798  [005] d..3 29320.081646: sched_switch: prev_comm=process_stats.s prev_pid=7798 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25022 next_prio=120
            date-28139 [001] d..3 29320.081878: sched_switch: prev_comm=date prev_pid=28139 prev_prio=120 prev_state=D ==> next_comm=vslam_proc next_pid=8024 next_prio=120
 vslam_proc-8024  [001] d..3 29320.081910: sched_switch: prev_comm=vslam_proc prev_pid=8024 prev_prio=120 prev_state=R ==> next_comm=date next_pid=28139 next_prio=120
             cat-28140 [002] d..3 29320.082078: sched_switch: prev_comm=cat prev_pid=28140 prev_prio=120 prev_state=D ==> next_comm=uice_log_daemo next_pid=6177 next_prio=120
 uice_log_daemo-6177  [002] d..3 29320.082201: sched_switch: prev_comm=uice_log_daemo prev_pid=6177 prev_prio=120 prev_state=S ==> next_comm=cat next_pid=28140 next_prio=120
   log_camera.sh-6384  [003] d..3 29320.082205: sched_switch: prev_comm=log_camera.sh prev_pid=6384 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8022 next_prio=120
 vslam_proc-8133  [000] dnH2 29320.082737: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_proc-8133  [000] dnH2 29320.082743: irq_handler_exit: irq=42 ret=handled
 vslam_proc-8022  [003] d..3 29320.082757: sched_switch: prev_comm=vslam_proc prev_pid=8022 prev_prio=120 prev_state=R ==> next_comm=log_camera.sh next_pid=6384 next_prio=120
   log_camera.sh-6384  [003] d..3 29320.082775: sched_switch: prev_comm=log_camera.sh prev_pid=6384 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8022 next_prio=120
 vslam_proc-8022  [003] d..3 29320.082784: sched_switch: prev_comm=vslam_proc prev_pid=8022 prev_prio=120 prev_state=R ==> next_comm=log_camera.sh next_pid=6384 next_prio=120
   log_camera.sh-6384  [003] d..3 29320.082812: sched_switch: prev_comm=log_camera.sh prev_pid=6384 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8022 next_prio=120
 vslam_proc-25022 [005] d..3 29320.082816: sched_switch: prev_comm=vslam_proc prev_pid=25022 prev_prio=120 prev_state=R ==> next_comm=process_stats.s next_pid=7798 next_prio=120
 process_stats.s-7798  [005] d..3 29320.082852: sched_switch: prev_comm=process_stats.s prev_pid=7798 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25022 next_prio=120
 vslam_proc-8022  [003] d..3 29320.082917: sched_switch: prev_comm=vslam_proc prev_pid=8022 prev_prio=120 prev_state=R ==> next_comm=log_camera.sh next_pid=6384 next_prio=120
 vslam_proc-25022 [005] d..3 29320.082940: sched_switch: prev_comm=vslam_proc prev_pid=25022 prev_prio=120 prev_state=R ==> next_comm=process_stats.s next_pid=7798 next_prio=120
            date-28139 [001] d..3 29320.082942: sched_switch: prev_comm=date prev_pid=28139 prev_prio=120 prev_state=x ==> next_comm=vslam_proc next_pid=8024 next_prio=120
             cat-28140 [002] d..3 29320.082943: sched_switch: prev_comm=cat prev_pid=28140 prev_prio=120 prev_state=x ==> next_comm=nvgpu_channel_p next_pid=590 next_prio=120
 nvgpu_channel_p-590   [002] d..3 29320.083119: sched_switch: prev_comm=nvgpu_channel_p prev_pid=590 prev_prio=120 prev_state=D ==> next_comm=rcu_preempt next_pid=7 next_prio=120
     rcu_preempt-7     [002] d..3 29320.083135: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8060 next_prio=120
 vslam_proc-8060  [002] d..3 29320.083652: sched_switch: prev_comm=vslam_proc prev_pid=8060 prev_prio=120 prev_state=S ==> next_comm=log_camera.sh next_pid=28142 next_prio=120
 vslam_proc-8133  [000] dnH2 29320.083775: irq_handler_entry: irq=62 name=host_syncpt
 vslam_proc-8133  [000] dnH2 29320.083776: irq_handler_exit: irq=62 ret=handled
 vslam_proc-8133  [000] dnH2 29320.084056: irq_handler_entry: irq=6 name=tegra186_timer0
 vslam_proc-25023 [004] d.h1 29320.084059: irq_handler_entry: irq=10 name=tegra186_timer4
   log_camera.sh-6384  [003] d.h1 29320.084059: irq_handler_entry: irq=9 name=tegra186_timer3
 process_stats.s-7798  [005] d.h3 29320.084059: irq_handler_entry: irq=11 name=tegra186_timer5
 vslam_proc-8133  [000] dnH2 29320.084060: hrtimer_expire_entry: hrtimer=ffffffc1f5bc6110 function=tick_sched_timer now=29319448003857
   log_camera.sh-6384  [003] d.h1 29320.084062: hrtimer_expire_entry: hrtimer=ffffffc1f5bf9110 function=tick_sched_timer now=29319448007857
            date-28142 [002] d.h2 29320.084062: irq_handler_entry: irq=8 name=tegra186_timer2
 vslam_proc-8024  [001] d.h1 29320.084063: irq_handler_entry: irq=7 name=tegra186_timer1
 vslam_proc-25023 [004] d.h1 29320.084063: hrtimer_expire_entry: hrtimer=ffffffc1f5c0a110 function=tick_sched_timer now=29319448007857
 vslam_proc-8133  [000] dnH2 29320.084063: softirq_raise: vec=1 [action=TIMER]
 process_stats.s-7798  [005] d.h3 29320.084063: hrtimer_expire_entry: hrtimer=ffffffc1f5c1b110 function=tick_sched_timer now=29319448007857
   log_camera.sh-6384  [003] d.h1 29320.084064: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-25023 [004] d.h1 29320.084064: softirq_raise: vec=1 [action=TIMER]
   log_camera.sh-6384  [003] d.h1 29320.084065: softirq_raise: vec=9 [action=RCU]
 vslam_proc-25023 [004] d.h1 29320.084065: softirq_raise: vec=9 [action=RCU]
 process_stats.s-7798  [005] d.h3 29320.084068: softirq_raise: vec=1 [action=TIMER]
 vslam_proc-8024  [001] d.h1 29320.084070: hrtimer_expire_entry: hrtimer=ffffffc1f5bd7110 function=tick_sched_timer now=29319448014576
            date-28142 [002] d.h2 29320.084070: hrtimer_expire_entry: hrtimer=ffffffc1f5be8110 function=tick_sched_timer now=29319448014608
   log_camera.sh-6384  [003] d.h1 29320.084070: softirq_raise: vec=7 [action=SCHED]
 vslam_proc-8133  [000] dnH2 29320.084071: hrtimer_expire_exit: hrtimer=ffffffc1f5bc6110
   log_camera.sh-6384  [003] d.h1 29320.084071: hrtimer_expire_exit: hrtimer=ffffffc1f5bf9110
 vslam_proc-25023 [004] d.h1 29320.084071: hrtimer_expire_exit: hrtimer=ffffffc1f5c0a110
 vslam_proc-8133  [000] dnH2 29320.084073: irq_handler_exit: irq=6 ret=handled
   log_camera.sh-6384  [003] d.h1 29320.084073: irq_handler_exit: irq=9 ret=handled
 process_stats.s-7798  [005] d.h3 29320.084073: hrtimer_expire_exit: hrtimer=ffffffc1f5c1b110
 vslam_proc-25023 [004] d.h1 29320.084073: irq_handler_exit: irq=10 ret=handled
 vslam_proc-8024  [001] d.h1 29320.084074: softirq_raise: vec=1 [action=TIMER]
            date-28142 [002] d.h2 29320.084074: softirq_raise: vec=1 [action=TIMER]
 process_stats.s-7798  [005] d.h3 29320.084074: irq_handler_exit: irq=11 ret=handled
   log_camera.sh-6384  [003] ..s1 29320.084076: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-25023 [004] ..s1 29320.084076: softirq_entry: vec=1 [action=TIMER]
 process_stats.s-7798  [005] ..s3 29320.084076: softirq_entry: vec=1 [action=TIMER]
   log_camera.sh-6384  [003] ..s1 29320.084077: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-25023 [004] ..s1 29320.084077: softirq_exit: vec=1 [action=TIMER]
 process_stats.s-7798  [005] ..s3 29320.084077: softirq_exit: vec=1 [action=TIMER]
            date-28142 [002] d.h2 29320.084077: softirq_raise: vec=9 [action=RCU]
   log_camera.sh-6384  [003] ..s1 29320.084077: softirq_entry: vec=7 [action=SCHED]
 vslam_proc-25023 [004] ..s1 29320.084077: softirq_entry: vec=9 [action=RCU]
 vslam_proc-25023 [004] ..s1 29320.084079: softirq_exit: vec=9 [action=RCU]
 vslam_proc-8024  [001] d.h1 29320.084083: softirq_raise: vec=7 [action=SCHED]
            date-28142 [002] d.h2 29320.084083: softirq_raise: vec=7 [action=SCHED]
   log_camera.sh-6384  [003] ..s1 29320.084083: softirq_exit: vec=7 [action=SCHED]
   log_camera.sh-6384  [003] ..s1 29320.084084: softirq_entry: vec=9 [action=RCU]
            date-28142 [002] d.h2 29320.084085: hrtimer_expire_exit: hrtimer=ffffffc1f5be8110
 vslam_proc-8024  [001] d.h1 29320.084087: hrtimer_expire_exit: hrtimer=ffffffc1f5bd7110
            date-28142 [002] d.h2 29320.084088: irq_handler_exit: irq=8 ret=handled
 vslam_proc-8024  [001] d.h1 29320.084089: irq_handler_exit: irq=7 ret=handled
            date-28142 [002] ..s2 29320.084091: softirq_entry: vec=1 [action=TIMER]
 vslam_proc-8024  [001] ..s1 29320.084091: softirq_entry: vec=1 [action=TIMER]
   log_camera.sh-6384  [003] ..s1 29320.084094: softirq_exit: vec=9 [action=RCU]
 vslam_proc-8024  [001] ..s1 29320.084094: softirq_exit: vec=1 [action=TIMER]
            date-28142 [002] ..s2 29320.084094: softirq_exit: vec=1 [action=TIMER]
 vslam_proc-8024  [001] ..s1 29320.084096: softirq_entry: vec=7 [action=SCHED]
            date-28142 [002] ..s2 29320.084098: softirq_entry: vec=7 [action=SCHED]
 vslam_proc-8024  [001] ..s1 29320.084100: softirq_exit: vec=7 [action=SCHED]
            date-28142 [002] ..s2 29320.084101: softirq_exit: vec=7 [action=SCHED]
            date-28142 [002] ..s2 29320.084101: softirq_entry: vec=9 [action=RCU]
            date-28142 [002] ..s2 29320.084106: softirq_exit: vec=9 [action=RCU]
 process_stats.s-7798  [005] d..3 29320.084248: sched_switch: prev_comm=process_stats.s prev_pid=7798 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=25022 next_prio=120
   log_camera.sh-6384  [003] d..3 29320.084429: sched_switch: prev_comm=log_camera.sh prev_pid=6384 prev_prio=120 prev_state=S ==> next_comm=rcu_preempt next_pid=7 next_prio=120
     rcu_preempt-7     [003] d..3 29320.084439: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=vslam_proc next_pid=8022 next_prio=120
 vslam_proc-25022 [005] d.h1 29320.085376: irq_handler_entry: irq=11 name=tegra186_timer5
 vslam_proc-25022 [005] d.h1 29320.085381: hrtimer_expire_entry: hrtimer=ffffffbffcf66c10 function=hrtimer_handler [uice] now=29319449325332

COuld you run the jetson_clocks to check if help.

Use jetson_clocks to monitor cpu frequency? What is the target for this method?
jetsom clock is used for kernel space usage?

It’s set the CPU frequency to max.
Just run below command before your test.

sudo jetson_clocks&

@ShaneCCC
Already use jestson_clock to max the cpu frequency.
The issue is still there.

Do you have any more ideas?

Can you trying disabling, the below config so that cpu does not idle?
CPU_IDLE_TEGRA18X

Also, can you run the test with only one cpu online?

May be at the end you need an RT Kernel?
Documentation has steps in how to apply RT patches and build the kernel.
Please make sure that before compiling, SCHEDUTIL governor is disabled.

@bbasu

Thanks for you reply.

Can you share the Documentation how to apply RT patches on JetPacke3.3?

We have already disable CPU_IDLE_TEGRA18X as you suggested, let us see the result next day.

Depended on CPU_IDLE_TEGRA18X result, if needed we will do test with only one cpu online.

Here is another log snapshot.
804.252196->804.724216 lost irq. From the log we found cpu 1 execute tick_stop-> “cpu_idle: state=0 cpu_id=1” -> “cpu_idle: state=4294967295 cpu_id=1”.

Maybe the root cause is CPU_IDLE_TEGRA18X as you mentioned before? Let us wait our final test result.

<idle>-0     [001] d..2   804.252182: tick_stop: success=yes msg=  
          <idle>-0     [002] d..2   804.252182: tick_stop: success=yes msg=  
          <idle>-0     [001] d..3   804.252184: hrtimer_cancel: hrtimer=ffffffc1f5bd7110
          <idle>-0     [002] d..3   804.252184: hrtimer_cancel: hrtimer=ffffffc1f5be8110
 vslam_framewor-3236  [004] d..3   804.252185: sched_stat_wait: comm=vslam_framewor pid=3240 delay=72640 [ns]
          <idle>-0     [001] d..3   804.252186: hrtimer_start: hrtimer=ffffffc1f5bd7110 function=tick_sched_timer expires=804804000000 softexpires=804804000000
          <idle>-0     [002] d..3   804.252186: hrtimer_start: hrtimer=ffffffc1f5be8110 function=tick_sched_timer expires=804792000000 softexpires=804792000000
 vslam_framewor-3236  [004] d..3   804.252187: sched_switch: prev_comm=vslam_framewor prev_pid=3236 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3240 next_prio=120
 vslam_framewor-3239  [003] d..2   804.252192: sched_waking: comm=vslam_framewor pid=3236 prio=120 target_cpu=004
          <idle>-0     [001] d..2   804.252192: cpu_idle: state=0 cpu_id=1
          <idle>-0     [002] d..2   804.252192: cpu_idle: state=0 cpu_id=2
 vslam_framewor-3239  [003] d..3   804.252194: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=12672 [ns] vruntime=256533434884 [ns]
 vslam_framewor-3239  [003] d..3   804.252195: sched_stat_sleep: comm=vslam_framewor pid=3236 delay=12672 [ns]
 vslam_framewor-3239  [003] d..3   804.252196: sched_wakeup: comm=vslam_framewor pid=3236 prio=120 target_cpu=004
     ksoftirqd/0-3     [000] d.H1   804.724216: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3240  [004] d.h1   804.724219: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_framewor-3239  [003] d.h1   804.724219: irq_handler_entry: irq=9 name=tegra186_timer3
 vslam_framewor-3216  [005] d.h1   804.724219: irq_handler_entry: irq=11 name=tegra186_timer5
          <idle>-0     [001] d..2   804.724219: cpu_idle: state=4294967295 cpu_id=1
 vslam_framewor-3240  [004] d.h2   804.724220: hrtimer_cancel: hrtimer=ffffffc1f5c0a110
 vslam_framewor-3239  [003] d.h2   804.724220: hrtimer_cancel: hrtimer=ffffffc1f5bf9110

@bbasu

Thanks for you reply.

Can you share the Documentation how to apply RT patches on JetPacke3.3?

We have already disable CPU_IDLE_TEGRA18X as you suggested, let us see the result next day.

Depended on CPU_IDLE_TEGRA18X, if needed we will do test with only one cpu online.

Here is another log snapshot.
804.252196->804.724216 lost irq. From the log we found cpu 1 execute tick_stop-> “cpu_idle: state=0 cpu_id=1” -> “cpu_idle: state=4294967295 cpu_id=1”.

Maybe the root cause is CPU_IDLE_TEGRA18X as you mentioned before? Let us wait our final test result.

<idle>-0     [001] d..2   804.252182: tick_stop: success=yes msg=  
          <idle>-0     [002] d..2   804.252182: tick_stop: success=yes msg=  
          <idle>-0     [001] d..3   804.252184: hrtimer_cancel: hrtimer=ffffffc1f5bd7110
          <idle>-0     [002] d..3   804.252184: hrtimer_cancel: hrtimer=ffffffc1f5be8110
 vslam_framewor-3236  [004] d..3   804.252185: sched_stat_wait: comm=vslam_framewor pid=3240 delay=72640 [ns]
          <idle>-0     [001] d..3   804.252186: hrtimer_start: hrtimer=ffffffc1f5bd7110 function=tick_sched_timer expires=804804000000 softexpires=804804000000
          <idle>-0     [002] d..3   804.252186: hrtimer_start: hrtimer=ffffffc1f5be8110 function=tick_sched_timer expires=804792000000 softexpires=804792000000
 vslam_framewor-3236  [004] d..3   804.252187: sched_switch: prev_comm=vslam_framewor prev_pid=3236 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3240 next_prio=120
 vslam_framewor-3239  [003] d..2   804.252192: sched_waking: comm=vslam_framewor pid=3236 prio=120 target_cpu=004
          <idle>-0     [001] d..2   804.252192: cpu_idle: state=0 cpu_id=1
          <idle>-0     [002] d..2   804.252192: cpu_idle: state=0 cpu_id=2
 vslam_framewor-3239  [003] d..3   804.252194: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=12672 [ns] vruntime=256533434884 [ns]
 vslam_framewor-3239  [003] d..3   804.252195: sched_stat_sleep: comm=vslam_framewor pid=3236 delay=12672 [ns]
 vslam_framewor-3239  [003] d..3   804.252196: sched_wakeup: comm=vslam_framewor pid=3236 prio=120 target_cpu=004
     ksoftirqd/0-3     [000] d.H1   804.724216: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3240  [004] d.h1   804.724219: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_framewor-3239  [003] d.h1   804.724219: irq_handler_entry: irq=9 name=tegra186_timer3
 vslam_framewor-3216  [005] d.h1   804.724219: irq_handler_entry: irq=11 name=tegra186_timer5
          <idle>-0     [001] d..2   804.724219: cpu_idle: state=4294967295 cpu_id=1
 vslam_framewor-3240  [004] d.h2   804.724220: hrtimer_cancel: hrtimer=ffffffc1f5c0a110
 vslam_framewor-3239  [003] d.h2   804.724220: hrtimer_cancel: hrtimer=ffffffc1f5bf9110

The follow is our whole log info for ref.

vslam_framewor-3101  [004] d..2   804.200001: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3101  [004] d..3   804.200005: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.200006: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260577682 softexpires=804260577682
 vslam_framewor-3101  [004] d..2   804.200006: itimer_state: which=0 expires=0 it_value=0.3187 it_interval=0.100000
 vslam_framewor-3101  [004] d..3   804.200007: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.200008: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260579378 softexpires=804260579378
   Capture Plane-3251  [000] d..3   804.200008: sched_stat_runtime: comm=Capture Plane pid=3251 runtime=139200 [ns] vruntime=229261859336 [ns]
 vslam_framewor-3101  [004] d..2   804.200009: itimer_state: which=0 expires=0 it_value=0.3187 it_interval=0.100000
   Capture Plane-3251  [000] d..3   804.200011: sched_stat_wait: comm=kworker/u12:0 pid=6 delay=1427744 [ns]
   Capture Plane-3251  [000] d..3   804.200013: sched_switch: prev_comm=Capture Plane prev_pid=3251 prev_prio=120 prev_state=S ==> next_comm=kworker/u12:0 next_pid=6 next_prio=120
   kworker/u12:0-6     [000] d..2   804.200024: timer_cancel: timer=ffffffc1eb367180
   kworker/u12:0-6     [000] d.h2   804.200044: irq_handler_entry: irq=42 name=ether_qos.common_irq
   kworker/u12:0-6     [000] d.h2   804.200048: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3222  [003] d..3   804.200052: sched_stat_runtime: comm=vslam_framewor pid=3222 runtime=56000 [ns] vruntime=255025506800 [ns]
   kworker/u12:0-6     [000] d.h1   804.200053: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3222  [003] d..3   804.200055: sched_stat_wait: comm=vslam_framewor pid=3249 delay=56000 [ns]
 vslam_framewor-3222  [003] d..3   804.200057: sched_switch: prev_comm=vslam_framewor prev_pid=3222 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3249 next_prio=120
 vslam_framewor-3101  [004] d..2   804.200061: timer_cancel: timer=ffffffc1e2e4c748
   kworker/u12:0-6     [000] d.h1   804.200062: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..2   804.200063: timer_start: timer=ffffffc1e2e4c748 function=tcp_write_timer expires=4295093411 [timeout=51] flags=0x00000000
 vslam_framewor-3249  [003] d..3   804.200066: sched_stat_runtime: comm=vslam_framewor pid=3249 runtime=14400 [ns] vruntime=255025435952 [ns]
 vslam_framewor-3249  [003] d..3   804.200067: sched_stat_wait: comm=vslam_framewor pid=3236 delay=99648 [ns]
   kworker/u12:0-6     [000] d.h1   804.200067: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3249  [003] d..3   804.200068: sched_switch: prev_comm=vslam_framewor prev_pid=3249 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3236 next_prio=120
   kworker/u12:0-6     [000] ..s1   804.200069: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..3   804.200082: sched_stat_runtime: comm=vslam_framewor pid=3101 runtime=168064 [ns] vruntime=256510244900 [ns]
 vslam_framewor-3101  [004] d..3   804.200086: sched_stat_wait: comm=rcu_preempt pid=7 delay=1438752 [ns]
 vslam_framewor-3101  [004] d..3   804.200089: sched_switch: prev_comm=vslam_framewor prev_pid=3101 prev_prio=120 prev_state=S ==> next_comm=rcu_preempt next_pid=7 next_prio=120
     rcu_preempt-7     [004] ...1   804.200097: timer_init: timer=ffffffc1ecab7d30
     rcu_preempt-7     [004] d..2   804.200098: timer_start: timer=ffffffc1ecab7d30 function=process_timeout expires=4295093361 [timeout=1] flags=0x00000004
     rcu_preempt-7     [004] d..3   804.200099: sched_stat_runtime: comm=rcu_preempt pid=7 runtime=16672 [ns] vruntime=256510093508 [ns]
     rcu_preempt-7     [004] d..3   804.200100: sched_stat_wait: comm=Capture Plane pid=11424 delay=1449216 [ns]
     rcu_preempt-7     [004] d..3   804.200102: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=Capture Plane next_pid=11424 next_prio=120
   kworker/u12:0-6     [000] d.s2   804.200106: softirq_raise: vec=3 [action=NET_RX]
   kworker/u12:0-6     [000] ..s1   804.200114: softirq_exit: vec=3 [action=NET_RX]
   kworker/u12:0-6     [000] d.H3   804.200114: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
   kworker/u12:0-6     [000] d.H3   804.200114: softirq_raise: vec=3 [action=NET_RX]
   kworker/u12:0-6     [000] d.H3   804.200114: irq_handler_exit: irq=45 ret=handled
   kworker/u12:0-6     [000] ..s1   804.200130: softirq_entry: vec=3 [action=NET_RX]
   kworker/u12:0-6     [000] d.s4   804.200147: sched_waking: comm=vslam_framewor pid=3387 prio=120 target_cpu=000
   kworker/u12:0-6     [000] d.s5   804.200150: sched_stat_runtime: comm=kworker/u12:0 pid=6 runtime=142016 [ns] vruntime=229261902632 [ns]
   Capture Plane-11424 [004] d..2   804.200152: sched_waking: comm=Capture Plane pid=11423 prio=120 target_cpu=005
   kworker/u12:0-6     [000] d.s5   804.200153: sched_stat_sleep: comm=vslam_framewor pid=3387 delay=281216 [ns]
   kworker/u12:0-6     [000] d.s5   804.200155: sched_wakeup: comm=vslam_framewor pid=3387 prio=120 target_cpu=000
   kworker/u12:0-6     [000] d.H3   804.200157: irq_handler_entry: irq=42 name=ether_qos.common_irq
   Capture Plane-11424 [004] d..3   804.200157: sched_stat_runtime: comm=vslam_framewor pid=3163 runtime=1460128 [ns] vruntime=279395075523 [ns]
   Capture Plane-11424 [004] d..3   804.200160: sched_stat_sleep: comm=Capture Plane pid=11423 delay=20893984 [ns]
   Capture Plane-11424 [004] d..3   804.200161: sched_wakeup: comm=Capture Plane pid=11423 prio=120 target_cpu=005
   kworker/u12:0-6     [000] d.H3   804.200161: irq_handler_exit: irq=42 ret=handled
   kworker/u12:0-6     [000] ..s1   804.200171: softirq_exit: vec=3 [action=NET_RX]
   kworker/u12:0-6     [000] d.H3   804.200171: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
   kworker/u12:0-6     [000] d.H3   804.200171: softirq_raise: vec=3 [action=NET_RX]
   kworker/u12:0-6     [000] d.H3   804.200171: irq_handler_exit: irq=45 ret=handled
   Capture Plane-11424 [004] ...1   804.200173: timer_init: timer=ffffffc04acf3a90
   Capture Plane-11424 [004] d..2   804.200174: timer_start: timer=ffffffc04acf3a90 function=process_timeout expires=4295093361 [timeout=1] flags=0x00000004
   Capture Plane-11424 [004] d..3   804.200175: sched_stat_runtime: comm=Capture Plane pid=11424 runtime=75936 [ns] vruntime=256510152772 [ns]
   Capture Plane-11424 [004] d..3   804.200178: sched_stat_wait: comm=vslam_framewor pid=3100 delay=3603904 [ns]
   Capture Plane-11424 [004] d..3   804.200182: sched_switch: prev_comm=Capture Plane prev_pid=11424 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3100 next_prio=120
   kworker/u12:0-6     [000] ..s1   804.200189: softirq_entry: vec=3 [action=NET_RX]
   kworker/u12:0-6     [000] ..s1   804.200190: softirq_exit: vec=3 [action=NET_RX]
   kworker/u12:0-6     [000] d..3   804.200209: sched_stat_runtime: comm=kworker/u12:0 pid=6 runtime=58560 [ns] vruntime=229261961192 [ns]
   kworker/u12:0-6     [000] d..3   804.200212: sched_stat_wait: comm=vslam_framewor pid=3168 delay=1566624 [ns]
   kworker/u12:0-6     [000] d..3   804.200213: sched_switch: prev_comm=kworker/u12:0 prev_pid=6 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3168 next_prio=120
 vslam_framewor-3100  [004] d..3   804.200219: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.200221: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804357604859 softexpires=804357604859
 vslam_framewor-3100  [004] d..2   804.200222: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3100  [004] d..3   804.200225: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.200225: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260585979 softexpires=804260585979
 vslam_framewor-3168  [000] ...1   804.200226: timer_init: timer=ffffffc1bed73a90
 vslam_framewor-3100  [004] d..2   804.200226: itimer_state: which=0 expires=0 it_value=0.2976 it_interval=0.100000
 vslam_framewor-3168  [000] d..2   804.200226: timer_start: timer=ffffffc1bed73a90 function=process_timeout expires=4295093361 [timeout=1] flags=0x00000000
 vslam_framewor-3100  [004] d..3   804.200227: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3168  [000] d..3   804.200227: sched_stat_runtime: comm=vslam_framewor pid=3168 runtime=19072 [ns] vruntime=229261958984 [ns]
 vslam_framewor-3100  [004] d..3   804.200227: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260588027 softexpires=804260588027
 vslam_framewor-3100  [004] d..2   804.200228: itimer_state: which=0 expires=0 it_value=0.2976 it_interval=0.100000
 vslam_framewor-3168  [000] d..3   804.200228: sched_stat_wait: comm=vslam_framewor pid=3387 delay=77632 [ns]
 vslam_framewor-3168  [000] d..3   804.200229: sched_switch: prev_comm=vslam_framewor prev_pid=3168 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3387 next_prio=120
 vslam_framewor-3387  [000] d..2   804.200231: hrtimer_cancel: hrtimer=ffffffc167647890
 vslam_framewor-3387  [000] d.h1   804.200241: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.h1   804.200246: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] d.h1   804.200260: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3387  [000] d.h1   804.200268: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.200273: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3387  [000] ..s1   804.200273: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3100  [004] d..3   804.200276: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.200278: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804357662075 softexpires=804357662075
 vslam_framewor-3100  [004] d..2   804.200279: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3100  [004] d..3   804.200282: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.200282: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260593843 softexpires=804260593843
 vslam_framewor-3100  [004] d..2   804.200283: itimer_state: which=0 expires=0 it_value=0.2927 it_interval=0.100000
 vslam_framewor-3100  [004] d..3   804.200283: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.200284: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260595571 softexpires=804260595571
 vslam_framewor-3100  [004] d..2   804.200284: itimer_state: which=0 expires=0 it_value=0.2927 it_interval=0.100000
 vslam_framewor-3387  [000] d.s2   804.200293: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.200308: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H3   804.200308: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.H3   804.200308: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H3   804.200308: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] ..s1   804.200324: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H1   804.200327: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3100  [004] d..3   804.200327: sched_stat_runtime: comm=vslam_framewor pid=3100 runtime=151936 [ns] vruntime=256510457220 [ns]
 vslam_framewor-3100  [004] d..3   804.200330: sched_stat_wait: comm=vslam_framewor pid=3240 delay=4245344 [ns]
 vslam_framewor-3100  [004] d..3   804.200332: sched_switch: prev_comm=vslam_framewor prev_pid=3100 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3240 next_prio=120
 vslam_framewor-3387  [000] d.H1   804.200332: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] d.s2   804.200337: timer_cancel: timer=ffffffc0713fe448
 vslam_framewor-3387  [000] d.s2   804.200338: timer_start: timer=ffffffc0713fe448 function=death_by_timeout expires=4403093360 [timeout=108000000] flags=0x00000000
 vslam_framewor-3387  [000] d.s2   804.200354: timer_cancel: timer=ffffffc0713fe308
 vslam_framewor-3387  [000] d.s2   804.200355: timer_start: timer=ffffffc0713fe308 function=death_by_timeout expires=4295168360 [timeout=75000] flags=0x00000000
 vslam_framewor-3387  [000] d.s3   804.200359: timer_start: timer=ffffffc1e2e4cf18 function=tcp_delack_timer expires=4295093370 [timeout=10] flags=0x00000000
 vslam_framewor-3387  [000] d.s4   804.200361: sched_waking: comm=vslam_framewor pid=3101 prio=120 target_cpu=004
 vslam_framewor-3387  [000] d.s5   804.200364: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=36896 [ns] vruntime=256519113732 [ns]
 vslam_framewor-3387  [000] d.s5   804.200366: sched_stat_sleep: comm=vslam_framewor pid=3101 delay=281440 [ns]
 vslam_framewor-3387  [000] d.s5   804.200369: sched_wakeup: comm=vslam_framewor pid=3101 prio=120 target_cpu=004
 vslam_framewor-3240  [004] dn.3   804.200371: sched_stat_wait: comm=vslam_framewor pid=3101 delay=0 [ns]
 vslam_framewor-3240  [004] d..3   804.200372: sched_switch: prev_comm=vslam_framewor prev_pid=3240 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3101 next_prio=120
 vslam_framewor-3387  [000] d.H2   804.200382: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3387  [000] d.H2   804.200391: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H2   804.200396: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3387  [000] ..s1   804.200397: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.200397: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.200399: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..3   804.200413: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.200415: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804357799196 softexpires=804357799196
 vslam_framewor-3101  [004] d..2   804.200416: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3101  [004] d..3   804.200418: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.200419: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260600580 softexpires=804260600580
 vslam_framewor-3101  [004] d..2   804.200419: itimer_state: which=0 expires=0 it_value=0.2797 it_interval=0.100000
 vslam_framewor-3101  [004] d..3   804.200420: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.200421: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260602308 softexpires=804260602308
 vslam_framewor-3101  [004] d..2   804.200421: itimer_state: which=0 expires=0 it_value=0.2797 it_interval=0.100000
 vslam_framewor-3387  [000] d.h2   804.200452: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3101  [004] d..2   804.200455: timer_cancel: timer=ffffffc1e2e4cec8
 vslam_framewor-3101  [004] d..2   804.200456: timer_start: timer=ffffffc1e2e4cec8 function=tcp_write_timer expires=4295093411 [timeout=51] flags=0x00000000
 vslam_framewor-3387  [000] d.h2   804.200458: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] d.h2   804.200459: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3387  [000] d.h2   804.200467: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h2   804.200472: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3387  [000] ..s2   804.200473: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..3   804.200473: sched_stat_runtime: comm=vslam_framewor pid=3101 runtime=108672 [ns] vruntime=256510353572 [ns]
 vslam_framewor-3101  [004] d..3   804.200476: sched_stat_wait: comm=vslam_framewor pid=3240 delay=108672 [ns]
 vslam_framewor-3101  [004] d..3   804.200479: sched_switch: prev_comm=vslam_framewor prev_pid=3101 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3240 next_prio=120
 vslam_framewor-3387  [000] d.s3   804.200491: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s2   804.200507: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H4   804.200507: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.H4   804.200507: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H4   804.200507: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] ..s2   804.200523: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.s5   804.200542: sched_waking: comm=vslam_framewor pid=3100 prio=120 target_cpu=004
 vslam_framewor-3387  [000] d.s6   804.200545: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=72064 [ns] vruntime=256519185796 [ns]
 vslam_framewor-3387  [000] d.s6   804.200547: sched_stat_sleep: comm=vslam_framewor pid=3100 delay=217632 [ns]
 vslam_framewor-3387  [000] d.s6   804.200549: sched_wakeup: comm=vslam_framewor pid=3100 prio=120 target_cpu=004
 vslam_framewor-3240  [004] dn.3   804.200550: sched_stat_wait: comm=vslam_framewor pid=3100 delay=0 [ns]
 vslam_framewor-3387  [000] d.H4   804.200551: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3240  [004] d..3   804.200551: sched_switch: prev_comm=vslam_framewor prev_pid=3240 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3100 next_prio=120
 vslam_framewor-3387  [000] d.H4   804.200556: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] ..s2   804.200558: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d..3   804.200561: sched_waking: comm=dcu_log_daemo pid=1299 prio=120 target_cpu=000
 vslam_framewor-3387  [000] d..4   804.200563: sched_stat_runtime: comm=vslam_framewor pid=3387 runtime=335200 [ns] vruntime=229265994312 [ns]
 vslam_framewor-3387  [000] d..4   804.200564: sched_stat_sleep: comm=dcu_log_daemo pid=1299 delay=3646656 [ns]
 vslam_framewor-3387  [000] d..4   804.200564: sched_wakeup: comm=dcu_log_daemo pid=1299 prio=120 target_cpu=000
 vslam_framewor-3387  [000] d.h1   804.200568: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.h1   804.200576: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3100  [004] d..3   804.200578: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.200580: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804357963580 softexpires=804357963580
 vslam_framewor-3100  [004] d..2   804.200581: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3387  [000] d.h1   804.200581: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] ..s1   804.200582: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3100  [004] d..3   804.200583: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.200584: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260608188 softexpires=804260608188
 vslam_framewor-3100  [004] d..2   804.200584: itimer_state: which=0 expires=0 it_value=0.2640 it_interval=0.100000
 vslam_framewor-3100  [004] d..3   804.200585: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.200585: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260610108 softexpires=804260610108
 vslam_framewor-3100  [004] d..2   804.200586: itimer_state: which=0 expires=0 it_value=0.2640 it_interval=0.100000
 vslam_framewor-3387  [000] d.s2   804.200593: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.200599: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.200600: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.s2   804.200605: timer_cancel: timer=ffffffc0713fe308
 vslam_framewor-3387  [000] d.s2   804.200606: timer_start: timer=ffffffc0713fe308 function=death_by_timeout expires=4403093360 [timeout=108000000] flags=0x00000000
 vslam_framewor-3387  [000] ..s1   804.200615: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.200630: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3100  [004] d..3   804.200632: sched_stat_runtime: comm=vslam_framewor pid=3100 runtime=86976 [ns] vruntime=256510544196 [ns]
 vslam_framewor-3100  [004] d..3   804.200635: sched_stat_wait: comm=vslam_framewor pid=3240 delay=86976 [ns]
 vslam_framewor-3100  [004] d..3   804.200638: sched_switch: prev_comm=vslam_framewor prev_pid=3100 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3240 next_prio=120
 vslam_framewor-3387  [000] d.h1   804.200638: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.200643: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3387  [000] d.H1   804.200645: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.H1   804.200649: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] ..s1   804.200650: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.200660: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.200881: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.h1   804.200887: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] d.h1   804.200961: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.h1   804.200970: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.200975: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] ..s1   804.200976: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.s2   804.200993: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201002: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201003: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.s4   804.201025: sched_waking: comm=vslam_framewor pid=3100 prio=120 target_cpu=004
 vslam_framewor-3387  [000] d.s5   804.201030: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=397984 [ns] vruntime=256519583780 [ns]
 vslam_framewor-3387  [000] d.s5   804.201033: sched_stat_sleep: comm=vslam_framewor pid=3100 delay=397984 [ns]
 vslam_framewor-3387  [000] d.s5   804.201038: sched_wakeup: comm=vslam_framewor pid=3100 prio=120 target_cpu=004
 vslam_framewor-3240  [004] dn.3   804.201041: sched_stat_wait: comm=vslam_framewor pid=3100 delay=0 [ns]
 vslam_framewor-3387  [000] ..s1   804.201041: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3240  [004] d..3   804.201042: sched_switch: prev_comm=vslam_framewor prev_pid=3240 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3100 next_prio=120
 vslam_framewor-3100  [004] d..3   804.201083: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.201086: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804358469246 softexpires=804358469246
 vslam_framewor-3100  [004] d..2   804.201087: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3100  [004] d..3   804.201092: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.201093: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260620438 softexpires=804260620438
 vslam_framewor-3100  [004] d..2   804.201093: itimer_state: which=0 expires=0 it_value=0.2143 it_interval=0.100000
 vslam_framewor-3100  [004] d..3   804.201095: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.201095: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260622742 softexpires=804260622742
 vslam_framewor-3100  [004] d..2   804.201095: itimer_state: which=0 expires=0 it_value=0.2143 it_interval=0.100000
 vslam_framewor-3387  [000] d.h1   804.201155: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3100  [004] d..3   804.201159: sched_stat_runtime: comm=vslam_framewor pid=3100 runtime=128000 [ns] vruntime=256510711780 [ns]
 vslam_framewor-3387  [000] d.h1   804.201163: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3100  [004] d..3   804.201166: sched_stat_wait: comm=vslam_framewor pid=3240 delay=128000 [ns]
 vslam_framewor-3100  [004] d..3   804.201168: sched_switch: prev_comm=vslam_framewor prev_pid=3100 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3240 next_prio=120
 vslam_framewor-3387  [000] d.h1   804.201169: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3387  [000] d.H1   804.201171: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.H1   804.201176: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] ..s1   804.201176: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201189: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.201282: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.h1   804.201287: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] d.h1   804.201363: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.h1   804.201371: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.201376: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] ..s1   804.201377: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.s2   804.201392: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201401: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201402: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H1   804.201403: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.H1   804.201407: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] d.s2   804.201422: timer_cancel: timer=ffffffc0713fef88
 vslam_framewor-3387  [000] d.s2   804.201424: timer_start: timer=ffffffc0713fef88 function=death_by_timeout expires=4295168360 [timeout=75000] flags=0x00000000
 vslam_framewor-3387  [000] d.s3   804.201436: timer_start: timer=ffffffc1e2e4b898 function=tcp_delack_timer expires=4295093370 [timeout=10] flags=0x00000000
 vslam_framewor-3387  [000] d.s4   804.201439: sched_waking: comm=vslam_framewor pid=3101 prio=120 target_cpu=004
 vslam_framewor-3387  [000] d.s5   804.201444: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=285888 [ns] vruntime=256519869668 [ns]
 vslam_framewor-3387  [000] d.s5   804.201446: sched_stat_sleep: comm=vslam_framewor pid=3101 delay=970912 [ns]
 vslam_framewor-3387  [000] d.s5   804.201450: sched_wakeup: comm=vslam_framewor pid=3101 prio=120 target_cpu=004
 vslam_framewor-3387  [000] ..s1   804.201452: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3240  [004] dn.3   804.201453: sched_stat_wait: comm=vslam_framewor pid=3101 delay=0 [ns]
 vslam_framewor-3240  [004] d..3   804.201454: sched_switch: prev_comm=vslam_framewor prev_pid=3240 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3101 next_prio=120
 vslam_framewor-3387  [000] d.h1   804.201485: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.h1   804.201494: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.201499: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] ..s1   804.201500: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H1   804.201501: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.H1   804.201506: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3101  [004] d..3   804.201518: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.201520: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804358903872 softexpires=804358903872
 vslam_framewor-3387  [000] d.s2   804.201521: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..2   804.201521: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3101  [004] d..3   804.201525: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.201526: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260631624 softexpires=804260631624
 vslam_framewor-3101  [004] d..2   804.201526: itimer_state: which=0 expires=0 it_value=0.1721 it_interval=0.100000
 vslam_framewor-3387  [000] ..s1   804.201527: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..3   804.201528: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.201528: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260633896 softexpires=804260633896
 vslam_framewor-3387  [000] ..s1   804.201528: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..2   804.201529: itimer_state: which=0 expires=0 it_value=0.1721 it_interval=0.100000
 vslam_framewor-3387  [000] d.s4   804.201543: sched_waking: comm=vslam_framewor pid=3100 prio=120 target_cpu=004
 vslam_framewor-3387  [000] d.s5   804.201546: sched_stat_runtime: comm=vslam_framewor pid=3101 runtime=101888 [ns] vruntime=256510971556 [ns]
 vslam_framewor-3387  [000] d.s5   804.201548: sched_stat_sleep: comm=vslam_framewor pid=3100 delay=387776 [ns]
 vslam_framewor-3387  [000] d.s5   804.201549: sched_wakeup: comm=vslam_framewor pid=3100 prio=120 target_cpu=004
 vslam_framewor-3387  [000] ..s1   804.201551: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..2   804.201573: timer_cancel: timer=ffffffc1e2e4b848
 vslam_framewor-3101  [004] d..2   804.201575: timer_start: timer=ffffffc1e2e4b848 function=tcp_write_timer expires=4295093411 [timeout=51] flags=0x00000005
 vslam_framewor-3387  [000] d.h1   804.201575: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3387  [000] d.h1   804.201583: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.201588: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3387  [000] ..s1   804.201589: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..3   804.201597: sched_stat_runtime: comm=vslam_framewor pid=3101 runtime=50752 [ns] vruntime=256511022308 [ns]
 vslam_framewor-3101  [004] d..3   804.201601: sched_stat_wait: comm=vslam_framewor pid=3100 delay=50752 [ns]
 vslam_framewor-3101  [004] d..3   804.201604: sched_switch: prev_comm=vslam_framewor prev_pid=3101 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3100 next_prio=120
 vslam_framewor-3387  [000] d.s2   804.201606: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201613: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H3   804.201613: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.H3   804.201613: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H3   804.201613: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] ..s1   804.201629: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3100  [004] d..3   804.201632: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.201635: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804359017824 softexpires=804359017824
 vslam_framewor-3100  [004] d..2   804.201636: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3100  [004] d..3   804.201639: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.201639: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260642160 softexpires=804260642160
 vslam_framewor-3100  [004] d..2   804.201640: itimer_state: which=0 expires=0 it_value=0.1618 it_interval=0.100000
 vslam_framewor-3100  [004] d..3   804.201641: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.201641: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260643792 softexpires=804260643792
 vslam_framewor-3100  [004] d..2   804.201641: itimer_state: which=0 expires=0 it_value=0.1618 it_interval=0.100000
 vslam_framewor-3387  [000] ..s1   804.201643: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.201681: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3100  [004] d..3   804.201685: sched_stat_runtime: comm=vslam_framewor pid=3100 runtime=88320 [ns] vruntime=256510957988 [ns]
 vslam_framewor-3100  [004] d..3   804.201689: sched_stat_wait: comm=vslam_framewor pid=3240 delay=240960 [ns]
 vslam_framewor-3387  [000] d.h1   804.201689: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3100  [004] d..3   804.201691: sched_switch: prev_comm=vslam_framewor prev_pid=3100 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3240 next_prio=120
 vslam_framewor-3387  [000] d.h1   804.201694: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3387  [000] d.H1   804.201696: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.H1   804.201701: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] ..s1   804.201701: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.s2   804.201719: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201726: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201727: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.s2   804.201734: timer_cancel: timer=ffffffc0713fef88
 vslam_framewor-3387  [000] d.s2   804.201735: timer_start: timer=ffffffc0713fef88 function=death_by_timeout expires=4403093360 [timeout=108000000] flags=0x00000000
 vslam_framewor-3387  [000] ..s1   804.201747: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.201763: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.h1   804.201771: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.201776: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] ..s1   804.201777: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H1   804.201782: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.H1   804.201786: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] d.s2   804.201797: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201826: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201827: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.s2   804.201833: timer_cancel: timer=ffffffc0713fee48
 vslam_framewor-3387  [000] d.s2   804.201834: timer_start: timer=ffffffc0713fee48 function=death_by_timeout expires=4295168360 [timeout=75000] flags=0x00000000
 vslam_framewor-3387  [000] d.s3   804.201839: timer_start: timer=ffffffc1e2e4c018 function=tcp_delack_timer expires=4295093370 [timeout=10] flags=0x00000000
 vslam_framewor-3387  [000] d.s4   804.201840: sched_waking: comm=vslam_framewor pid=3101 prio=120 target_cpu=004
 vslam_framewor-3387  [000] d.s5   804.201844: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=159168 [ns] vruntime=256520028836 [ns]
 vslam_framewor-3387  [000] d.s5   804.201846: sched_stat_sleep: comm=vslam_framewor pid=3101 delay=247488 [ns]
 vslam_framewor-3387  [000] d.s5   804.201849: sched_wakeup: comm=vslam_framewor pid=3101 prio=120 target_cpu=004
 vslam_framewor-3240  [004] dn.3   804.201851: sched_stat_wait: comm=vslam_framewor pid=3101 delay=0 [ns]
 vslam_framewor-3240  [004] d..3   804.201852: sched_switch: prev_comm=vslam_framewor prev_pid=3240 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3101 next_prio=120
 vslam_framewor-3387  [000] d.H1   804.201864: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.H1   804.201872: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H1   804.201877: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] d.s4   804.201880: sched_waking: comm=vslam_framewor pid=3100 prio=120 target_cpu=004
 vslam_framewor-3387  [000] d.s5   804.201881: sched_stat_runtime: comm=vslam_framewor pid=3101 runtime=37792 [ns] vruntime=256511066628 [ns]
 vslam_framewor-3387  [000] d.s5   804.201883: sched_stat_sleep: comm=vslam_framewor pid=3100 delay=196960 [ns]
 vslam_framewor-3387  [000] d.s5   804.201884: sched_wakeup: comm=vslam_framewor pid=3100 prio=120 target_cpu=004
 vslam_framewor-3387  [000] ..s1   804.201885: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201885: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.201888: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..3   804.201896: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.201898: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804359282401 softexpires=804359282401
 vslam_framewor-3101  [004] d..2   804.201899: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3101  [004] d..3   804.201903: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.201903: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260651033 softexpires=804260651033
 vslam_framewor-3101  [004] d..2   804.201904: itimer_state: which=0 expires=0 it_value=0.1363 it_interval=0.100000
 vslam_framewor-3101  [004] d..3   804.201905: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.201905: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260652985 softexpires=804260652985
 vslam_framewor-3101  [004] d..2   804.201906: itimer_state: which=0 expires=0 it_value=0.1363 it_interval=0.100000
 vslam_framewor-3101  [004] d..2   804.201946: timer_cancel: timer=ffffffc1e2e4bfc8
 vslam_framewor-3101  [004] d..2   804.201947: timer_start: timer=ffffffc1e2e4bfc8 function=tcp_write_timer expires=4295093411 [timeout=51] flags=0x00000004
 vslam_framewor-3387  [000] d.h1   804.201949: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3387  [000] d.h1   804.201956: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.201962: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3387  [000] d.H1   804.201963: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3101  [004] d..3   804.201966: sched_stat_runtime: comm=vslam_framewor pid=3101 runtime=84064 [ns] vruntime=256511150692 [ns]
 vslam_framewor-3387  [000] d.H1   804.201968: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] ..s1   804.201969: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..3   804.201970: sched_stat_wait: comm=vslam_framewor pid=3100 delay=84064 [ns]
 vslam_framewor-3101  [004] d..3   804.201971: sched_switch: prev_comm=vslam_framewor prev_pid=3101 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3100 next_prio=120
 vslam_framewor-3387  [000] ..s1   804.201978: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3100  [004] d..3   804.202002: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.202003: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804359387682 softexpires=804359387682
 vslam_framewor-3100  [004] d..2   804.202004: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3100  [004] d..3   804.202007: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.202008: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260658226 softexpires=804260658226
 vslam_framewor-3100  [004] d..2   804.202008: itimer_state: which=0 expires=0 it_value=0.1266 it_interval=0.100000
 vslam_framewor-3100  [004] d..3   804.202009: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3100  [004] d..3   804.202009: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260659922 softexpires=804260659922
 vslam_framewor-3100  [004] d..2   804.202010: itimer_state: which=0 expires=0 it_value=0.1266 it_interval=0.100000
 vslam_framewor-3387  [000] d.h1   804.202054: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3100  [004] d..3   804.202057: sched_stat_runtime: comm=vslam_framewor pid=3100 runtime=90912 [ns] vruntime=256511119748 [ns]
 vslam_framewor-3100  [004] d..3   804.202061: sched_stat_wait: comm=vslam_framewor pid=3240 delay=212768 [ns]
 vslam_framewor-3387  [000] d.h1   804.202062: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3100  [004] d..3   804.202062: sched_switch: prev_comm=vslam_framewor prev_pid=3100 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3240 next_prio=120
 vslam_framewor-3387  [000] d.h1   804.202067: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3387  [000] d.H1   804.202069: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.H1   804.202073: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] ..s1   804.202074: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.202082: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.202181: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.h1   804.202186: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] d.h1   804.202194: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.h1   804.202202: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.202207: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] ..s1   804.202207: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.s2   804.202222: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.202240: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.202241: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.s2   804.202250: timer_cancel: timer=ffffffc0713fee48
 vslam_framewor-3387  [000] d.s2   804.202251: timer_start: timer=ffffffc0713fee48 function=death_by_timeout expires=4403093360 [timeout=108000000] flags=0x00000000
 vslam_framewor-3387  [000] d.H2   804.202262: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.H2   804.202271: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.H2   804.202276: irq_handler_exit: irq=44 ret=handled
 vslam_framewor-3387  [000] d.s2   804.202283: timer_cancel: timer=ffffffc1e4ba8bc8
 vslam_framewor-3387  [000] d.s2   804.202283: timer_start: timer=ffffffc1e4ba8bc8 function=death_by_timeout expires=4295168360 [timeout=75000] flags=0x00000000
 vslam_framewor-3387  [000] d.s3   804.202287: timer_start: timer=ffffffc1e2e49a98 function=tcp_delack_timer expires=4295093370 [timeout=10] flags=0x00000000
 vslam_framewor-3387  [000] d.s4   804.202290: sched_waking: comm=vslam_framewor pid=3101 prio=120 target_cpu=004
 vslam_framewor-3387  [000] d.s5   804.202294: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=237248 [ns] vruntime=256520266084 [ns]
 vslam_framewor-3387  [000] d.s5   804.202297: sched_stat_sleep: comm=vslam_framewor pid=3101 delay=328160 [ns]
 vslam_framewor-3387  [000] d.s5   804.202300: sched_wakeup: comm=vslam_framewor pid=3101 prio=120 target_cpu=004
 vslam_framewor-3387  [000] ..s1   804.202302: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] ..s1   804.202302: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3240  [004] dn.3   804.202302: sched_stat_wait: comm=vslam_framewor pid=3101 delay=0 [ns]
 vslam_framewor-3240  [004] d..3   804.202304: sched_switch: prev_comm=vslam_framewor prev_pid=3240 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3101 next_prio=120
 vslam_framewor-3387  [000] ..s1   804.202304: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..3   804.202356: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.202359: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804359743075 softexpires=804359743075
 vslam_framewor-3101  [004] d..2   804.202360: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3101  [004] d..3   804.202364: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.202364: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260668803 softexpires=804260668803
 vslam_framewor-3101  [004] d..2   804.202365: itimer_state: which=0 expires=0 it_value=0.920 it_interval=0.100000
 vslam_framewor-3101  [004] d..3   804.202366: hrtimer_cancel: hrtimer=ffffffc077324c88
 vslam_framewor-3101  [004] d..3   804.202366: hrtimer_start: hrtimer=ffffffc077324c88 function=it_real_fn expires=804260670755 softexpires=804260670755
 vslam_framewor-3101  [004] d..2   804.202367: itimer_state: which=0 expires=0 it_value=0.920 it_interval=0.100000
 vslam_framewor-3101  [004] d..2   804.202417: timer_cancel: timer=ffffffc1e2e49a48
 vslam_framewor-3387  [000] d.h1   804.202419: irq_handler_entry: irq=45 name=2490000.ether_qos.tx0
 vslam_framewor-3101  [004] d..2   804.202419: timer_start: timer=ffffffc1e2e49a48 function=tcp_write_timer expires=4295093411 [timeout=51] flags=0x00000004
 vslam_framewor-3387  [000] d.h1   804.202427: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.202433: irq_handler_exit: irq=45 ret=handled
 vslam_framewor-3387  [000] d.H1   804.202434: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3387  [000] d.H1   804.202439: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] ..s1   804.202440: softirq_entry: vec=3 [action=NET_RX]
 vslam_framewor-3101  [004] d..3   804.202441: sched_stat_runtime: comm=vslam_framewor pid=3101 runtime=146080 [ns] vruntime=256511412164 [ns]
 vslam_framewor-3101  [004] d..3   804.202445: sched_stat_wait: comm=vslam_framewor pid=3240 delay=146080 [ns]
 vslam_framewor-3101  [004] d..3   804.202448: sched_switch: prev_comm=vslam_framewor prev_pid=3101 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3240 next_prio=120
 vslam_framewor-3387  [000] ..s1   804.202451: softirq_exit: vec=3 [action=NET_RX]
 vslam_framewor-3237  [002] d..3   804.202530: sched_stat_runtime: comm=vslam_framewor pid=3237 runtime=3125056 [ns] vruntime=387807105638 [ns]
 vslam_framewor-3237  [002] d..3   804.202537: sched_stat_runtime: comm=vslam_framewor pid=3237 runtime=5568 [ns] vruntime=387807111206 [ns]
 vslam_framewor-3237  [002] d..3   804.202541: sched_stat_runtime: comm=vslam_framewor pid=3237 runtime=7264 [ns] vruntime=387807118470 [ns]
 vslam_framewor-3237  [002] d..3   804.202542: sched_stat_runtime: comm=vslam_framewor pid=3237 runtime=1024 [ns] vruntime=387807119494 [ns]
 vslam_framewor-3237  [002] d..3   804.202543: sched_stat_runtime: comm=vslam_framewor pid=3237 runtime=832 [ns] vruntime=387807120326 [ns]
 vslam_framewor-3237  [002] d..3   804.202544: sched_stat_runtime: comm=vslam_framewor pid=3237 runtime=1024 [ns] vruntime=387807121350 [ns]
 vslam_framewor-3387  [000] d.h1   804.202619: irq_handler_entry: irq=6 name=tegra186_timer0
 vslam_framewor-3240  [004] d.h1   804.202620: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_framewor-3236  [003] d.h1   804.202620: irq_handler_entry: irq=9 name=tegra186_timer3
 vslam_framewor-3163  [005] d.h1   804.202620: irq_handler_entry: irq=11 name=tegra186_timer5
 vslam_framewor-3240  [004] d.h2   804.202622: hrtimer_cancel: hrtimer=ffffffc1f5c0a110
 vslam_framewor-3387  [000] d.h2   804.202622: hrtimer_cancel: hrtimer=ffffffc1f5bc6110
 vslam_framewor-3163  [005] d.h2   804.202622: hrtimer_cancel: hrtimer=ffffffc1f5c1b110
 vslam_framewor-3236  [003] d.h2   804.202622: hrtimer_cancel: hrtimer=ffffffc1f5bf9110
 vslam_framewor-3237  [002] d.h1   804.202623: irq_handler_entry: irq=8 name=tegra186_timer2
 vslam_framewor-3240  [004] d.h1   804.202623: hrtimer_expire_entry: hrtimer=ffffffc1f5c0a110 function=tick_sched_timer now=804260005796
 vslam_framewor-3387  [000] d.h1   804.202623: hrtimer_expire_entry: hrtimer=ffffffc1f5bc6110 function=tick_sched_timer now=804260005956
 vslam_framewor-3163  [005] d.h1   804.202623: hrtimer_expire_entry: hrtimer=ffffffc1f5c1b110 function=tick_sched_timer now=804260006372
 vslam_framewor-3236  [003] d.h1   804.202624: hrtimer_expire_entry: hrtimer=ffffffc1f5bf9110 function=tick_sched_timer now=804260006596
 vslam_framewor-3239  [001] d.h1   804.202624: irq_handler_entry: irq=7 name=tegra186_timer1
 vslam_framewor-3240  [004] d.h1   804.202626: softirq_raise: vec=1 [action=TIMER]
 vslam_framewor-3236  [003] d.h1   804.202626: softirq_raise: vec=1 [action=TIMER]
 vslam_framewor-3163  [005] d.h1   804.202626: softirq_raise: vec=1 [action=TIMER]
 vslam_framewor-3240  [004] d.h1   804.202628: softirq_raise: vec=9 [action=RCU]
 vslam_framewor-3163  [005] d.h1   804.202628: softirq_raise: vec=9 [action=RCU]
 vslam_framewor-3236  [003] d.h1   804.202629: softirq_raise: vec=9 [action=RCU]
 vslam_framewor-3237  [002] d.h2   804.202630: hrtimer_cancel: hrtimer=ffffffc1f5be8110
 vslam_framewor-3387  [000] d.h1   804.202630: softirq_raise: vec=1 [action=TIMER]
 vslam_framewor-3239  [001] d.h2   804.202630: hrtimer_cancel: hrtimer=ffffffc1f5bd7110
 vslam_framewor-3236  [003] d.h2   804.202630: sched_stat_runtime: comm=vslam_framewor pid=3236 runtime=2563552 [ns] vruntime=255036985104 [ns]
 vslam_framewor-3240  [004] d.h2   804.202630: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=189824 [ns] vruntime=256520455908 [ns]
 vslam_framewor-3163  [005] d.h2   804.202630: sched_stat_runtime: comm=vslam_framewor pid=3163 runtime=2473664 [ns] vruntime=279397549187 [ns]
 vslam_framewor-3387  [000] d.h1   804.202631: softirq_raise: vec=9 [action=RCU]
 vslam_framewor-3239  [001] d.h1   804.202631: hrtimer_expire_entry: hrtimer=ffffffc1f5bd7110 function=tick_sched_timer now=804260014116
 vslam_framewor-3237  [002] d.h1   804.202631: hrtimer_expire_entry: hrtimer=ffffffc1f5be8110 function=tick_sched_timer now=804260014148
 vslam_framewor-3387  [000] d.h2   804.202633: sched_stat_runtime: comm=vslam_framewor pid=3387 runtime=2069984 [ns] vruntime=229268064296 [ns]
 vslam_framewor-3236  [003] d.h1   804.202634: hrtimer_expire_exit: hrtimer=ffffffc1f5bf9110
 vslam_framewor-3240  [004] d.h1   804.202634: hrtimer_expire_exit: hrtimer=ffffffc1f5c0a110
 vslam_framewor-3163  [005] d.h1   804.202634: hrtimer_expire_exit: hrtimer=ffffffc1f5c1b110
 vslam_framewor-3239  [001] d.h1   804.202635: softirq_raise: vec=1 [action=TIMER]
 vslam_framewor-3237  [002] d.h1   804.202635: softirq_raise: vec=1 [action=TIMER]
 vslam_framewor-3387  [000] d.h1   804.202635: hrtimer_expire_exit: hrtimer=ffffffc1f5bc6110
 vslam_framewor-3236  [003] d.h2   804.202635: hrtimer_start: hrtimer=ffffffc1f5bf9110 function=tick_sched_timer expires=804264000000 softexpires=804264000000
 vslam_framewor-3240  [004] d.h2   804.202635: hrtimer_start: hrtimer=ffffffc1f5c0a110 function=tick_sched_timer expires=804264000000 softexpires=804264000000
 vslam_framewor-3163  [005] d.h2   804.202635: hrtimer_start: hrtimer=ffffffc1f5c1b110 function=tick_sched_timer expires=804264000000 softexpires=804264000000
 vslam_framewor-3387  [000] d.h2   804.202636: hrtimer_start: hrtimer=ffffffc1f5bc6110 function=tick_sched_timer expires=804264000000 softexpires=804264000000
 vslam_framewor-3236  [003] d.h1   804.202637: irq_handler_exit: irq=9 ret=handled
 vslam_framewor-3387  [000] d.h1   804.202637: irq_handler_exit: irq=6 ret=handled
 vslam_framewor-3163  [005] d.h1   804.202637: irq_handler_exit: irq=11 ret=handled
 vslam_framewor-3240  [004] d.h1   804.202637: irq_handler_exit: irq=10 ret=handled
 vslam_framewor-3237  [002] d.h1   804.202638: softirq_raise: vec=9 [action=RCU]
 vslam_framewor-3239  [001] d.h1   804.202638: softirq_raise: vec=9 [action=RCU]
 vslam_framewor-3240  [004] ..s1   804.202639: softirq_entry: vec=1 [action=TIMER]
 vslam_framewor-3236  [003] ..s1   804.202639: softirq_entry: vec=1 [action=TIMER]
 vslam_framewor-3163  [005] ..s1   804.202639: softirq_entry: vec=1 [action=TIMER]
 vslam_framewor-3387  [000] d.H1   804.202640: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3236  [003] d.s2   804.202641: timer_cancel: timer=ffffffc069fcba90
 vslam_framewor-3240  [004] d.s2   804.202641: timer_cancel: timer=ffffffc04acf3a90
 vslam_framewor-3163  [005] ..s1   804.202641: softirq_exit: vec=1 [action=TIMER]
 vslam_framewor-3237  [002] d.h2   804.202641: sched_stat_runtime: comm=vslam_framewor pid=3237 runtime=96224 [ns] vruntime=387807217574 [ns]
 vslam_framewor-3239  [001] d.h2   804.202641: sched_stat_runtime: comm=vslam_framewor pid=3239 runtime=3994048 [ns] vruntime=386879062598 [ns]
 vslam_framewor-3163  [005] ..s1   804.202641: softirq_entry: vec=9 [action=RCU]
 vslam_framewor-3236  [003] ..s1   804.202642: timer_expire_entry: timer=ffffffc069fcba90 function=process_timeout now=4295093361
 vslam_framewor-3240  [004] ..s1   804.202642: timer_expire_entry: timer=ffffffc04acf3a90 function=process_timeout now=4295093361
 vslam_framewor-3236  [003] d.s2   804.202643: sched_waking: comm=vslam_framewor pid=3223 prio=120 target_cpu=003
 vslam_framewor-3240  [004] d.s2   804.202643: sched_waking: comm=Capture Plane pid=11424 prio=120 target_cpu=004
 vslam_framewor-3163  [005] ..s1   804.202644: softirq_exit: vec=9 [action=RCU]
 vslam_framewor-3387  [000] d.H1   804.202644: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3387  [000] ..s1   804.202645: softirq_entry: vec=1 [action=TIMER]
 vslam_framewor-3387  [000] d.s2   804.202646: timer_cancel: timer=ffffffc1bed73a90
 vslam_framewor-3387  [000] ..s1   804.202646: timer_expire_entry: timer=ffffffc1bed73a90 function=process_timeout now=4295093361
 vslam_framewor-3240  [004] d.s3   804.202646: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=16768 [ns] vruntime=256520472676 [ns]
 vslam_framewor-3236  [003] d.s3   804.202646: sched_stat_runtime: comm=vslam_framewor pid=3236 runtime=16288 [ns] vruntime=255037001392 [ns]
 vslam_framewor-3387  [000] d.s2   804.202647: sched_waking: comm=vslam_framewor pid=3168 prio=120 target_cpu=000
 vslam_framewor-3237  [002] d.h1   804.202648: softirq_raise: vec=7 [action=SCHED]
 vslam_framewor-3387  [000] d.s3   804.202649: sched_stat_runtime: comm=vslam_framewor pid=3387 runtime=15840 [ns] vruntime=229268080136 [ns]
 vslam_framewor-3236  [003] d.s3   804.202649: sched_stat_sleep: comm=vslam_framewor pid=3223 delay=3966464 [ns]
 vslam_framewor-3240  [004] d.s3   804.202649: sched_stat_sleep: comm=Capture Plane pid=11424 delay=2471232 [ns]
 vslam_framewor-3387  [000] d.s3   804.202650: sched_stat_sleep: comm=vslam_framewor pid=3168 delay=2421024 [ns]
 vslam_framewor-3239  [001] d.h1   804.202650: hrtimer_expire_exit: hrtimer=ffffffc1f5bd7110
 vslam_framewor-3237  [002] d.h1   804.202650: hrtimer_expire_exit: hrtimer=ffffffc1f5be8110
 vslam_framewor-3237  [002] d.h2   804.202650: hrtimer_start: hrtimer=ffffffc1f5be8110 function=tick_sched_timer expires=804264000000 softexpires=804264000000
 vslam_framewor-3239  [001] d.h2   804.202650: hrtimer_start: hrtimer=ffffffc1f5bd7110 function=tick_sched_timer expires=804264000000 softexpires=804264000000
 vslam_framewor-3240  [004] dns3   804.202651: sched_wakeup: comm=Capture Plane pid=11424 prio=120 target_cpu=004
 vslam_framewor-3387  [000] dns3   804.202651: sched_wakeup: comm=vslam_framewor pid=3168 prio=120 target_cpu=000
 vslam_framewor-3236  [003] dns3   804.202651: sched_wakeup: comm=vslam_framewor pid=3223 prio=120 target_cpu=003
 vslam_framewor-3387  [000] .ns1   804.202652: timer_expire_exit: timer=ffffffc1bed73a90
 vslam_framewor-3240  [004] .ns1   804.202652: timer_expire_exit: timer=ffffffc04acf3a90
 vslam_framewor-3239  [001] d.h1   804.202652: irq_handler_exit: irq=7 ret=handled
 vslam_framewor-3237  [002] d.h1   804.202652: irq_handler_exit: irq=8 ret=handled
 vslam_framewor-3236  [003] .ns1   804.202652: timer_expire_exit: timer=ffffffc069fcba90
 vslam_framewor-3387  [000] .ns1   804.202653: softirq_exit: vec=1 [action=TIMER]
 vslam_framewor-3236  [003] .ns1   804.202653: softirq_exit: vec=1 [action=TIMER]
 vslam_framewor-3240  [004] dns2   804.202653: timer_cancel: timer=ffffffc1ecab7d30
 vslam_framewor-3387  [000] .ns1   804.202653: softirq_entry: vec=9 [action=RCU]
 vslam_framewor-3236  [003] .ns1   804.202653: softirq_entry: vec=9 [action=RCU]
 vslam_framewor-3240  [004] .ns1   804.202653: timer_expire_entry: timer=ffffffc1ecab7d30 function=process_timeout now=4295093361
 vslam_framewor-3240  [004] dns2   804.202653: sched_waking: comm=rcu_preempt pid=7 prio=120 target_cpu=004
 vslam_framewor-3236  [003] .ns1   804.202654: softirq_exit: vec=9 [action=RCU]
 vslam_framewor-3239  [001] ..s1   804.202654: softirq_entry: vec=1 [action=TIMER]
 vslam_framewor-3237  [002] ..s1   804.202654: softirq_entry: vec=1 [action=TIMER]
 vslam_framewor-3240  [004] dns3   804.202655: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=9088 [ns] vruntime=256520481764 [ns]
 vslam_framewor-3239  [001] ..s1   804.202655: softirq_exit: vec=1 [action=TIMER]
 vslam_framewor-3237  [002] ..s1   804.202655: softirq_exit: vec=1 [action=TIMER]
 vslam_framewor-3240  [004] dns3   804.202656: sched_stat_sleep: comm=rcu_preempt pid=7 delay=2556256 [ns]
 vslam_framewor-3239  [001] ..s1   804.202656: softirq_entry: vec=9 [action=RCU]
 vslam_framewor-3237  [002] ..s1   804.202656: softirq_entry: vec=7 [action=SCHED]
 vslam_framewor-3240  [004] dns3   804.202657: sched_wakeup: comm=rcu_preempt pid=7 prio=120 target_cpu=004
 vslam_framewor-3240  [004] .ns1   804.202657: timer_expire_exit: timer=ffffffc1ecab7d30
 vslam_framewor-3236  [003] dn.3   804.202657: sched_stat_wait: comm=vslam_framewor pid=3223 delay=0 [ns]
 vslam_framewor-3240  [004] .ns1   804.202657: softirq_exit: vec=1 [action=TIMER]
 vslam_framewor-3240  [004] .ns1   804.202658: softirq_entry: vec=9 [action=RCU]
 vslam_framewor-3236  [003] d..3   804.202659: sched_switch: prev_comm=vslam_framewor prev_pid=3236 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3223 next_prio=120
 vslam_framewor-3240  [004] .ns1   804.202660: softirq_exit: vec=9 [action=RCU]
 vslam_framewor-3237  [002] ..s1   804.202660: softirq_exit: vec=7 [action=SCHED]
 vslam_framewor-3237  [002] ..s1   804.202660: softirq_entry: vec=9 [action=RCU]
 vslam_framewor-3239  [001] ..s1   804.202660: softirq_exit: vec=9 [action=RCU]
 vslam_framewor-3240  [004] dn.3   804.202661: sched_stat_wait: comm=Capture Plane pid=11424 delay=9088 [ns]
 vslam_framewor-3237  [002] ..s1   804.202662: softirq_exit: vec=9 [action=RCU]
 vslam_framewor-3240  [004] d..3   804.202663: sched_switch: prev_comm=vslam_framewor prev_pid=3240 prev_prio=120 prev_state=R ==> next_comm=Capture Plane next_pid=11424 next_prio=120
 vslam_framewor-3387  [000] .ns1   804.202664: softirq_exit: vec=9 [action=RCU]
 vslam_framewor-3387  [000] dn.3   804.202665: sched_stat_wait: comm=vslam_framewor pid=3168 delay=0 [ns]
 vslam_framewor-3387  [000] d..3   804.202667: sched_switch: prev_comm=vslam_framewor prev_pid=3387 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3168 next_prio=120
 vslam_framewor-3223  [003] ...1   804.202676: timer_init: timer=ffffffc069fcba90
   Capture Plane-11424 [004] ...1   804.202676: timer_init: timer=ffffffc04acf3a90
   Capture Plane-11424 [004] d..2   804.202677: timer_start: timer=ffffffc04acf3a90 function=process_timeout expires=4295093362 [timeout=1] flags=0x00000004
 vslam_framewor-3223  [003] d..2   804.202677: timer_start: timer=ffffffc069fcba90 function=process_timeout expires=4295093362 [timeout=1] flags=0x00000003
 vslam_framewor-3168  [000] ...1   804.202678: timer_init: timer=ffffffc1bed73a90
 vslam_framewor-3223  [003] d..3   804.202678: sched_stat_runtime: comm=vslam_framewor pid=3223 runtime=32320 [ns] vruntime=255028033712 [ns]
   Capture Plane-11424 [004] d..3   804.202678: sched_stat_runtime: comm=Capture Plane pid=11424 runtime=23232 [ns] vruntime=256511495908 [ns]
 vslam_framewor-3168  [000] d..2   804.202680: timer_start: timer=ffffffc1bed73a90 function=process_timeout expires=4295093362 [timeout=1] flags=0x00000000
   Capture Plane-11424 [004] d..3   804.202680: sched_stat_wait: comm=rcu_preempt pid=7 delay=23232 [ns]
 vslam_framewor-3223  [003] d..3   804.202681: sched_stat_wait: comm=vslam_framewor pid=3236 delay=32320 [ns]
 vslam_framewor-3223  [003] d..3   804.202681: sched_switch: prev_comm=vslam_framewor prev_pid=3223 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3236 next_prio=120
 vslam_framewor-3168  [000] d..3   804.202681: sched_stat_runtime: comm=vslam_framewor pid=3168 runtime=32960 [ns] vruntime=229261991944 [ns]
   Capture Plane-11424 [004] d..3   804.202682: sched_switch: prev_comm=Capture Plane prev_pid=11424 prev_prio=120 prev_state=S ==> next_comm=rcu_preempt next_pid=7 next_prio=120
 vslam_framewor-3168  [000] d..3   804.202683: sched_stat_wait: comm=vslam_framewor pid=3387 delay=32960 [ns]
 vslam_framewor-3168  [000] d..3   804.202685: sched_switch: prev_comm=vslam_framewor prev_pid=3168 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3387 next_prio=120
     rcu_preempt-7     [004] ...1   804.202686: timer_init: timer=ffffffc1ecab7d30
     rcu_preempt-7     [004] d..2   804.202687: timer_start: timer=ffffffc1ecab7d30 function=process_timeout expires=4295093362 [timeout=1] flags=0x00000004
     rcu_preempt-7     [004] d..3   804.202687: sched_stat_runtime: comm=rcu_preempt pid=7 runtime=9216 [ns] vruntime=256511481892 [ns]
     rcu_preempt-7     [004] d..3   804.202689: sched_stat_wait: comm=vslam_framewor pid=3240 delay=32448 [ns]
     rcu_preempt-7     [004] d..3   804.202690: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3240 next_prio=120
 vslam_framewor-3387  [000] d.h1   804.202704: irq_handler_entry: irq=44 name=2490000.ether_qos.rx0
 vslam_framewor-3387  [000] d.h1   804.202713: softirq_raise: vec=3 [action=NET_RX]
 vslam_framewor-3387  [000] d.h1   804.202718: irq_handler_exit: irq=44

you can check this devtalk

applies for tx2 also

@bbasu The good news is lost irq interval is shorten. The bad news is lost irq is still there.

Here is the log snap short:
11740.082471->11740.162676 lost irq about 80ms.

vslam_framewor-4227  [001] d..3 11740.082459: sched_switch: prev_comm=vslam_framewor prev_pid=4227 prev_prio=120 prev_state=S ==> next_comm=swapper/1
          <idle>-0     [001] d..2 11740.082463: tick_stop: success=yes msg= 
          <idle>-0     [002] d..2 11740.082463: tick_stop: success=yes msg= 
          <idle>-0     [002] d..3 11740.082465: hrtimer_cancel: hrtimer=ffffffc1f5be8090
          <idle>-0     [001] d..3 11740.082465: hrtimer_cancel: hrtimer=ffffffc1f5bd7090
          <idle>-0     [001] d..3 11740.082468: hrtimer_start: hrtimer=ffffffc1f5bd7090 function=tick_sched_timer expires=11741804000000 softexpires=1
          <idle>-0     [002] d..3 11740.082468: hrtimer_start: hrtimer=ffffffc1f5be8090 function=tick_sched_timer expires=11741792000000 softexpires=1
          <idle>-0     [001] d..2 11740.082471: cpu_idle: state=1 cpu_id=1
          <idle>-0     [002] d..2 11740.082471: cpu_idle: state=1 cpu_id=2
     ksoftirqd/0-3     [000] d.H1 11740.162676: irq_handler_entry: irq=42 name=ether_qos.common_irq
          <idle>-0     [004] d.h2 11740.162680: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_framewor-3240  [003] d.h1 11740.162680: irq_handler_entry: irq=9 name=tegra186_timer3
 vslam_framewor-3220  [005] d.h1 11740.162680: irq_handler_entry: irq=11 name=tegra186_timer5
     ksoftirqd/0-3     [000] d.H1 11740.162680: irq_handler_exit: irq=42 ret=handled
          <idle>-0     [004] d.h3 11740.162682: hrtimer_cancel: hrtimer=ffffffc1f5c0a090
     ksoftirqd/0-3     [000] d.H1 11740.162682: irq_handler_entry: irq=6 name=tegra186_timer0
          <idle>-0     [004] d.h2 11740.162684: hrtimer_expire_entry: hrtimer=ffffffc1f5c0a090 function=tick_sched_timer now=11741000007888
     ksoftirqd/0-3     [000] d.H2 11740.162684: hrtimer_cancel: hrtimer=ffffffc1f5bc6090
 vslam_framewor-3240  [003] d.h2 11740.162684: hrtimer_cancel: hrtimer=ffffffc1f5bf9090

The whole log info is here:
cpu_idle is still shown from 11740.082471 (cpu_idle: state=1 cpu_id=1) to 11740.162742 ( cpu_idle: state=4294967295 cpu_id=1)

vslam_framewor-4227  [001] d..3 11740.082422: sched_stat_runtime: comm=vslam_framewor pid=4227 runtime=15136 [ns] vruntime=7107636090562 [ns]
 vslam_framewor-4227  [001] d..3 11740.082430: sched_stat_runtime: comm=vslam_framewor pid=4227 runtime=6880 [ns] vruntime=7107636097442 [ns]
 vslam_framewor-9468  [002] d..3 11740.082430: sched_stat_runtime: comm=vslam_framewor pid=9468 runtime=14496 [ns] vruntime=7035216376953 [ns]
 vslam_framewor-9468  [002] d..3 11740.082454: sched_switch: prev_comm=vslam_framewor prev_pid=9468 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
 vslam_framewor-4227  [001] d..3 11740.082459: sched_switch: prev_comm=vslam_framewor prev_pid=4227 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
          <idle>-0     [001] d..2 11740.082463: tick_stop: success=yes msg= 
          <idle>-0     [002] d..2 11740.082463: tick_stop: success=yes msg= 
          <idle>-0     [002] d..3 11740.082465: hrtimer_cancel: hrtimer=ffffffc1f5be8090
          <idle>-0     [001] d..3 11740.082465: hrtimer_cancel: hrtimer=ffffffc1f5bd7090
          <idle>-0     [001] d..3 11740.082468: hrtimer_start: hrtimer=ffffffc1f5bd7090 function=tick_sched_timer expires=11741804000000 softexpires=11741804000000
          <idle>-0     [002] d..3 11740.082468: hrtimer_start: hrtimer=ffffffc1f5be8090 function=tick_sched_timer expires=11741792000000 softexpires=11741792000000
          <idle>-0     [001] d..2 11740.082471: cpu_idle: state=1 cpu_id=1
          <idle>-0     [002] d..2 11740.082471: cpu_idle: state=1 cpu_id=2
     ksoftirqd/0-3     [000] d.H1 11740.162676: irq_handler_entry: irq=42 name=ether_qos.common_irq
          <idle>-0     [004] d.h2 11740.162680: irq_handler_entry: irq=10 name=tegra186_timer4
 vslam_framewor-3240  [003] d.h1 11740.162680: irq_handler_entry: irq=9 name=tegra186_timer3
 vslam_framewor-3220  [005] d.h1 11740.162680: irq_handler_entry: irq=11 name=tegra186_timer5
     ksoftirqd/0-3     [000] d.H1 11740.162680: irq_handler_exit: irq=42 ret=handled
          <idle>-0     [004] d.h3 11740.162682: hrtimer_cancel: hrtimer=ffffffc1f5c0a090
     ksoftirqd/0-3     [000] d.H1 11740.162682: irq_handler_entry: irq=6 name=tegra186_timer0
          <idle>-0     [004] d.h2 11740.162684: hrtimer_expire_entry: hrtimer=ffffffc1f5c0a090 function=tick_sched_timer now=11741000007888
     ksoftirqd/0-3     [000] d.H2 11740.162684: hrtimer_cancel: hrtimer=ffffffc1f5bc6090
 vslam_framewor-3240  [003] d.h2 11740.162684: hrtimer_cancel: hrtimer=ffffffc1f5bf9090
 vslam_framewor-3220  [005] d.h2 11740.162684: hrtimer_cancel: hrtimer=ffffffc1f5c1b090
     ksoftirqd/0-3     [000] d.H1 11740.162685: hrtimer_expire_entry: hrtimer=ffffffc1f5bc6090 function=tick_sched_timer now=11741000010416
 vslam_framewor-3240  [003] d.h1 11740.162686: hrtimer_expire_entry: hrtimer=ffffffc1f5bf9090 function=tick_sched_timer now=11741000010928
 vslam_framewor-3220  [005] d.h1 11740.162686: hrtimer_expire_entry: hrtimer=ffffffc1f5c1b090 function=tick_sched_timer now=11741000010960
          <idle>-0     [004] d.h2 11740.162686: softirq_raise: vec=1 [action=TIMER]
          <idle>-0     [004] d.h2 11740.162688: softirq_raise: vec=9 [action=RCU]
 vslam_framewor-3240  [003] d.h1 11740.162688: softirq_raise: vec=1 [action=TIMER]
 vslam_framewor-3220  [005] d.h1 11740.162688: softirq_raise: vec=1 [action=TIMER]
 vslam_framewor-3240  [003] d.h1 11740.162689: softirq_raise: vec=9 [action=RCU]
 vslam_framewor-3220  [005] d.h1 11740.162689: softirq_raise: vec=9 [action=RCU]
          <idle>-0     [004] d.h2 11740.162690: softirq_raise: vec=7 [action=SCHED]
     ksoftirqd/0-3     [000] d.H1 11740.162690: softirq_raise: vec=1 [action=TIMER]
 vslam_framewor-3220  [005] d.h2 11740.162690: sched_stat_runtime: comm=vslam_framewor pid=3220 runtime=80588672 [ns] vruntime=4943446172628 [ns]
 vslam_framewor-3240  [003] d.h2 11740.162691: sched_stat_runtime: comm=vslam_framewor pid=3240 runtime=82068192 [ns] vruntime=4968715100637 [ns]
     ksoftirqd/0-3     [000] d.H1 11740.162692: softirq_raise: vec=9 [action=RCU]
          <idle>-0     [004] d.h2 11740.162692: hrtimer_expire_exit: hrtimer=ffffffc1f5c0a090
          <idle>-0     [004] d.h3 11740.162693: hrtimer_start: hrtimer=ffffffc1f5c0a090 function=tick_sched_timer expires=11741004000000 softexpires=11741004000000
     ksoftirqd/0-3     [000] d.H2 11740.162693: sched_stat_runtime: comm=ksoftirqd/0 pid=3 runtime=83029600 [ns] vruntime=4837414796935 [ns]
          <idle>-0     [004] d.h3 11740.162694: hrtimer_cancel: hrtimer=ffffffc04c573e30
          <idle>-0     [002] d.h2 11740.162694: irq_handler_entry: irq=8 name=tegra186_timer2
          <idle>-0     [004] d.h2 11740.162694: hrtimer_expire_entry: hrtimer=ffffffc04c573e30 function=hrtimer_wakeup now=11741000007888
 vslam_framewor-3220  [005] d.h1 11740.162695: softirq_raise: vec=7 [action=SCHED]
          <idle>-0     [004] d.h3 11740.162696: sched_waking: comm=vslam_framewor pid=3384 prio=120 target_cpu=004
 vslam_framewor-3220  [005] d.h1 11740.162696: hrtimer_expire_exit: hrtimer=ffffffc1f5c1b090
          <idle>-0     [002] d.h3 11740.162696: hrtimer_cancel: hrtimer=ffffffc001431108
 vslam_framewor-3240  [003] d.h1 11740.162696: hrtimer_expire_exit: hrtimer=ffffffc1f5bf9090
 vslam_framewor-3220  [005] d.h2 11740.162696: hrtimer_start: hrtimer=ffffffc1f5c1b090 function=tick_sched_timer expires=11741004000000 softexpires=11741004000000
     ksoftirqd/0-3     [000] dnH1 11740.162696: softirq_raise: vec=7 [action=SCHED]
 vslam_framewor-3240  [003] d.h2 11740.162697: hrtimer_start: hrtimer=ffffffc1f5bf9090 function=tick_sched_timer expires=11741004000000 softexpires=11741004000000
 vslam_framewor-3220  [005] d.h2 11740.162697: hrtimer_cancel: hrtimer=ffffffc16693f890
     ksoftirqd/0-3     [000] dnH1 11740.162697: hrtimer_expire_exit: hrtimer=ffffffc1f5bc6090
 vslam_framewor-3240  [003] d.h2 11740.162697: hrtimer_cancel: hrtimer=ffffffbffcf66c10
 vslam_framewor-3220  [005] d.h1 11740.162697: hrtimer_expire_entry: hrtimer=ffffffc16693f890 function=hrtimer_wakeup now=11741000010960
     ksoftirqd/0-3     [000] dnH2 11740.162698: hrtimer_start: hrtimer=ffffffc1f5bc6090 function=tick_sched_timer expires=11741004000000 softexpires=11741004000000
          <idle>-0     [002] d.h2 11740.162698: hrtimer_expire_entry: hrtimer=ffffffc001431108 function=sched_rt_period_timer now=11741000022384
 vslam_framewor-3240  [003] d.h1 11740.162698: hrtimer_expire_entry: hrtimer=ffffffbffcf66c10 function=hrtimer_handler [ndc] now=11741000010928
 vslam_framewor-3220  [005] d.h2 11740.162698: sched_waking: comm=vslam_framewor pid=3385 prio=120 target_cpu=005
     ksoftirqd/0-3     [000] dnH1 11740.162699: irq_handler_exit: irq=6 ret=handled
     ksoftirqd/0-3     [000] dnH1 11740.162702: irq_handler_entry: irq=389 name=Tegra PCIe MSI
 vslam_framewor-3220  [005] d.h2 11740.162702: sched_migrate_task: comm=vslam_framewor pid=3385 prio=120 orig_cpu=5 dest_cpu=4
          <idle>-0     [001] d.h2 11740.162702: softirq_raise: vec=7 [action=SCHED]
          <idle>-0     [004] d.h4 11740.162703: sched_stat_sleep: comm=vslam_framewor pid=3384 delay=82054656 [ns]
          <idle>-0     [001] ..s2 11740.162704: softirq_entry: vec=7 [action=SCHED]
          <idle>-0     [004] dnh4 11740.162705: sched_wakeup: comm=vslam_framewor pid=3384 prio=120 target_cpu=004
          <idle>-0     [004] dnh2 11740.162706: hrtimer_expire_exit: hrtimer=ffffffc04c573e30
     ksoftirqd/0-3     [000] dnH1 11740.162706: irq_handler_entry: irq=452 name=ndc:7014
          <idle>-0     [004] dnh3 11740.162706: hrtimer_cancel: hrtimer=ffffffc16276be30
          <idle>-0     [004] dnh2 11740.162707: hrtimer_expire_entry: hrtimer=ffffffc16276be30 function=hrtimer_wakeup now=11741000007888
          <idle>-0     [002] d.h2 11740.162707: hrtimer_expire_exit: hrtimer=ffffffc001431108
 vslam_framewor-3220  [005] d.h3 11740.162707: sched_stat_sleep: comm=vslam_framewor pid=3385 delay=88175840 [ns]
          <idle>-0     [004] dnh3 11740.162707: sched_waking: comm=sleep pid=19084 prio=120 target_cpu=004
          <idle>-0     [002] d.h2 11740.162709: irq_handler_exit: irq=8 ret=handled
 vslam_framewor-3220  [005] d.h3 11740.162709: sched_wakeup: comm=vslam_framewor pid=3385 prio=120 target_cpu=004
 vslam_framewor-3220  [005] d.h1 11740.162710: hrtimer_expire_exit: hrtimer=ffffffc16693f890
 vslam_framewor-3220  [005] d.h2 11740.162710: hrtimer_cancel: hrtimer=ffffffc1e2c57e30
          <idle>-0     [004] dnh4 11740.162710: sched_stat_sleep: comm=sleep pid=19084 delay=249683392 [ns]
 vslam_framewor-3220  [005] d.h1 11740.162710: hrtimer_expire_entry: hrtimer=ffffffc1e2c57e30 function=hrtimer_wakeup now=11741000010960
          <idle>-0     [004] dnh4 11740.162711: sched_wakeup: comm=sleep pid=19084 prio=120 target_cpu=004
 vslam_framewor-3220  [005] d.h2 11740.162711: sched_waking: comm=vslam_framewor pid=3007 prio=120 target_cpu=005
          <idle>-0     [004] dnh2 11740.162711: hrtimer_expire_exit: hrtimer=ffffffc16276be30
          <idle>-0     [004] dnh2 11740.162712: irq_handler_exit: irq=10 ret=handled
 vslam_framewor-3220  [005] d.h3 11740.162713: sched_stat_runtime: comm=vslam_framewor pid=3220 runtime=22720 [ns] vruntime=4943446195348 [ns]
 vslam_framewor-3220  [005] d.h3 11740.162714: sched_stat_sleep: comm=vslam_framewor pid=3007 delay=126263328 [ns]
          <idle>-0     [002] d..3 11740.162714: hrtimer_cancel: hrtimer=ffffffc1f5be8090
          <idle>-0     [002] d..3 11740.162714: hrtimer_start: hrtimer=ffffffc1f5be8090 function=tick_sched_timer expires=11741792000000 softexpires=11741792000000
          <idle>-0     [004] .ns2 11740.162715: softirq_entry: vec=1 [action=TIMER]
 vslam_framewor-3220  [005] dnh3 11740.162715: sched_wakeup: comm=vslam_framewor pid=3007 prio=120 target_cpu=005
 vslam_framewor-3220  [005] dnh1 11740.162715: hrtimer_expire_exit: hrtimer=ffffffc1e2c57e30
 vslam_framewor-3220  [005] dnh1 11740.162716: irq_handler_exit: irq=11 ret=handled
          <idle>-0     [002] ...2 11740.162716: cpu_idle: state=4294967295 cpu_id=2
          <idle>-0     [004] dns3 11740.162716: timer_cancel: timer=ffffffc0e15f3a90
 vslam_framewor-3220  [005] .ns1 11740.162717: softirq_entry: vec=1 [action=TIMER]
          <idle>-0     [004] .ns2 11740.162718: timer_expire_entry: timer=ffffffc0e15f3a90 function=process_timeout now=4297827546
          <idle>-0     [004] dns3 11740.162718: sched_waking: comm=Capture Plane pid=24100 prio=120 target_cpu=004
 vslam_framewor-3220  [005] dns2 11740.162719: timer_cancel: timer=ffffffc1ebf30b90
          <idle>-0     [002] d..2 11740.162719: cpu_idle: state=1 cpu_id=2
 vslam_framewor-3220  [005] dns1 11740.162719: timer_expire_entry: timer=ffffffc1ebf30b90 function=delayed_work_timer_fn now=4297827546
     ksoftirqd/0-3     [000] dnH2 11740.162720: softirq_raise: vec=6 [action=TASKLET]
          <idle>-0     [004] dns4 11740.162720: sched_stat_sleep: comm=Capture Plane pid=24100 delay=83039872 [ns]
          <idle>-0     [004] dns4 11740.162721: sched_wakeup: comm=Capture Plane pid=24100 prio=120 target_cpu=004
 vslam_framewor-3220  [005] dns3 11740.162721: sched_waking: comm=kworker/u12:3 pid=7059 prio=120 target_cpu=004
          <idle>-0     [004] .ns2 11740.162722: timer_expire_exit: timer=ffffffc0e15f3a90
          <idle>-0     [004] dns3 11740.162722: timer_cancel: timer=ffffffc1cf7e3a90
          <idle>-0     [004] .ns2 11740.162723: timer_expire_entry: timer=ffffffc1cf7e3a90 function=process_timeout now=4297827546
 vslam_framewor-3220  [005] dns4 11740.162724: sched_stat_sleep: comm=kworker/u12:3 pid=7059 delay=82186464 [ns]
          <idle>-0     [004] dns3 11740.162724: sched_waking: comm=vslam_framewor pid=3167 prio=120 target_cpu=004
 vslam_framewor-3220  [005] dns4 11740.162724: sched_wakeup: comm=kworker/u12:3 pid=7059 prio=120 target_cpu=004
          <idle>-0     [001] d.s3 11740.162725: sched_stat_runtime: comm=ksoftirqd/0 pid=3 runtime=32384 [ns] vruntime=4837414829319 [ns]
 vslam_framewor-3220  [005] dns1 11740.162725: timer_expire_exit: timer=ffffffc1ebf30b90
          <idle>-0     [004] dns4 11740.162726: sched_stat_sleep: comm=vslam_framewor pid=3167 delay=83065280 [ns]
 vslam_framewor-3220  [005] .ns1 11740.162726: softirq_exit: vec=1 [action=TIMER]
 vslam_framewor-3220  [005] .ns1 11740.162726: softirq_entry: vec=7 [action=SCHED]
          <idle>-0     [004] dns4 11740.162726: sched_wakeup: comm=vslam_framewor pid=3167 prio=120 target_cpu=004
 vslam_framewor-3240  [003] d.h1 11740.162727: hrtimer_expire_exit: hrtimer=ffffffbffcf66c10
 vslam_framewor-3240  [003] d.h2 11740.162727: hrtimer_start: hrtimer=ffffffbffcf66c10 function=hrtimer_handler [ndc] expires=11741003939978 softexpires=11741003939978
          <idle>-0     [004] .ns2 11740.162727: timer_expire_exit: timer=ffffffc1cf7e3a90
          <idle>-0     [004] dns3 11740.162727: timer_cancel: timer=ffffffc04b6b7a90
 vslam_framewor-3240  [003] d.h1 11740.162727: irq_handler_exit: irq=9 ret=handled
          <idle>-0     [004] .ns2 11740.162728: timer_expire_entry: timer=ffffffc04b6b7a90 function=process_timeout now=4297827546
          <idle>-0     [004] dns3 11740.162729: sched_waking: comm=Capture Plane pid=24467 prio=120 target_cpu=004
 vslam_framewor-3240  [003] ..s1 11740.162729: softirq_entry: vec=1 [action=TIMER]
 vslam_framewor-3220  [005] .ns1 11740.162729: softirq_exit: vec=7 [action=SCHED]
          <idle>-0     [001] d.s3 11740.162729: sched_stat_wait: comm=vslam_framewor pid=9467 delay=83161120 [ns]
 vslam_framewor-3220  [005] .ns1 11740.162729: softirq_entry: vec=9 [action=RCU]
 vslam_framewor-3240  [003] d.s2 11740.162730: timer_cancel: timer=ffffffc076cf4798
          <idle>-0     [004] dns4 11740.162730: sched_stat_sleep: comm=Capture Plane pid=24467 delay=83090272 [ns]
 vslam_framewor-3240  [003] ..s1 11740.162730: timer_expire_entry: timer=ffffffc076cf4798 function=tcp_delack_timer now=4297827546
          <idle>-0     [004] dns4 11740.162731: sched_wakeup: comm=Capture Plane pid=24467 prio=120 target_cpu=004
          <idle>-0     [004] .ns2 11740.162731: timer_expire_exit: timer=ffffffc04b6b7a90
          <idle>-0     [004] dns3 11740.162732: timer_cancel: timer=ffffffc1ecab7d30
 vslam_framewor-3240  [003] ..s1 11740.162732: timer_expire_exit: timer=ffffffc076cf4798
          <idle>-0     [004] .ns2 11740.162732: timer_expire_entry: timer=ffffffc1ecab7d30 function=process_timeout now=4297827546
 vslam_framewor-3220  [005] .ns1 11740.162732: softirq_exit: vec=9 [action=RCU]
          <idle>-0     [004] dns3 11740.162732: sched_waking: comm=rcu_preempt pid=7 prio=120 target_cpu=004
          <idle>-0     [001] d.s3 11740.162732: sched_migrate_task: comm=vslam_framewor pid=9467 prio=120 orig_cpu=0 dest_cpu=1
 vslam_framewor-3240  [003] ..s1 11740.162733: softirq_exit: vec=1 [action=TIMER]
 vslam_framewor-3240  [003] ..s1 11740.162733: softirq_entry: vec=9 [action=RCU]
 vslam_framewor-3220  [005] dn.3 11740.162734: sched_stat_runtime: comm=vslam_framewor pid=3220 runtime=15040 [ns] vruntime=4943446210388 [ns]
 vslam_framewor-3240  [003] ..s1 11740.162734: softirq_exit: vec=9 [action=RCU]
          <idle>-0     [004] dns4 11740.162734: sched_stat_sleep: comm=rcu_preempt pid=7 delay=83137024 [ns]
          <idle>-0     [004] dns4 11740.162735: sched_wakeup: comm=rcu_preempt pid=7 prio=120 target_cpu=004
          <idle>-0     [004] .ns2 11740.162735: timer_expire_exit: timer=ffffffc1ecab7d30
 vslam_framewor-3220  [005] dn.3 11740.162736: sched_stat_wait: comm=vslam_framewor pid=3007 delay=15040 [ns]
          <idle>-0     [004] .ns2 11740.162736: softirq_exit: vec=1 [action=TIMER]
     ksoftirqd/0-3     [000] dnH2 11740.162737: softirq_raise: vec=6 [action=TASKLET]
          <idle>-0     [004] .ns2 11740.162737: softirq_entry: vec=7 [action=SCHED]
 vslam_framewor-3220  [005] d..3 11740.162738: sched_switch: prev_comm=vslam_framewor prev_pid=3220 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3007 next_prio=120
          <idle>-0     [001] .ns2 11740.162740: softirq_exit: vec=7 [action=SCHED]
          <idle>-0     [001] .n.2 11740.162742: cpu_idle: state=4294967295 cpu_id=1
          <idle>-0     [004] .ns2 11740.162743: softirq_exit: vec=7 [action=SCHED]
          <idle>-0     [004] .ns2 11740.162744: softirq_entry: vec=9 [action=RCU]
          <idle>-0     [001] dn.3 11740.162744: hrtimer_cancel: hrtimer=ffffffc1f5bd7090
          <idle>-0     [004] .ns2 11740.162746: softirq_exit: vec=9 [action=RCU]
          <idle>-0     [001] dn.3 11740.162746: hrtimer_start: hrtimer=ffffffc1f5bd7090 function=tick_sched_timer expires=11741004000000 softexpires=11741004000000
     ksoftirqd/0-3     [000] dnH2 11740.162746: softirq_raise: vec=6 [action=TASKLET]
          <idle>-0     [004] .n.2 11740.162747: cpu_idle: state=4294967295 cpu_id=4
          <idle>-0     [001] dn.3 11740.162749: sched_stat_wait: comm=vslam_framewor pid=9467 delay=0 [ns]
          <idle>-0     [004] dn.3 11740.162750: sched_stat_wait: comm=vslam_framewor pid=3385 delay=30880 [ns]
          <idle>-0     [001] d..3 11740.162750: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=9467 next_prio=120
          <idle>-0     [004] d..3 11740.162751: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3385 next_prio=120
     ksoftirqd/0-3     [000] dnH1 11740.162777: irq_handler_exit: irq=452 ret=handled
     ksoftirqd/0-3     [000] dnH1 11740.162785: irq_handler_exit: irq=389 ret=handled
     ksoftirqd/0-3     [000] dnH1 11740.162787: irq_handler_entry: irq=53 name=d230000.actmon
     ksoftirqd/0-3     [000] dnH1 11740.162798: irq_handler_exit: irq=53 ret=handled
     ksoftirqd/0-3     [000] dnH2 11740.162799: sched_waking: comm=irq/53-d230000. pid=185 prio=49 target_cpu=000
 vslam_framewor-3007  [005] ...1 11740.162803: hrtimer_init: hrtimer=ffffffc1e2c57890 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_ABS
     ksoftirqd/0-3     [000] dnH5 11740.162803: hrtimer_start: hrtimer=ffffffc001431108 function=sched_rt_period_timer expires=11742000000000 softexpires=11742000000000
 vslam_framewor-3007  [005] d..2 11740.162805: hrtimer_start: hrtimer=ffffffc1e2c57890 function=hrtimer_wakeup expires=11741020177729 softexpires=11741020127729
     ksoftirqd/0-3     [000] dnH3 11740.162806: sched_wakeup: comm=irq/53-d230000. pid=185 prio=49 target_cpu=000
 vslam_framewor-3007  [005] d..3 11740.162807: sched_stat_runtime: comm=vslam_framewor pid=3007 runtime=78624 [ns] vruntime=4943437273972 [ns]
 vslam_framewor-3007  [005] d..3 11740.162811: sched_stat_wait: comm=vslam_framewor pid=3220 delay=78624 [ns]
     ksoftirqd/0-3     [000] dnH1 11740.162812: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3007  [005] d..3 11740.162813: sched_switch: prev_comm=vslam_framewor prev_pid=3007 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3220 next_prio=120
     ksoftirqd/0-3     [000] dnH1 11740.162816: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3385  [004] d.s4 11740.162820: timer_cancel: timer=ffffffc1eca938b0
 vslam_framewor-3385  [004] d.s4 11740.162821: timer_start: timer=ffffffc1eca938b0 function=eqos_eee_ctrl_timer expires=4297827796 [timeout=250] flags=0x00000004
 vslam_framewor-9467  [001] d..2 11740.162825: sched_waking: comm=vslam_framewor pid=3241 prio=120 target_cpu=001
 vslam_framewor-9467  [001] d..2 11740.162830: sched_migrate_task: comm=vslam_framewor pid=3241 prio=120 orig_cpu=1 dest_cpu=2
 vslam_framewor-3385  [004] ...1 11740.162834: hrtimer_init: hrtimer=ffffffc16693f890 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_ABS
 vslam_framewor-9467  [001] d..3 11740.162834: sched_stat_sleep: comm=vslam_framewor pid=3241 delay=89242048 [ns]
 vslam_framewor-3385  [004] d..2 11740.162835: hrtimer_start: hrtimer=ffffffc16693f890 function=hrtimer_wakeup expires=11741020209665 softexpires=11741020159665
 vslam_framewor-3385  [004] d..3 11740.162836: sched_stat_runtime: comm=vslam_framewor pid=3385 runtime=98752 [ns] vruntime=4886834496725 [ns]
 vslam_framewor-9467  [001] d..3 11740.162838: sched_wakeup: comm=vslam_framewor pid=3241 prio=120 target_cpu=002
 vslam_framewor-3385  [004] d..3 11740.162838: sched_stat_wait: comm=sleep pid=19084 delay=126656 [ns]
 vslam_framewor-3385  [004] d..3 11740.162839: sched_switch: prev_comm=vslam_framewor prev_pid=3385 prev_prio=120 prev_state=S ==> next_comm=sleep next_pid=19084 next_prio=120
          <idle>-0     [002] .n.2 11740.162840: cpu_idle: state=4294967295 cpu_id=2
          <idle>-0     [002] dn.3 11740.162841: hrtimer_cancel: hrtimer=ffffffc1f5be8090
          <idle>-0     [002] dn.3 11740.162842: hrtimer_start: hrtimer=ffffffc1f5be8090 function=tick_sched_timer expires=11741004000000 softexpires=11741004000000
          <idle>-0     [002] dn.3 11740.162844: sched_stat_wait: comm=vslam_framewor pid=3241 delay=0 [ns]
          <idle>-0     [002] d..3 11740.162846: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=vslam_framewor next_pid=3241 next_prio=120
 vslam_framewor-3241  [002] d..3 11740.162883: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=49280 [ns] vruntime=7035216426233 [ns]
 vslam_framewor-3241  [002] d..3 11740.162892: sched_stat_runtime: comm=sleep pid=19084 runtime=56000 [ns] vruntime=4886834453973 [ns]
 vslam_framewor-3241  [002] d..3 11740.162894: sched_stat_wait: comm=rcu_preempt pid=7 delay=158400 [ns]
 vslam_framewor-3241  [002] d..3 11740.162895: sched_migrate_task: comm=rcu_preempt pid=7 prio=120 orig_cpu=4 dest_cpu=2
 vslam_framewor-3241  [002] d..3 11740.162896: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=13376 [ns] vruntime=7035216439609 [ns]
 vslam_framewor-3241  [002] dn.3 11740.162899: sched_stat_wait: comm=rcu_preempt pid=7 delay=0 [ns]
 vslam_framewor-3241  [002] d..3 11740.162900: sched_switch: prev_comm=vslam_framewor prev_pid=3241 prev_prio=120 prev_state=S ==> next_comm=rcu_preempt next_pid=7 next_prio=120
     rcu_preempt-7     [002] ...1 11740.162909: timer_init: timer=ffffffc1ecab7d30
     rcu_preempt-7     [002] d..2 11740.162910: timer_start: timer=ffffffc1ecab7d30 function=process_timeout expires=4297827547 [timeout=1] flags=0x00000002
     rcu_preempt-7     [002] d..3 11740.162911: sched_stat_runtime: comm=rcu_preempt pid=7 runtime=15456 [ns] vruntime=7035207469529 [ns]
     rcu_preempt-7     [002] d..3 11740.162916: sched_stat_runtime: comm=sleep pid=19084 runtime=24032 [ns] vruntime=4886834478005 [ns]
     rcu_preempt-7     [002] d..3 11740.162918: sched_stat_wait: comm=Capture Plane pid=24467 delay=186464 [ns]
     rcu_preempt-7     [002] d..3 11740.162920: sched_migrate_task: comm=Capture Plane pid=24467 prio=120 orig_cpu=4 dest_cpu=2
     rcu_preempt-7     [002] d..3 11740.162921: sched_stat_runtime: comm=rcu_preempt pid=7 runtime=9536 [ns] vruntime=7035207479065 [ns]
     rcu_preempt-7     [002] d..3 11740.162921: sched_stat_wait: comm=Capture Plane pid=24467 delay=0 [ns]
     rcu_preempt-7     [002] d..3 11740.162922: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=Capture Plane next_pid=24467 next_prio=120
   Capture Plane-24467 [002] ...1 11740.162946: timer_init: timer=ffffffc04b6b7a90
   Capture Plane-24467 [002] d..2 11740.162947: timer_start: timer=ffffffc04b6b7a90 function=process_timeout expires=4297827547 [timeout=1] flags=0x00000002
   Capture Plane-24467 [002] d..3 11740.162948: sched_stat_runtime: comm=Capture Plane pid=24467 runtime=27200 [ns] vruntime=7035207503417 [ns]
   Capture Plane-24467 [002] d..3 11740.162952: sched_stat_runtime: comm=sleep pid=19084 runtime=35936 [ns] vruntime=4886834513941 [ns]
   Capture Plane-24467 [002] d..3 11740.162955: sched_stat_wait: comm=vslam_framewor pid=3167 delay=226944 [ns]
   Capture Plane-24467 [002] d..3 11740.162956: sched_migrate_task: comm=vslam_framewor pid=3167 prio=120 orig_cpu=4 dest_cpu=2
   Capture Plane-24467 [002] d..3 11740.162957: sched_stat_runtime: comm=Capture Plane pid=24467 runtime=9280 [ns] vruntime=7035207512697 [ns]
   Capture Plane-24467 [002] d..3 11740.162958: sched_stat_wait: comm=vslam_framewor pid=3167 delay=0 [ns]
   Capture Plane-24467 [002] d..3 11740.162959: sched_switch: prev_comm=Capture Plane prev_pid=24467 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3167 next_prio=120
 vslam_framewor-3167  [002] ...1 11740.162979: timer_init: timer=ffffffc1cf7e3a90
 vslam_framewor-3167  [002] d..2 11740.162980: timer_start: timer=ffffffc1cf7e3a90 function=process_timeout expires=4297827547 [timeout=1] flags=0x00000002
 vslam_framewor-3167  [002] d..3 11740.162984: sched_stat_runtime: comm=vslam_framewor pid=3167 runtime=25504 [ns] vruntime=7035207484825 [ns]
 vslam_framewor-3167  [002] d..3 11740.162988: sched_stat_runtime: comm=sleep pid=19084 runtime=35968 [ns] vruntime=4886834549909 [ns]
 vslam_framewor-3167  [002] d..3 11740.162989: sched_stat_wait: comm=kworker/u12:3 pid=7059 delay=265056 [ns]
 vslam_framewor-3167  [002] d..3 11740.162990: sched_migrate_task: comm=kworker/u12:3 pid=7059 prio=120 orig_cpu=4 dest_cpu=2
 vslam_framewor-3167  [002] d..3 11740.162991: sched_stat_runtime: comm=vslam_framewor pid=3167 runtime=8128 [ns] vruntime=7035207492953 [ns]
 vslam_framewor-3167  [002] d..3 11740.162993: sched_stat_wait: comm=kworker/u12:3 pid=7059 delay=0 [ns]
 vslam_framewor-3167  [002] d..3 11740.162994: sched_switch: prev_comm=vslam_framewor prev_pid=3167 prev_prio=120 prev_state=S ==> next_comm=kworker/u12:3 next_pid=7059 next_prio=120
           sleep-19084 [004] ...1 11740.163004: sched_process_exit: comm=sleep pid=19084 prio=120
   kworker/u12:3-7059  [002] d..2 11740.163012: timer_start: timer=ffffffc1ebf30b90 function=delayed_work_timer_fn expires=4297827553 [timeout=7] flags=0x00300005
   kworker/u12:3-7059  [002] d..3 11740.163015: sched_stat_runtime: comm=kworker/u12:3 pid=7059 runtime=23808 [ns] vruntime=7035207608249 [ns]
   kworker/u12:3-7059  [002] d..3 11740.163019: sched_stat_runtime: comm=sleep pid=19084 runtime=30752 [ns] vruntime=4886834580661 [ns]
     ksoftirqd/0-3     [000] dnH1 11740.163020: irq_handler_entry: irq=42 name=ether_qos.common_irq
   kworker/u12:3-7059  [002] d..3 11740.163020: sched_stat_wait: comm=Capture Plane pid=24100 delay=299008 [ns]
   kworker/u12:3-7059  [002] d..3 11740.163021: sched_migrate_task: comm=Capture Plane pid=24100 prio=120 orig_cpu=4 dest_cpu=2
   kworker/u12:3-7059  [002] d..3 11740.163021: sched_stat_runtime: comm=kworker/u12:3 pid=7059 runtime=6720 [ns] vruntime=7035207614969 [ns]
   kworker/u12:3-7059  [002] d..3 11740.163022: sched_stat_wait: comm=Capture Plane pid=24100 delay=0 [ns]
   kworker/u12:3-7059  [002] d..3 11740.163023: sched_switch: prev_comm=kworker/u12:3 prev_pid=7059 prev_prio=120 prev_state=S ==> next_comm=Capture Plane next_pid=24100 next_prio=120
     ksoftirqd/0-3     [000] dnH1 11740.163024: irq_handler_exit: irq=42 ret=handled
           sleep-19084 [004] d..5 11740.163026: sched_waking: comm=log_camera.sh pid=2013 prio=120 target_cpu=000
           sleep-19084 [004] d..6 11740.163029: sched_stat_runtime: comm=ksoftirqd/0 pid=3 runtime=303744 [ns] vruntime=4837415133063 [ns]
           sleep-19084 [004] d..6 11740.163032: sched_stat_sleep: comm=log_camera.sh pid=2013 delay=254836448 [ns]
           sleep-19084 [004] d..6 11740.163033: sched_wakeup: comm=log_camera.sh pid=2013 prio=120 target_cpu=000
   Capture Plane-24100 [002] ...1 11740.163034: timer_init: timer=ffffffc0e15f3a90
   Capture Plane-24100 [002] d..2 11740.163035: timer_start: timer=ffffffc0e15f3a90 function=process_timeout expires=4297827547 [timeout=1] flags=0x00000002
   Capture Plane-24100 [002] d..3 11740.163036: sched_stat_runtime: comm=Capture Plane pid=24100 runtime=14368 [ns] vruntime=7035207468185 [ns]
           sleep-19084 [004] d..3 11740.163037: sched_stat_runtime: comm=sleep pid=19084 runtime=17728 [ns] vruntime=4886834598389 [ns]
           sleep-19084 [004] d..3 11740.163040: sched_stat_wait: comm=vslam_framewor pid=3384 delay=338112 [ns]
   Capture Plane-24100 [002] d..3 11740.163040: sched_stat_runtime: comm=ksoftirqd/0 pid=3 runtime=11520 [ns] vruntime=4837415144583 [ns]
   Capture Plane-24100 [002] d..3 11740.163041: sched_stat_wait: comm=log_camera.sh pid=2013 delay=11520 [ns]
           sleep-19084 [004] d..3 11740.163042: sched_switch: prev_comm=sleep prev_pid=19084 prev_prio=120 prev_state=x ==> next_comm=vslam_framewor next_pid=3384 next_prio=120
   Capture Plane-24100 [002] d..3 11740.163042: sched_migrate_task: comm=log_camera.sh pid=2013 prio=120 orig_cpu=0 dest_cpu=2
   Capture Plane-24100 [002] d..3 11740.163043: sched_stat_runtime: comm=Capture Plane pid=24100 runtime=7264 [ns] vruntime=7035207475449 [ns]
   Capture Plane-24100 [002] d..3 11740.163045: sched_stat_wait: comm=log_camera.sh pid=2013 delay=0 [ns]
   Capture Plane-24100 [002] d..3 11740.163045: sched_switch: prev_comm=Capture Plane prev_pid=24100 prev_prio=120 prev_state=S ==> next_comm=log_camera.sh next_pid=2013 next_prio=120
 vslam_framewor-9467  [001] d..2 11740.163066: sched_waking: comm=vslam_framewor pid=3241 prio=120 target_cpu=002
 vslam_framewor-9467  [001] d..2 11740.163071: sched_migrate_task: comm=vslam_framewor pid=3241 prio=120 orig_cpu=2 dest_cpu=4
 vslam_framewor-3384  [004] d.h2 11740.163074: sched_stat_runtime: comm=vslam_framewor pid=3384 runtime=37440 [ns] vruntime=4886834513525 [ns]
 vslam_framewor-3384  [004] d.h2 11740.163076: sched_stat_sleep: comm=vslam_framewor pid=3241 delay=191616 [ns]
 vslam_framewor-3384  [004] d.h2 11740.163077: sched_wakeup: comm=vslam_framewor pid=3241 prio=120 target_cpu=004
 vslam_framewor-3384  [004] d..3 11740.163080: hrtimer_start: hrtimer=ffffffc1e2c62088 function=it_real_fn expires=11741100406354 softexpires=11741100406354
 vslam_framewor-3384  [004] d..2 11740.163081: itimer_state: which=0 expires=0 it_value=0.100000 it_interval=0.100000
 vslam_framewor-3384  [004] d..3 11740.163086: hrtimer_cancel: hrtimer=ffffffc1e2c62088
 vslam_framewor-3384  [004] d..2 11740.163087: itimer_state: which=0 expires=0 it_value=0.0 it_interval=0.0
 vslam_framewor-3384  [004] d..2 11740.163088: itimer_state: which=0 expires=0 it_value=0.0 it_interval=0.0
 vslam_framewor-3384  [004] ...1 11740.163097: hrtimer_init: hrtimer=ffffffc04c573e30 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_REL
 vslam_framewor-3384  [004] d..2 11740.163098: hrtimer_start: hrtimer=ffffffc04c573e30 function=hrtimer_wakeup expires=11741030475490 softexpires=11741030425490
 vslam_framewor-3384  [004] d..3 11740.163100: sched_stat_runtime: comm=vslam_framewor pid=3384 runtime=25632 [ns] vruntime=4886834539157 [ns]
 vslam_framewor-3384  [004] d..3 11740.163101: sched_stat_wait: comm=vslam_framewor pid=3241 delay=25632 [ns]
 vslam_framewor-3384  [004] d..3 11740.163102: sched_switch: prev_comm=vslam_framewor prev_pid=3384 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3241 next_prio=120
 vslam_framewor-9467  [001] d..3 11740.163111: sched_stat_runtime: comm=vslam_framewor pid=9467 runtime=374528 [ns] vruntime=7107639266754 [ns]
 vslam_framewor-9467  [001] d..3 11740.163117: sched_switch: prev_comm=vslam_framewor prev_pid=9467 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
          <idle>-0     [001] d..2 11740.163120: tick_stop: success=yes msg= 
          <idle>-0     [001] d..3 11740.163120: hrtimer_cancel: hrtimer=ffffffc1f5bd7090
          <idle>-0     [001] d..3 11740.163122: hrtimer_start: hrtimer=ffffffc1f5bd7090 function=tick_sched_timer expires=11741804000000 softexpires=11741804000000
          <idle>-0     [001] d..2 11740.163123: cpu_idle: state=1 cpu_id=1
     ksoftirqd/0-3     [000] dnH1 11740.163154: irq_handler_entry: irq=42 name=ether_qos.common_irq
     ksoftirqd/0-3     [000] dnH1 11740.163159: irq_handler_exit: irq=42 ret=handled
   log_camera.sh-2013  [002] ...1 11740.163179: sched_process_wait: comm=log_camera.sh pid=0 prio=120
   log_camera.sh-2013  [002] ...2 11740.163393: hrtimer_init: hrtimer=ffffffc1ea570f48 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_REL
   log_camera.sh-2013  [002] d..4 11740.163395: sched_stat_runtime: comm=log_camera.sh pid=2013 runtime=351616 [ns] vruntime=7035207791225 [ns]
   log_camera.sh-2013  [002] ...1 11740.163407: hrtimer_init: hrtimer=ffffffc04b611c88 clockid=CLOCK_MONOTONIC mode=HRTIMER_MODE_REL
   log_camera.sh-2013  [002] ...1 11740.163515: sched_process_fork: comm=log_camera.sh pid=2013 child_comm=log_camera.sh child_pid=19085
   log_camera.sh-2013  [002] d..3 11740.163521: sched_stat_runtime: comm=log_camera.sh pid=2013 runtime=125952 [ns] vruntime=7035207917177 [ns]
   log_camera.sh-2013  [002] d..3 11740.163525: sched_wakeup_new: comm=log_camera.sh pid=19085 prio=120 target_cpu=002
 vslam_framewor-3241  [004] d..2 11740.164134: sched_waking: comm=vslam_framewor pid=9467 prio=120 target_cpu=001
 vslam_framewor-3241  [004] d..2 11740.164138: sched_migrate_task: comm=vslam_framewor pid=9467 prio=120 orig_cpu=1 dest_cpu=4
     ksoftirqd/0-3     [000] dnH1 11740.164140: irq_handler_entry: irq=42 name=ether_qos.common_irq
 vslam_framewor-3241  [004] d..3 11740.164141: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=1040480 [ns] vruntime=4886844438453 [ns]
 vslam_framewor-3241  [004] d..3 11740.164144: sched_stat_sleep: comm=vslam_framewor pid=9467 delay=1030656 [ns]
     ksoftirqd/0-3     [000] dnH1 11740.164145: irq_handler_exit: irq=42 ret=handled
 vslam_framewor-3241  [004] d..3 11740.164146: sched_wakeup: comm=vslam_framewor pid=9467 prio=120 target_cpu=004
 vslam_framewor-3241  [004] d..3 11740.164195: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=54240 [ns] vruntime=4886844492693 [ns]
 vslam_framewor-3241  [004] d..3 11740.164199: sched_stat_wait: comm=vslam_framewor pid=9467 delay=54240 [ns]
 vslam_framewor-3241  [004] d..3 11740.164201: sched_switch: prev_comm=vslam_framewor prev_pid=3241 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=9467 next_prio=120
 vslam_framewor-9467  [004] d..2 11740.164231: sched_waking: comm=vslam_framewor pid=3241 prio=120 target_cpu=004
 vslam_framewor-9467  [004] d..3 11740.164233: sched_stat_runtime: comm=vslam_framewor pid=9467 runtime=38944 [ns] vruntime=4886843436917 [ns]
 vslam_framewor-9467  [004] d..3 11740.164235: sched_stat_sleep: comm=vslam_framewor pid=3241 delay=38944 [ns]
 vslam_framewor-9467  [004] d..3 11740.164236: sched_wakeup: comm=vslam_framewor pid=3241 prio=120 target_cpu=004
 vslam_framewor-9467  [004] d..3 11740.164250: sched_stat_runtime: comm=vslam_framewor pid=9467 runtime=16512 [ns] vruntime=4886843453429 [ns]
 vslam_framewor-9467  [004] d..3 11740.164252: sched_stat_wait: comm=vslam_framewor pid=3241 delay=16512 [ns]
 vslam_framewor-9467  [004] d..3 11740.164253: sched_switch: prev_comm=vslam_framewor prev_pid=9467 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3241 next_prio=120
 vslam_framewor-3241  [004] d..2 11740.164275: sched_waking: comm=vslam_framewor pid=9467 prio=120 target_cpu=004
 vslam_framewor-3241  [004] d..3 11740.164276: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=26336 [ns] vruntime=4886844519029 [ns]
 vslam_framewor-3241  [004] d..3 11740.164278: sched_stat_sleep: comm=vslam_framewor pid=9467 delay=26336 [ns]
 vslam_framewor-3241  [004] d..3 11740.164278: sched_wakeup: comm=vslam_framewor pid=9467 prio=120 target_cpu=004
 vslam_framewor-3241  [004] d..3 11740.164289: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=13312 [ns] vruntime=4886844532341 [ns]
 vslam_framewor-3241  [004] d..3 11740.164291: sched_stat_wait: comm=vslam_framewor pid=9467 delay=13312 [ns]
 vslam_framewor-3241  [004] d..3 11740.164292: sched_switch: prev_comm=vslam_framewor prev_pid=3241 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=9467 next_prio=120
 vslam_framewor-9467  [004] d..2 11740.164326: sched_waking: comm=vslam_framewor pid=3241 prio=120 target_cpu=004
 vslam_framewor-9467  [004] d..3 11740.164327: sched_stat_runtime: comm=vslam_framewor pid=9467 runtime=37856 [ns] vruntime=4886843491285 [ns]
 vslam_framewor-9467  [004] d..3 11740.164328: sched_stat_sleep: comm=vslam_framewor pid=3241 delay=37856 [ns]
 vslam_framewor-9467  [004] d..3 11740.164329: sched_wakeup: comm=vslam_framewor pid=3241 prio=120 target_cpu=004
 vslam_framewor-9467  [004] d..3 11740.164339: sched_stat_runtime: comm=vslam_framewor pid=9467 runtime=11552 [ns] vruntime=4886843502837 [ns]
 vslam_framewor-9467  [004] d..3 11740.164341: sched_stat_wait: comm=vslam_framewor pid=3241 delay=11552 [ns]
 vslam_framewor-9467  [004] d..3 11740.164342: sched_switch: prev_comm=vslam_framewor prev_pid=9467 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3241 next_prio=120
 vslam_framewor-3241  [004] d..2 11740.164374: sched_waking: comm=vslam_framewor pid=9467 prio=120 target_cpu=004
 vslam_framewor-3241  [004] d..3 11740.164376: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=36896 [ns] vruntime=4886844569237 [ns]
 vslam_framewor-3241  [004] d..3 11740.164377: sched_stat_sleep: comm=vslam_framewor pid=9467 delay=36896 [ns]
 vslam_framewor-3241  [004] d..3 11740.164378: sched_wakeup: comm=vslam_framewor pid=9467 prio=120 target_cpu=004
 vslam_framewor-3241  [004] d..3 11740.164386: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=9792 [ns] vruntime=4886844579029 [ns]
 vslam_framewor-3241  [004] d..3 11740.164387: sched_stat_wait: comm=vslam_framewor pid=9467 delay=9792 [ns]
 vslam_framewor-3241  [004] d..3 11740.164388: sched_switch: prev_comm=vslam_framewor prev_pid=3241 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=9467 next_prio=120
 vslam_framewor-9467  [004] d..2 11740.164416: sched_waking: comm=vslam_framewor pid=3241 prio=120 target_cpu=004
 vslam_framewor-9467  [004] d..3 11740.164417: sched_stat_runtime: comm=vslam_framewor pid=9467 runtime=31456 [ns] vruntime=4886843534293 [ns]
 vslam_framewor-9467  [004] d..3 11740.164418: sched_stat_sleep: comm=vslam_framewor pid=3241 delay=31456 [ns]
 vslam_framewor-9467  [004] d..3 11740.164419: sched_wakeup: comm=vslam_framewor pid=3241 prio=120 target_cpu=004
 vslam_framewor-9467  [004] d..3 11740.164447: sched_stat_runtime: comm=vslam_framewor pid=9467 runtime=30048 [ns] vruntime=4886843564341 [ns]
 vslam_framewor-9467  [004] d..3 11740.164449: sched_stat_wait: comm=vslam_framewor pid=3241 delay=30048 [ns]
 vslam_framewor-9467  [004] d..3 11740.164450: sched_switch: prev_comm=vslam_framewor prev_pid=9467 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3241 next_prio=120
 vslam_framewor-3241  [004] d..2 11740.164473: sched_waking: comm=vslam_framewor pid=9467 prio=120 target_cpu=004
 vslam_framewor-3241  [004] d..3 11740.164475: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=27872 [ns] vruntime=4886844606901 [ns]
 vslam_framewor-3241  [004] d..3 11740.164476: sched_stat_sleep: comm=vslam_framewor pid=9467 delay=27872 [ns]
 vslam_framewor-3241  [004] d..3 11740.164477: sched_wakeup: comm=vslam_framewor pid=9467 prio=120 target_cpu=004
 vslam_framewor-3241  [004] d..3 11740.164504: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=28512 [ns] vruntime=4886844635413 [ns]
 vslam_framewor-3241  [004] d..3 11740.164506: sched_stat_wait: comm=vslam_framewor pid=9467 delay=28512 [ns]
 vslam_framewor-3241  [004] d..3 11740.164507: sched_switch: prev_comm=vslam_framewor prev_pid=3241 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=9467 next_prio=120
 vslam_framewor-9467  [004] ...1 11740.164578: timer_init: timer=ffffffc1ecaa3c00
 vslam_framewor-9467  [004] d..2 11740.164580: timer_start: timer=ffffffc1ecaa3c00 function=process_timeout expires=4297827571 [timeout=25] flags=0x00000004
 vslam_framewor-9467  [004] d..3 11740.164581: sched_stat_runtime: comm=vslam_framewor pid=9467 runtime=77216 [ns] vruntime=4886843641557 [ns]
 vslam_framewor-9467  [004] d..3 11740.164590: sched_switch: prev_comm=vslam_framewor prev_pid=9467 prev_prio=120 prev_state=S ==> next_comm=swapper/4 next_pid=0 next_prio=120
          <idle>-0     [004] d..2 11740.164596: cpu_idle: state=1 cpu_id=4
   log_camera.sh-2013  [002] d..3 11740.164798: sched_stat_runtime: comm=log_camera.sh pid=2013 runtime=1277600 [ns] vruntime=7035209194777 [ns]
   log_camera.sh-2013  [002] d..3 11740.164802: sched_stat_wait: comm=log_camera.sh pid=19085 delay=1277600 [ns]
   log_camera.sh-2013  [002] d..3 11740.164806: sched_switch: prev_comm=log_camera.sh prev_pid=2013 prev_prio=120 prev_state=S ==> next_comm=log_camera.sh next_pid=19085 next_prio=120
     ksoftirqd/0-3     [000] dnH1 11740.165022: irq_handler_entry: irq=62 name=host_syncpt
     ksoftirqd/0-3     [000] dnH1 11740.165023: irq_handler_exit: irq=62 ret=handled
     ksoftirqd/0-3     [000] dnH2 11740.165024: sched_waking: comm=irq/62-host_syn pid=60 prio=49 target_cpu=002
             cat-19085 [002] dnh4 11740.165033: sched_wakeup: comm=irq/62-host_syn pid=60 prio=49 target_cpu=002
             cat-19085 [002] dn.3 11740.165040: sched_stat_runtime: comm=log_camera.sh pid=19085 runtime=230592 [ns] vruntime=7035225670196 [ns]
             cat-19085 [002] d..3 11740.165044: sched_switch: prev_comm=log_camera.sh prev_pid=19085 prev_prio=120 prev_state=R+ ==> next_comm=irq/62-host_syn next_pid=60 next_prio=49
 irq/62-host_syn-60    [002] d..3 11740.165059: sched_waking: comm=vslam_framewor pid=9467 prio=120 target_cpu=004
 irq/62-host_syn-60    [002] d..3 11740.165066: sched_waking: comm=kworker/u12:3 pid=7059 prio=120 target_cpu=002
          <idle>-0     [004] d.h3 11740.165066: sched_stat_sleep: comm=vslam_framewor pid=9467 delay=483712 [ns]
 irq/62-host_syn-60    [002] d..3 11740.165068: sched_migrate_task: comm=kworker/u12:3 pid=7059 prio=120 orig_cpu=2 dest_cpu=4
          <idle>-0     [004] dnh3 11740.165068: sched_wakeup: comm=vslam_framewor pid=9467 prio=120 target_cpu=004
          <idle>-0     [004] .n.2 11740.165070: cpu_idle: state=4294967295 cpu_id=4
          <idle>-0     [004] dnh5 11740.165070: sched_stat_sleep: comm=kworker/u12:3 pid=7059 delay=2056224 [ns]
          <idle>-0     [004] dnh5 11740.165070: sched_wakeup: comm=kworker/u12:3 pid=7059 prio=120 target_cpu=004
          <idle>-0     [004] dn.3 11740.165077: sched_stat_wait: comm=kworker/u12:3 pid=7059 delay=0 [ns]
          <idle>-0     [004] d..3 11740.165079: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u12:3 next_pid=7059 next_prio=120
   kworker/u12:3-7059  [004] d..3 11740.165085: sched_waking: comm=nvgpu_channel_p pid=596 prio=120 target_cpu=004
   kworker/u12:3-7059  [004] d..4 11740.165087: sched_stat_runtime: comm=kworker/u12:3 pid=7059 runtime=15744 [ns] vruntime=4886835622645 [ns]
   kworker/u12:3-7059  [004] d..4 11740.165090: sched_stat_blocked: comm=nvgpu_channel_p pid=596 delay=91217152 [ns]
   kworker/u12:3-7059  [004] d..4 11740.165091: sched_blocked_reason: pid=596 iowait=0 caller=gk20a_channel_poll_worker+0x2d4/0x3d0
   kworker/u12:3-7059  [004] d..4 11740.165093: sched_wakeup: comm=nvgpu_channel_p pid=596 prio=120 target_cpu=004
   kworker/u12:3-7059  [004] d..3 11740.165098: sched_stat_runtime: comm=kworker/u12:3 pid=7059 runtime=11616 [ns] vruntime=4886835634261 [ns]
 irq/62-host_syn-60    [002] d..3 11740.165099: sched_stat_wait: comm=log_camera.sh pid=19085 delay=63584 [ns]
   kworker/u12:3-7059  [004] d..3 11740.165099: sched_stat_wait: comm=nvgpu_channel_p pid=596 delay=11616 [ns]
   kworker/u12:3-7059  [004] d..3 11740.165100: sched_switch: prev_comm=kworker/u12:3 prev_pid=7059 prev_prio=120 prev_state=S ==> next_comm=nvgpu_channel_p next_pid=596 next_prio=120
 nvgpu_channel_p-596   [004] d..2 11740.165102: timer_cancel: timer=ffffffc07652fd10
 irq/62-host_syn-60    [002] d..3 11740.165104: sched_switch: prev_comm=irq/62-host_syn prev_pid=60 prev_prio=49 prev_state=S ==> next_comm=log_camera.sh next_pid=19085 next_prio=120
 nvgpu_channel_p-596   [004] ...1 11740.165174: timer_init: timer=ffffffc07652fd10
 nvgpu_channel_p-596   [004] d..2 11740.165175: timer_start: timer=ffffffc07652fd10 function=process_timeout expires=4297827571 [timeout=25] flags=0x00000004
 nvgpu_channel_p-596   [004] d..3 11740.165176: sched_stat_runtime: comm=nvgpu_channel_p pid=596 runtime=77824 [ns] vruntime=4886835684725 [ns]
 nvgpu_channel_p-596   [004] d..3 11740.165177: sched_stat_wait: comm=vslam_framewor pid=9467 delay=111712 [ns]
 nvgpu_channel_p-596   [004] d..3 11740.165179: sched_switch: prev_comm=nvgpu_channel_p prev_pid=596 prev_prio=120 prev_state=D ==> next_comm=vslam_framewor next_pid=9467 next_prio=120
 vslam_framewor-9467  [004] d..2 11740.165180: timer_cancel: timer=ffffffc1ecaa3c00
 vslam_framewor-9467  [004] d..2 11740.165217: sched_waking: comm=vslam_framewor pid=3241 prio=120 target_cpu=004
 vslam_framewor-9467  [004] d..3 11740.165220: sched_stat_runtime: comm=vslam_framewor pid=9467 runtime=43616 [ns] vruntime=4886843685173 [ns]
 vslam_framewor-9467  [004] d..3 11740.165222: sched_stat_sleep: comm=vslam_framewor pid=3241 delay=716256 [ns]
 vslam_framewor-9467  [004] d..3 11740.165223: sched_wakeup: comm=vslam_framewor pid=3241 prio=120 target_cpu=004
 vslam_framewor-9467  [004] d..3 11740.165269: sched_stat_runtime: comm=vslam_framewor pid=9467 runtime=48928 [ns] vruntime=4886843734101 [ns]
 vslam_framewor-9467  [004] d..3 11740.165272: sched_stat_wait: comm=vslam_framewor pid=3241 delay=48928 [ns]
 vslam_framewor-9467  [004] d..3 11740.165274: sched_switch: prev_comm=vslam_framewor prev_pid=9467 prev_prio=120 prev_state=S ==> next_comm=vslam_framewor next_pid=3241 next_prio=120
 vslam_framewor-3241  [004] d..2 11740.165322: sched_waking: comm=vslam_framewor pid=9467 prio=120 target_cpu=004
 vslam_framewor-3241  [004] d..3 11740.165325: sched_stat_runtime: comm=vslam_framewor pid=3241 runtime=55840 [ns] vruntime=4886844691253 [ns]

Do you have any more suggesting?
We will try to apply rt patch later. But I am afraid rt patch don’t affect lost irq issue. Seems kernel disable irq at some point with long term?

How can I locate the longest disable irq source path?

Can you try disabling denver cores
set the governor to performance and then offline denver cores
echo performance > /ys/devices/system/cpu/cpu0/cpufreq/scaling_governor
echo 0 > /sys/devices/system/cpu/cpu1/online
echo 0 > /sys/devices/system/cpu/cpu2/online

Also, can you run your application to a particular CPU using taskset?

Why we need to disable denver cores? What special feature for denver cores.

We already use cgroup to force vslam to special cores (5 cores include 2 denver cores).

As I mentioned before, our vslam cost about 500$ cpu performance. I am not sure this will effect final performance of irq?

Please do below tests & share results with log if the problem still coming.

  1. Disable cpu idle “CONFIG_CPU_IDLE” in kernel defconfig.
  2. Pass “nohz=off” in kernel boot arg to disable the tickless kernel/dyntick-idle mode.
  3. Disable CONFIG_TEGRA_PROFILER in kernel defconfig.
  4. If issue still there, then please try with CONFIG_HZ_1000=y to have near realtime interrupt freq.

@sumtg, bbasu

We are trying to apply rt_patch for JetPack3.3 with tag tegra-l4t-r28.2.1.
Follow this link to enable rt for tx2. https://github.com/kozyilmaz/nvidia-jetson-rt/blob/master/docs/README.03-realtime.md

Here is our steps:

  1. sources/kernel/kernel-4.4$ ./scripts/rt-patch.sh apply-patches
  2. make tegra18_defconfig
  3. make zImage, we get error message:
CC      drivers/iommu/io-pgtable-arm.o
  CC      drivers/iommu/of_iommu.o
  CC      drivers/input/misc/gpio_output.o
  CC      drivers/input/misc/gpio_axis.o
  CC      drivers/input/misc/keychord.o
  CC      drivers/iommu/arm-smmu.o
  CC      drivers/iommu/tegra-iommu.o
  CC      drivers/iommu/tegra-smmu.o
  CC      drivers/input/misc/uinput.o
  CC      drivers/iommu/of_tegra-smmu.o
drivers/iommu/tegra-smmu.c:1649:13: error: initialization from incompatible pointer type [-Werror=incompatible-pointer-types]
  .map_sg  = smmu_iommu_map_sg,
             ^~~~~~~~~~~~~~~~~
drivers/iommu/tegra-smmu.c:1649:13: note: (near initialization for ‘smmu_iommu_ops_default.map_sg’)
  LD      drivers/input/mouse/built-in.o
  LD      drivers/input/tablet/built-in.o
  CC      drivers/input/touchscreen/of_touchscreen.o
  LD      drivers/input/misc/compass/built-in.o
  LD      drivers/input/misc/mpu/built-in.o
  LD      drivers/input/misc/pressure
  1. make modules, we get error messag:
In file included from include/linux/io.h:25:0,
                 from include/linux/pci.h:31,
                 from drivers/net/ethernet/intel/ixgbe/ixgbe_osdep.h:33,
                 from drivers/net/ethernet/intel/ixgbe/ixgbe_type.h:66,
                 from drivers/net/ethernet/intel/ixgbe/ixgbe_api.h:28,
                 from drivers/net/ethernet/intel/ixgbe/ixgbe_api.c:25:
./arch/arm64/include/asm/io.h:212:0: note: this is the location of the previous definition
 #define IOMEM(x)        ((void __force __iomem *)(x))
 
In file included from drivers/net/ethernet/intel/ixgbe/ixgbe_type.h:66:0,
                 from drivers/net/ethernet/intel/ixgbe/ixgbe_dcb.c:26:
drivers/net/ethernet/intel/ixgbe/ixgbe_osdep.h:51:0: warning: "IOMEM" redefined
 #define IOMEM __iomem
 
In file included from include/linux/io.h:25:0,
                 from include/linux/pci.h:31,
                 from drivers/net/ethernet/intel/ixgbe/ixgbe_osdep.h:33,
                 from drivers/net/ethernet/intel/ixgbe/ixgbe_type.h:66,
                 from drivers/net/ethernet/intel/ixgbe/ixgbe_dcb.c:26:
./arch/arm64/include/asm/io.h:212:0: note: this is the location of the previous definition
 #define IOMEM(x)        ((void __force __iomem *)(x))
 
  CC [M]  drivers/net/wireless/bcmdhd/dhd_pno.o
  CC [M]  net/netfilter/nf_nat_proto_udp.o
  CC [M]  drivers/net/ethernet/intel/ixgbe/ixgbe_dcb_82598.o
  CC [M]  net/netfilter/nf_nat_proto_tcp.o
drivers/net/wireless/bcmdhd/dhd_pno.c: In function ‘_dhd_pno_get_for_batch’:
drivers/net/wireless/bcmdhd/dhd_pno.c:1557:23: error: passing argument 1 of ‘waitqueue_active’ from incompatible pointer type [-Werror=incompatible-pointer-types]
  if (waitqueue_active(&_pno_state->get_batch_done.wait))
                       ^
In file included from include/linux/kernfs.h:18:0,
                 from include/linux/sysfs.h:15,
                 from include/linux/kobject.h:21,
                 from include/linux/device.h:17,
                 from include/linux/leds.h:15,
                 from include/linux/mmc/host.h:15,
                 from drivers/net/wireless/bcmdhd/include/linux_osl.h:30,
                 from drivers/net/wireless/bcmdhd/include/osl.h:43,
                 from drivers/net/wireless/bcmdhd/dhd_pno.c:30:
include/linux/wait.h:106:19: note: expected ‘wait_queue_head_t * {aka struct __wait_queue_head *}’ but argument is of type ‘struct swait_queue_head *’
 static inline int waitqueue_active(wait_queue_head_t *q)
                   ^~~~~~~~~~~~~~~~
drivers/net/wireless/bcmdhd/dhd_pno.c: In function ‘dhd_pno_event_handler’:
drivers/net/wireless/bcmdhd/dhd_pno.c:2003:25: error: passing argument 1 of ‘waitqueue_active’ from incompatible pointer type [-Werror=incompatible-pointer-types]
   if (!waitqueue_active(&_pno_state->get_batch_done.wait)) {
                         ^
In file included from include/linux/kernfs.h:18:0,
                 from include/linux/sysfs.h:15,
                 from include/linux/kobject.h:21,
                 from include/linux/device.h:17,
                 from include/linux/leds.h:15,
                 from include/linux/mmc/host.h:15,
                 from drivers/net/wireless/bcmdhd/include/linux_osl.h:30,
                 from drivers/net/wireless/bcmdhd/include/osl.h:43,
                 from drivers/net/wireless/bcmdhd/dhd_pno.c:30:
include/linux/wait.h:106:19: note: expected ‘wait_queue_head_t * {aka struct __wait_queue_head *}’ but argument is of type ‘struct swait_queue_head *’
 static inline int waitqueue_active(wait_queue_head_t *q)
                   ^~~~~~~~~~~~~~~~
In file included from drivers/net/ethernet/intel/ixgbe/ixgbe_type.h:66:0,
                 from drivers/net/ethernet/intel/ixgbe/ixgbe_dcb_82598.c:26:
drivers/net/ethernet/intel/ixgbe/ixgbe_osdep.h:51:0: warning: "IOMEM" redefined
 #define IOMEM __iomem

Use the same apply method with JetPack4.2, both make zImage and make modues passed.

Can you try this method on your side with JetPack3.3?

After switch CROSS_COMPILER from “gcc version 6.4.1 20171012 (Linaro GCC 6.4-2017.11)” to “aarch64-unknown-linux-gnu-gcc 4.8.5”, rt_patch can be successful applied with JetPack3.3.

It would be better to switch to latest JetPack 4.2.2 & Kernel-4.9.

@sumitg Thanks for your replay.

We will switch to JetPack4.2.2 in future.

We have applied method 1 to 3, so far so good. irq latency is still there. But the max latency value is shorten. The latency value is accepted for us now.

  1. Disable cpu idle “CONFIG_CPU_IDLE” in kernel defconfig.
  2. Pass “nohz=off” in kernel boot arg to disable the tickless kernel/dyntick-idle mode.
  3. Disable CONFIG_TEGRA_PROFILER in kernel defconfig.

Doesn’t apply method 4. Because it will cause more cpu overload.
4) If issue still there, then please try with CONFIG_HZ_1000=y to have near realtime interrupt freq.

BTW, we also test with rt-patch. The test result is also good, even Ethernet response time. But it also bring other side-effect. Like programmer exit or kill -9 single will cause kernel coredump. And the whole system will hang.