Re: [BUG nohz]: wrong user and system time accounting

Luiz Capitulino
2017-04-04T18:03:02Z

On Mon, 3 Apr 2017 15:06:13 -0400
Luiz Capitulino <lcapitulino@redhat.com> wrote:

> On Mon, 3 Apr 2017 17:23:17 +0200
> Frederic Weisbecker <fweisbec@gmail.com> wrote:
>
> > Do you observe aligned ticks with trace events (hrtimer_expire_entry)?
> >
> > You might want to enforce the global clock to trace that:
> >
> > echo "global" > /sys/kernel/debug/tracing/trace_clock
>
> I've used the same trace points & debugging code I've been using to debug
> this issue, and this what I'm seeing:
>
> stress-25757 [002] 2742.717507: function: enter_from_user_mode <-- apic_timer_interrupt
> stress-25757 [002] 2742.717508: function: __context_tracking_exit <-- enter_from_user_mode
> stress-25757 [002] 2742.717508: bprint: vtime_delta: diff=0 (now=4297409970 vtime_snap=4297409970)
> stress-25757 [002] 2742.717509: function: smp_apic_timer_interrupt <-- apic_timer_interrupt
> stress-25757 [002] 2742.717509: function: irq_enter <-- smp_apic_timer_interrupt
> stress-25757 [002] 2742.717510: hrtimer_expire_entry: hrtimer=0xffffc900039fbe58 function=hrtimer_wakeup now=2742674000776
> stress-25757 [002] 2742.717514: function: irq_exit <-- smp_apic_timer_interrupt
> cyclictest-25760 [002] 2742.717518: function: vtime_account_system <-- vtime_common_task_switch
> cyclictest-25760 [002] 2742.717518: bprint: vtime_delta: diff=1000000 (now=4297409971 vtime_snap=4297409970)
> cyclictest-25760 [002] 2742.717519: function: __vtime_account_system <-- vtime_account_system
> cyclictest-25760 [002] 2742.717519: bprint: get_vtime_delta: vtime_snap=4297409970 now=4297409971
> cyclictest-25760 [002] 2742.717520: function: account_system_time <-- __vtime_account_system
> cyclictest-25760 [002] 2742.717520: bprint: account_system_time: cputime=961981
> cyclictest-25760 [002] 2742.717521: function: __context_tracking_enter <-- do_syscall_64
> cyclictest-25760 [002] 2742.717522: function: vtime_user_enter <-- __context_tracking_enter
> cyclictest-25760 [002] 2742.717522: bprint: vtime_delta: diff=0 (now=4297409971 vtime_snap=4297409971)
>
> CPU2 shows 98% system time while the other CPUs (from CPU3 to CPU7)
> show 98% user time (they're all running the same workload).

On further debugging this, I realized that I had overlooked something:
the timer interrupt in this trace is not the tick, but cyclictest's timer
(remember that the test-case consists of pinning cyclictest and a task
hogging the CPU to the same CPU).

I'm running cyclictest with -i 200. If I increase this to -i 1000, then
I seem unable to reproduce the issue (caution: even with -i 200 it
doesn't always happen. But it does usually happen after I restart the
test-case a few times. However, I've never been able to reproduce
with -i 1000).

Now, if it's really cyclictest that's causing the timer interrupts to
get aligned, I guess this might not have a solution? (note: I haven't
been able to reproduce this on bare-metal).