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

[Luiz Capitulino]

On Thu, 23 Mar 2017 21:08:38 -0400
Rik van Riel <riel@xxxxxxxxxx> wrote:

> On Thu, 2017-03-23 at 21:05 -0400, Luiz Capitulino wrote:
> > On Thu, 23 Mar 2017 20:56:02 -0400
> > Rik van Riel <riel@xxxxxxxxxx> wrote:
> >   
> > > On Thu, 2017-03-23 at 16:55 -0400, Luiz Capitulino wrote:  
> > > > When there are two or more tasks executing in user-space and
> > > > taking 100% of a nohz_full CPU, top reports 70% system time
> > > > and 30% user time utilization. Sometimes I'm even able to get
> > > > 100% system time and 0% user time.
> > > > 
> > > > This was reproduced with latest Linus tree (093b995), but I
> > > > don't believe it's a regression (at least not a recent one)
> > > > as I can reproduce it with older kernels. Also, I have
> > > > CONFIG_IRQ_TIME_ACCOUNTING=y and haven't tried to reproduce
> > > > without it yet.
> > > > 
> > > > Below you'll find the steps to reproduce and some initial
> > > > analysis.
> > > > 
> > > > Steps to reproduce
> > > > ------------------
> > > > 
> > > > 1. Set up a CPU for nohz_full with isolcpus= nohz_full=
> > > > 
> > > > 2. Pin two tasks that hog the CPU 100% of the time to that CPU
> > > > 
> > > > 3. Run top -d1 and check system time
> > > > 
> > > > NOTE: When there's only one task hogging a nohz_full CPU, top
> > > > ÂÂÂÂÂÂshows 100% user-time, as expected
> > > > 
> > > > Initial analysis
> > > > ----------------
> > > > 
> > > > When tracing vtime accounting functions and the user-space/kernel
> > > > transitions when the issue is taking place, I see several of the
> > > > following:
> > > > 
> > > > hog-10552 [015]ÂÂ1132.711104:
> > > > function:ÂÂÂÂÂÂÂÂÂÂÂÂÂenter_from_user_mode <--
> > > > apic_timer_interrupt
> > > > hog-10552 [015]ÂÂ1132.711105:
> > > > function:ÂÂÂÂÂÂÂÂÂÂÂÂÂ__context_tracking_exit <--
> > > > enter_from_user_mode
> > > > hog-10552 [015]ÂÂ1132.711105:
> > > > bprint:ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ__context_tracking_exit.part.4: new state=1
> > > > cur
> > > > state=1 active=1
> > > > hog-10552 [015]ÂÂ1132.711105:
> > > > function:ÂÂÂÂÂÂÂÂÂÂÂÂÂvtime_account_user <--
> > > > __context_tracking_exit.part.4
> > > > hog-10552 [015]ÂÂ1132.711105:
> > > > function:ÂÂÂÂÂÂÂÂÂÂÂÂÂsmp_apic_timer_interrupt <--
> > > > apic_timer_interrupt
> > > > hog-10552 [015]ÂÂ1132.711106: function:ÂÂÂÂÂÂÂÂÂÂÂÂÂirq_enter <--
> > > > smp_apic_timer_interrupt
> > > > hog-10552 [015]ÂÂ1132.711106:
> > > > function:ÂÂÂÂÂÂÂÂÂÂÂÂÂtick_sched_timer
> > > > <-- __hrtimer_run_queues
> > > > hog-10552 [015]ÂÂ1132.711108: function:ÂÂÂÂÂÂÂÂÂÂÂÂÂirq_exit <--
> > > > smp_apic_timer_interrupt
> > > > hog-10552 [015]ÂÂ1132.711108:
> > > > function:ÂÂÂÂÂÂÂÂÂÂÂÂÂ__context_tracking_enter <--
> > > > prepare_exit_to_usermode
> > > > hog-10552 [015]ÂÂ1132.711108:
> > > > bprint:ÂÂÂÂÂÂÂÂÂÂÂÂÂÂÂ__context_tracking_enter.part.2: new
> > > > state=1
> > > > cur state=0 active=1
> > > > hog-10552 [015]ÂÂ1132.711109:
> > > > function:ÂÂÂÂÂÂÂÂÂÂÂÂÂvtime_user_enter
> > > > <-- __context_tracking_enter.part.2
> > > > hog-10552 [015]ÂÂ1132.711109:
> > > > function:ÂÂÂÂÂÂÂÂÂÂÂÂÂ__vtime_account_system <-- vtime_user_enter
> > > > hog-10552 [015]ÂÂ1132.711109:
> > > > function:ÂÂÂÂÂÂÂÂÂÂÂÂÂaccount_system_time <--
> > > > __vtime_account_system
> > > > 
> > > > On entering the kernel due to a timer interrupt,
> > > > vtime_account_user()
> > > > skips user-time accounting. Then later on when returning to user-
> > > > space,
> > > > vtime_user_enter() is probably accounting the whole time (ie.
> > > > user-
> > > > space
> > > > plus kernel-space) to system time.
> > > > 
> > > > Now, when does vtime_account_user() skips accounting? Well, when
> > > > the
> > > > time delta is less then one jiffie. This would imply that
> > > > vtime_account_user()
> > > > is being called less than one jiffie since the last accounting,
> > > > but I
> > > > haven't
> > > > confirmed any of this yet.ÂÂ  
> > > 
> > > Jiffies should be advanced by the timer interrupt, on the
> > > housekeeping CPU, which is not doing context tracking.  
> > 
> > The hypothesis isn't that it wasn't advanced, but that we stayed in
> > user-space less than 1ms.  
> 
> That is part of the hypothesis. The other part of the hypothesis
> involves jiffies advancing on the nohz_full & isolated CPU while
> that CPU is in kernel mode 30% of the time.

OK.

> I have no good explanation for the latter yet...
> 
> > > Why is the isolated/nohz_full CPU receiving timer interrupts
> > > at all?
> > > 
> > > I thought it would not, but obviously I am wrong. What is
> > > going on here?  
> > 
> > There are two runnable SCHED_OTHER tasks on the nohz_full CPU. When
> > that happens, the tick is re-activated. We're not nohz_full anymore,
> > but accounting should still work.  
> 
> Isn't the scheduler tick distinct from the timer interrupt,
> or am I confused?

If you consider the scheduler tick to be the code that's run
by scheduler_tick(), yes they are distinct. But I was referring
to tick_sched_timer() the "main" tick handler. This one runs
as a hrtimer handler. In the case described in this email, the
timer interrupt fires because the nohz code sets up a hrtimer
to run (which is the tick, tick_sched_timer()).

Btw, _if_ the hypothesis is correct, I guess I might be able to
create a reproducer that doesn't depend on the tick. A task
staying 980us busy-looping in user-space and then making a
few dozen microseconds kernel call will probably report 100%
system time. This will be hard to do, but I'll give it try tomorrow.