On 20/05/20 19:02, Frederic Weisbecker wrote: > On Wed, May 20, 2020 at 06:49:25PM +0200, Juri Lelli wrote: > > On 20/05/20 18:24, Frederic Weisbecker wrote: > > > > Hummm, so I enabled 'timer:*', anything else you think I should be > > looking at? > > Are you sure you also enabled timer_expire_entry? > Because: I run with trace-cmd record -e sched_switch -e sched_wakeup -e sched_migrate_task \ -e 'timer:*' -e 'irq_vectors:*' -e 'irq:softirq*' \ -e 'irq:irq_handler*' taskset --cpu-list 4-35 ./sysjitter/sysjitter \ --runtime 10 200 And $ grep ' timer_expire_entry:' trace.txt | wc -l 1173 seems to confirm that the event was indeed enabled, e.g. ksoftirqd/11-100 [011] 159.270023: timer_expire_entry: timer=0xffff9807df8a5a60 function=delayed_work_timer_fn now=4294826418 baseclk=4294825984 > > > > > ... > > ksoftirqd/13-117 [013] 148.265945: softirq_entry: vec=1 [action=TIMER] > > ...the timer softirq keep triggering without any timer callback executed. If that's the > case, we may be dealing with an interesting issue. > > Thanks. > > > ksoftirqd/13-117 [013] 148.265947: softirq_exit: vec=1 [action=TIMER] > > ksoftirqd/13-117 [013] 148.265948: softirq_entry: vec=7 [action=SCHED] > > ksoftirqd/13-117 [013] 148.265950: softirq_exit: vec=7 [action=SCHED] > > ksoftirqd/13-117 [013] 148.265952: sched_switch: ksoftirqd/13:117 [120] S ==> sysjitter:2536 [120] > > sysjitter-2536 [013] 148.266912: local_timer_entry: vector=236 > > sysjitter-2536 [013] 148.266914: hrtimer_cancel: hrtimer=0xffff9807df91bee0 > > sysjitter-2536 [013] 148.266916: hrtimer_expire_entry: hrtimer=0xffff9807df91bee0 now=148249107837 function=tick_sched_timer/0x0 > > sysjitter-2536 [013] 148.266918: softirq_raise: vec=1 [action=TIMER] > > sysjitter-2536 [013] 148.266920: softirq_raise: vec=7 [action=SCHED] > > sysjitter-2536 [013] 148.266922: hrtimer_expire_exit: hrtimer=0xffff9807df91bee0 > > sysjitter-2536 [013] 148.266924: hrtimer_start: hrtimer=0xffff9807df91bee0 function=tick_sched_timer/0x0 expires=148250105422 softexpires=148250105422 > > sysjitter-2536 [013] 148.266926: local_timer_exit: vector=236 > > sysjitter-2536 [013] 148.266930: sched_wakeup: ksoftirqd/13:117 [120] success=1 CPU:013 > > sysjitter-2536 [013] 148.266932: tick_stop: success=0 dependency=SCHED > > sysjitter-2536 [013] 148.266934: irq_work_entry: vector=246 > > sysjitter-2536 [013] 148.266936: irq_work_exit: vector=246 > > sysjitter-2536 [013] 148.266937: tick_stop: success=0 dependency=SCHED > > sysjitter-2536 [013] 148.266940: sched_switch: sysjitter:2536 [120] R ==> ksoftirqd/13:117 [120] > > ksoftirqd/13-117 [013] 148.266943: softirq_entry: vec=1 [action=TIMER] > > ksoftirqd/13-117 [013] 148.266946: softirq_exit: vec=1 [action=TIMER] > > ksoftirqd/13-117 [013] 148.266946: softirq_entry: vec=7 [action=SCHED] > > ksoftirqd/13-117 [013] 148.266948: softirq_exit: vec=7 [action=SCHED] > > ksoftirqd/13-117 [013] 148.266950: sched_switch: ksoftirqd/13:117 [120] S ==> sysjitter:2536 [120] > > sysjitter-2536 [013] 148.267912: local_timer_entry: vector=236 > > sysjitter-2536 [013] 148.267914: hrtimer_cancel: hrtimer=0xffff9807df91bee0 > > sysjitter-2536 [013] 148.267916: hrtimer_expire_entry: hrtimer=0xffff9807df91bee0 now=148250107750 function=tick_sched_timer/0x0 > > sysjitter-2536 [013] 148.267918: softirq_raise: vec=1 [action=TIMER] > > sysjitter-2536 [013] 148.267920: softirq_raise: vec=7 [action=SCHED] > > sysjitter-2536 [013] 148.267922: hrtimer_expire_exit: hrtimer=0xffff9807df91bee0 > > sysjitter-2536 [013] 148.267924: hrtimer_start: hrtimer=0xffff9807df91bee0 function=tick_sched_timer/0x0 expires=148251105422 softexpires=148251105422 > > sysjitter-2536 [013] 148.267926: local_timer_exit: vector=236 > > sysjitter-2536 [013] 148.267929: sched_wakeup: ksoftirqd/13:117 [120] success=1 CPU:013 > > sysjitter-2536 [013] 148.267931: tick_stop: success=0 dependency=SCHED > > sysjitter-2536 [013] 148.267934: irq_work_entry: vector=246 > > sysjitter-2536 [013] 148.267936: irq_work_exit: vector=246 > > sysjitter-2536 [013] 148.267937: tick_stop: success=0 dependency=SCHED > > sysjitter-2536 [013] 148.267940: sched_switch: sysjitter:2536 [120] R ==> ksoftirqd/13:117 [120] > > ksoftirqd/13-117 [013] 148.267943: softirq_entry: vec=1 [action=TIMER] > > ksoftirqd/13-117 [013] 148.267945: softirq_exit: vec=1 [action=TIMER] > > ksoftirqd/13-117 [013] 148.267946: softirq_entry: vec=7 [action=SCHED] > > ksoftirqd/13-117 [013] 148.267947: softirq_exit: vec=7 [action=SCHED] > > ksoftirqd/13-117 [013] 148.267949: sched_switch: ksoftirqd/13:117 [120] S ==> sysjitter:2536 [120] > > sysjitter-2536 [013] 148.268865: call_function_single_entry: vector=251 > > sysjitter-2536 [013] 148.268867: call_function_single_exit: vector=251 > > sysjitter-2536 [013] 148.268870: tick_stop: success=1 dependency=NONE > > sysjitter-2536 [013] 148.268872: hrtimer_cancel: hrtimer=0xffff9807df91bee0 > > sysjitter-2536 [013] 148.268876: call_function_single_entry: vector=251 > > sysjitter-2536 [013] 148.268878: call_function_single_exit: vector=251 > > ... > > > > it looks like tick sched timer is kept armed until tick_stop > > succedes (because of the check performed after _single_exit)? > > > > Thanks for your quick reply! > > >
