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

[Luiz Capitulino]

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

> On Mon, 3 Apr 2017 17:23:17 +0200
> Frederic Weisbecker <fweisbec@xxxxxxxxx> 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).