Groups > linux.kernel > #1607903 > unrolled thread

[BUG nohz]: wrong user and system time accounting

Started by	Luiz Capitulino <lcapitulino@redhat.com>
First post	2017-03-23 22:00 +0100
Last post	2017-03-30 03:50 +0200
Articles	20 on this page of 54 — 6 participants

Back to article view | Back to linux.kernel

  [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-23 22:00 +0100
    Re: [BUG nohz]: wrong user and system time accounting Rik van Riel <riel@redhat.com> - 2017-03-24 02:00 +0100
      Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-24 02:10 +0100
        Re: [BUG nohz]: wrong user and system time accounting Rik van Riel <riel@redhat.com> - 2017-03-24 02:10 +0100
          Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-24 02:50 +0100
      Re: [BUG nohz]: wrong user and system time accounting lkml@pengaru.com - 2017-03-27 07:40 +0200
    Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-24 03:00 +0100
    Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-27 04:00 +0200
      Re: [BUG nohz]: wrong user and system time accounting Rik van Riel <riel@redhat.com> - 2017-03-27 19:40 +0200
        Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-28 09:30 +0200
        Re: [BUG nohz]: wrong user and system time accounting Rik van Riel <riel@redhat.com> - 2017-03-28 23:10 +0200
          Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-28 23:30 +0200
            Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-29 12:00 +0200
              Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-03-29 15:00 +0200
        Re: [BUG nohz]: wrong user and system time accounting Rik van Riel <riel@redhat.com> - 2017-03-28 23:30 +0200
          Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-28 23:40 +0200
        Re: [BUG nohz]: wrong user and system time accounting Rik van Riel <riel@redhat.com> - 2017-03-29 22:20 +0200
          Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-03-30 01:00 +0200
            Re: [BUG nohz]: wrong user and system time accounting Rik van Riel <riel@redhat.com> - 2017-03-30 15:00 +0200
          Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-30 04:00 +0200
            Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-03-30 14:50 +0200
              Re: [BUG nohz]: wrong user and system time accounting Mike Galbraith <efault@gmx.de> - 2017-03-30 15:20 +0200
          Re: [BUG nohz]: wrong user and system time accounting Mike Galbraith <efault@gmx.de> - 2017-03-30 06:30 +0200
            Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-30 08:50 +0200
              Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-30 14:00 +0200
                Re: [BUG nohz]: wrong user and system time accounting Mike Galbraith <efault@gmx.de> - 2017-03-30 14:40 +0200
              Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-03-30 15:40 +0200
                Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-30 16:10 +0200
                  Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-03-30 16:30 +0200
                    Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-30 23:30 +0200
                      Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-31 22:10 +0200
                        Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-04-01 01:30 +0200
                          Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-04-01 05:20 +0200
                            Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-04-03 17:30 +0200
                              Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-04-03 21:10 +0200
                                Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-04-04 20:10 +0200
                                  Re: [BUG nohz]: wrong user and system time accounting Rik van Riel <riel@redhat.com> - 2017-04-05 16:30 +0200
            Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-03-30 15:00 +0200
              Re: [BUG nohz]: wrong user and system time accounting Rik van Riel <riel@redhat.com> - 2017-03-30 15:10 +0200
                Re: [BUG nohz]: wrong user and system time accounting Mike Galbraith <efault@gmx.de> - 2017-03-30 15:40 +0200
                  Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-04-03 16:50 +0200
                    Re: [BUG nohz]: wrong user and system time accounting Mike Galbraith <efault@gmx.de> - 2017-04-04 09:40 +0200
                Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-03-30 15:50 +0200
        Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-30 00:50 +0200
          Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-30 04:20 +0200
            Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-30 14:30 +0200
      Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-27 20:50 +0200
        Re: [BUG nohz]: wrong user and system time accounting Wanpeng Li <kernellwp@gmail.com> - 2017-03-28 07:40 +0200
          Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-28 16:00 +0200
    Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-03-29 15:10 +0200
      Re: [BUG nohz]: wrong user and system time accounting Rik van Riel <riel@redhat.com> - 2017-03-29 15:20 +0200
        Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-29 15:30 +0200
          Re: [BUG nohz]: wrong user and system time accounting Frederic Weisbecker <fweisbec@gmail.com> - 2017-03-29 23:20 +0200
            Re: [BUG nohz]: wrong user and system time accounting Luiz Capitulino <lcapitulino@redhat.com> - 2017-03-30 03:50 +0200

Page 1 of 3 [1] 2 3 Next page →

#1607903 — [BUG nohz]: wrong user and system time accounting

From	Luiz Capitulino <lcapitulino@redhat.com>
Date	2017-03-23 22:00 +0100
Subject	[BUG nohz]: wrong user and system time accounting
Message-ID	<tohZT-7Mb-5@gated-at.bofh.it>

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.

[toc] | [next] | [standalone]

#1608040

From	Rik van Riel <riel@redhat.com>
Date	2017-03-24 02:00 +0100
Message-ID	<tolK9-1Wj-7@gated-at.bofh.it>
In reply to	#1607903

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.

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?

[toc] | [prev] | [next] | [standalone]

#1608051

From	Luiz Capitulino <lcapitulino@redhat.com>
Date	2017-03-24 02:10 +0100
Message-ID	<tolTQ-2hX-11@gated-at.bofh.it>
In reply to	#1608040

On Thu, 23 Mar 2017 20:56:02 -0400
Rik van Riel <riel@redhat.com> 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.

> 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.

[toc] | [prev] | [next] | [standalone]

#1608056

From	Rik van Riel <riel@redhat.com>
Date	2017-03-24 02:10 +0100
Message-ID	<tolTQ-2hX-15@gated-at.bofh.it>
In reply to	#1608051

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@redhat.com> 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.

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?

[toc] | [prev] | [next] | [standalone]

#1608068

From	Luiz Capitulino <lcapitulino@redhat.com>
Date	2017-03-24 02:50 +0100
Message-ID	<tomwx-2zj-5@gated-at.bofh.it>
In reply to	#1608056

On Thu, 23 Mar 2017 21:08:38 -0400
Rik van Riel <riel@redhat.com> 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@redhat.com> 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.

[toc] | [prev] | [next] | [standalone]

#1609456

From	lkml@pengaru.com
Date	2017-03-27 07:40 +0200
Message-ID	<tpvxM-321-5@gated-at.bofh.it>
In reply to	#1608040

On Thu, Mar 23, 2017 at 08:56:02PM -0400, Rik van Riel 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.
> 
> 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?

This thread sounds awful familiar to me.

With CONFIG_NO_HZ_FULL=y && CONFIG_VIRT_CPU_ACCOUNTING_GEN=y I observed process
accounting anomalies with user CPU time being misaccounted as system time all
the way back to 4.6.0.

After switching to CONFIG_NO_HZ_IDLE=y && CONFIG_VIRT_CPU_ACCOUNTING_GEN=n the
issues went away.

The lkml thread I had seen at that time which compelled me to suspect these
settings was this:
http://lkml.iu.edu/hypermail/linux/kernel/1608.2/05860.html

It sounds like this issue is finally beginning to be understood though, good
work!

Regards,
Vito Caputo

[toc] | [prev] | [next] | [standalone]

#1608072

From	Wanpeng Li <kernellwp@gmail.com>
Date	2017-03-24 03:00 +0100
Message-ID	<tomGe-2CL-19@gated-at.bofh.it>
In reply to	#1607903

2017-03-24 4:55 GMT+08:00 Luiz Capitulino <lcapitulino@redhat.com>:
>
> 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

I just saw at most 12% system time instead of 30% or 100%. Could you
grep HZ /boot/config-`uname -r` and post here?

Regards,
Wanpeng Li

>
> 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.

[toc] | [prev] | [next] | [standalone]

#1609427

From	Wanpeng Li <kernellwp@gmail.com>
Date	2017-03-27 04:00 +0200
Message-ID	<tps6R-hZ-3@gated-at.bofh.it>
In reply to	#1607903

2017-03-24 4:55 GMT+08:00 Luiz Capitulino <lcapitulino@redhat.com>:
>
> 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.

Actually after I bisect, the first bad commit is ff9a9b4c4334 ("sched,
time: Switch VIRT_CPU_ACCOUNTING_GEN to jiffy granularity"). The bug
can be reproduced readily if CONFIG_CONTEXT_TRACKING_FORCE is true,
then just stress all the online cpus or just one cpu and leave others
idle(so it stresses the global timekeeping one), top show 100%
sys-time. And another way to reproduce it is by nohz_full, and gives
the stress to the house keeping cpu, the top show 100% sys-time of the
house keeping cpu, and also the other cpus who have at least two tasks
running on and in full_nohz mode.

Let's consider the cpu which has responsibility for the global
timekeeping, as the tracing posted above, the vtime_account_user() is
called before tick_sched_timer() which will update jiffies, so jiffies
is stale in vtime_account_user() and the run time in userspace is
skipped, the vtime_user_enter() is called after jiffies update, so
both the time in userspace and in  kernel are accumulated to sys time.
If the housekeeping cpu is idle when CONFIG_NO_HZ_FULL, everything is
fine. However, if you give stress to the housekeeping cpu, top will
show 100% sys-time of both the housekeeping cpu and the other cpus who
have at least two tasks running on and in full_nohz mode. I think it
is because the stress delays the timer interrupt handling in some
degree, then the jiffies is not updated timely before other cpus
access it in vtime_account_user().

I think we can keep syscalls/exceptions context tracking still in
jiffies based sampling and utilize local_clock() in vtime_delta()
again for irqs which avoids jiffies stale influence. I can make a
patch if the idea is acceptable or there is any better proposal. :)

Regards,
Wanpeng Li

[toc] | [prev] | [next] | [standalone]

#1610014

From	Rik van Riel <riel@redhat.com>
Date	2017-03-27 19:40 +0200
Message-ID	<tpGMy-3cO-19@gated-at.bofh.it>
In reply to	#1609427

On Mon, 2017-03-27 at 09:56 +0800, Wanpeng Li wrote:
> 
> Actually after I bisect, the first bad commit is ff9a9b4c4334
> ("sched,
> time: Switch VIRT_CPU_ACCOUNTING_GEN to jiffy granularity"). The bug
> can be reproduced readily if CONFIG_CONTEXT_TRACKING_FORCE is true

At the time, we thought it was an "occasionally bad" / "unlucky"
kind of bug, not a systemic issue, like your observations seem
to suggest.

> Let's consider the cpu which has responsibility for the global
> timekeeping, as the tracing posted above, the vtime_account_user() is
> called before tick_sched_timer() which will update jiffies, so
> jiffies
> is stale in vtime_account_user() and the run time in userspace is
> skipped, the vtime_user_enter() is called after jiffies update, so
> both the time in userspace and in  kernel are accumulated to sys
> time.
> If the housekeeping cpu is idle when CONFIG_NO_HZ_FULL, everything is
> fine. However, if you give stress to the housekeeping cpu, top will
> show 100% sys-time of both the housekeeping cpu and the other cpus
> who
> have at least two tasks running on and in full_nohz mode. I think it
> is because the stress delays the timer interrupt handling in some
> degree, then the jiffies is not updated timely before other cpus
> access it in vtime_account_user().
> 
> I think we can keep syscalls/exceptions context tracking still in
> jiffies based sampling and utilize local_clock() in vtime_delta()
> again for irqs which avoids jiffies stale influence. I can make a
> patch if the idea is acceptable or there is any better proposal. :)

Making that patch seems worthwhile, but I would like to
know what the root cause is of the issue that is being
observed.

Is the problem due to the nohz_full CPU receiving an
interrupt at the same time the timer interrupt fires on
the housekeeping CPU?

Is it due to a nohz_full CPU updating jiffies all by
itself from irq context?  In that case, could it be
better to always have that be done by the housekeeping
CPU?

What exactly is going on here?

[toc] | [prev] | [next] | [standalone]

#1610378

From	Wanpeng Li <kernellwp@gmail.com>
Date	2017-03-28 09:30 +0200
Message-ID	<tpTJL-4au-1@gated-at.bofh.it>
In reply to	#1610014

2017-03-28 1:35 GMT+08:00 Rik van Riel <riel@redhat.com>:
> On Mon, 2017-03-27 at 09:56 +0800, Wanpeng Li wrote:
>>
>> Actually after I bisect, the first bad commit is ff9a9b4c4334
>> ("sched,
>> time: Switch VIRT_CPU_ACCOUNTING_GEN to jiffy granularity"). The bug
>> can be reproduced readily if CONFIG_CONTEXT_TRACKING_FORCE is true
>
> At the time, we thought it was an "occasionally bad" / "unlucky"
> kind of bug, not a systemic issue, like your observations seem
> to suggest.
>
>> Let's consider the cpu which has responsibility for the global
>> timekeeping, as the tracing posted above, the vtime_account_user() is
>> called before tick_sched_timer() which will update jiffies, so
>> jiffies
>> is stale in vtime_account_user() and the run time in userspace is
>> skipped, the vtime_user_enter() is called after jiffies update, so
>> both the time in userspace and in  kernel are accumulated to sys
>> time.
>> If the housekeeping cpu is idle when CONFIG_NO_HZ_FULL, everything is
>> fine. However, if you give stress to the housekeeping cpu, top will
>> show 100% sys-time of both the housekeeping cpu and the other cpus
>> who
>> have at least two tasks running on and in full_nohz mode. I think it
>> is because the stress delays the timer interrupt handling in some
>> degree, then the jiffies is not updated timely before other cpus
>> access it in vtime_account_user().
>>
>> I think we can keep syscalls/exceptions context tracking still in
>> jiffies based sampling and utilize local_clock() in vtime_delta()
>> again for irqs which avoids jiffies stale influence. I can make a
>> patch if the idea is acceptable or there is any better proposal. :)
>
> Making that patch seems worthwhile, but I would like to
> know what the root cause is of the issue that is being
> observed.
>
> Is the problem due to the nohz_full CPU receiving an
> interrupt at the same time the timer interrupt fires on
> the housekeeping CPU?
>
> Is it due to a nohz_full CPU updating jiffies all by
> itself from irq context?  In that case, could it be
> better to always have that be done by the housekeeping
> CPU?

I observed that the jiffies is always updated by housekeeping CPU as
we expected.

Regards,
Wanpeng Li

[toc] | [prev] | [next] | [standalone]

#1611361

From	Rik van Riel <riel@redhat.com>
Date	2017-03-28 23:10 +0200
Message-ID	<tq6xj-52S-1@gated-at.bofh.it>
In reply to	#1610014

On Tue, 2017-03-28 at 16:14 -0400, Luiz Capitulino wrote:
> On Tue, 28 Mar 2017 13:24:06 -0400
> Luiz Capitulino <lcapitulino@redhat.com> wrote:
> > I'm starting to suspect that the nohz code may be programming
> > the tick period to be shorter than 1ms when it re-activates
> > the tick.
> 
> And I think I was right, it looks like the nohz code is programming
> the tick period incorrectly when restarting the tick. The patch below
> fixes things for me, but I still have some homework todo and more
> testing before posting a patch for inclusion. Could you guys test it?

Your patch seems to work. I don't claim to understand why
your patch makes a difference, but for this particular test
case, on this particular setup, it seems to work...

> diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> index 7fe53be..9abe979 100644
> --- a/kernel/time/tick-sched.c
> +++ b/kernel/time/tick-sched.c
> @@ -1152,6 +1152,7 @@ static enum hrtimer_restart
> tick_sched_timer(struct hrtimer *timer)
>         struct pt_regs *regs = get_irq_regs();
>         ktime_t now = ktime_get();
>  
> +       ts->last_tick = now;
>         tick_sched_do_timer(now);
>  
>         /*

[toc] | [prev] | [next] | [standalone]

#1611370

From	Luiz Capitulino <lcapitulino@redhat.com>
Date	2017-03-28 23:30 +0200
Message-ID	<tq6QG-5f5-7@gated-at.bofh.it>
In reply to	#1611361

On Tue, 28 Mar 2017 17:01:52 -0400
Rik van Riel <riel@redhat.com> wrote:

> On Tue, 2017-03-28 at 16:14 -0400, Luiz Capitulino wrote:
> > On Tue, 28 Mar 2017 13:24:06 -0400
> > Luiz Capitulino <lcapitulino@redhat.com> wrote:  
> > > I'm starting to suspect that the nohz code may be programming
> > > the tick period to be shorter than 1ms when it re-activates
> > > the tick.  
> > 
> > And I think I was right, it looks like the nohz code is programming
> > the tick period incorrectly when restarting the tick. The patch below
> > fixes things for me, but I still have some homework todo and more
> > testing before posting a patch for inclusion. Could you guys test it?  
> 
> Your patch seems to work. I don't claim to understand why
> your patch makes a difference, but for this particular test
> case, on this particular setup, it seems to work...

I don't fully understand why either yet. I was looking for places
where nohz might be programming the tick period incorrectly and
I found that there's a case in tick_nohz_stop_sched_tick() where
tick_nohz_restart() is called only to reprogram the tick timer,
not cancel the tick. In this case, ts->last_tick seems to be out
of date. Fixing this fixed accounting for me.

> > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > index 7fe53be..9abe979 100644
> > --- a/kernel/time/tick-sched.c
> > +++ b/kernel/time/tick-sched.c
> > @@ -1152,6 +1152,7 @@ static enum hrtimer_restart
> > tick_sched_timer(struct hrtimer *timer)
> >         struct pt_regs *regs = get_irq_regs();
> >         ktime_t now = ktime_get();
> >  
> > +       ts->last_tick = now;
> >         tick_sched_do_timer(now);
> >  
> >         /*  
>

[toc] | [prev] | [next] | [standalone]

#1611770

From	Wanpeng Li <kernellwp@gmail.com>
Date	2017-03-29 12:00 +0200
Message-ID	<tqiyv-55o-33@gated-at.bofh.it>
In reply to	#1611370

2017-03-29 5:26 GMT+08:00 Luiz Capitulino <lcapitulino@redhat.com>:
> On Tue, 28 Mar 2017 17:01:52 -0400
> Rik van Riel <riel@redhat.com> wrote:
>
>> On Tue, 2017-03-28 at 16:14 -0400, Luiz Capitulino wrote:
>> > On Tue, 28 Mar 2017 13:24:06 -0400
>> > Luiz Capitulino <lcapitulino@redhat.com> wrote:
>> > > I'm starting to suspect that the nohz code may be programming
>> > > the tick period to be shorter than 1ms when it re-activates
>> > > the tick.
>> >
>> > And I think I was right, it looks like the nohz code is programming
>> > the tick period incorrectly when restarting the tick. The patch below
>> > fixes things for me, but I still have some homework todo and more
>> > testing before posting a patch for inclusion. Could you guys test it?
>>
>> Your patch seems to work. I don't claim to understand why
>> your patch makes a difference, but for this particular test
>> case, on this particular setup, it seems to work...
>
> I don't fully understand why either yet. I was looking for places
> where nohz might be programming the tick period incorrectly and

The bug is still present when I config CONTEXT_TRACKING_FORCE and
nohz=off in the boot parameter.

Regards,
Wanpeng Li

> I found that there's a case in tick_nohz_stop_sched_tick() where
> tick_nohz_restart() is called only to reprogram the tick timer,
> not cancel the tick. In this case, ts->last_tick seems to be out
> of date. Fixing this fixed accounting for me.
>
>> > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
>> > index 7fe53be..9abe979 100644
>> > --- a/kernel/time/tick-sched.c
>> > +++ b/kernel/time/tick-sched.c
>> > @@ -1152,6 +1152,7 @@ static enum hrtimer_restart
>> > tick_sched_timer(struct hrtimer *timer)
>> >         struct pt_regs *regs = get_irq_regs();
>> >         ktime_t now = ktime_get();
>> >
>> > +       ts->last_tick = now;
>> >         tick_sched_do_timer(now);
>> >
>> >         /*
>>
>

[toc] | [prev] | [next] | [standalone]

#1611906

From	Frederic Weisbecker <fweisbec@gmail.com>
Date	2017-03-29 15:00 +0200
Message-ID	<tqlmG-6Yd-23@gated-at.bofh.it>
In reply to	#1611770

On Wed, Mar 29, 2017 at 05:56:30PM +0800, Wanpeng Li wrote:
> 2017-03-29 5:26 GMT+08:00 Luiz Capitulino <lcapitulino@redhat.com>:
> > On Tue, 28 Mar 2017 17:01:52 -0400
> > Rik van Riel <riel@redhat.com> wrote:
> >
> >> On Tue, 2017-03-28 at 16:14 -0400, Luiz Capitulino wrote:
> >> > On Tue, 28 Mar 2017 13:24:06 -0400
> >> > Luiz Capitulino <lcapitulino@redhat.com> wrote:
> >> > > I'm starting to suspect that the nohz code may be programming
> >> > > the tick period to be shorter than 1ms when it re-activates
> >> > > the tick.
> >> >
> >> > And I think I was right, it looks like the nohz code is programming
> >> > the tick period incorrectly when restarting the tick. The patch below
> >> > fixes things for me, but I still have some homework todo and more
> >> > testing before posting a patch for inclusion. Could you guys test it?
> >>
> >> Your patch seems to work. I don't claim to understand why
> >> your patch makes a difference, but for this particular test
> >> case, on this particular setup, it seems to work...
> >
> > I don't fully understand why either yet. I was looking for places
> > where nohz might be programming the tick period incorrectly and
> 
> The bug is still present when I config CONTEXT_TRACKING_FORCE and
> nohz=off in the boot parameter.

Indeed I saw something similar a few days ago with:

    !CONFIG_NO_HZ_FULL && CONFIG_VIRT_CPU_ACCOUNTING_GEN && CONTEXT_TRACKING_FORCE

And it disappeared with CONFIG_NO_HZ_FULL=y so I didn't care much because that setting
isn't used in production and in fact I intend to remove CONTEXT_TRACKING_FORCE. But
it could be the sign of something important.

It might be different than Luiz's bug because I can't reproduce his bug yet even with
his config.

[toc] | [prev] | [next] | [standalone]

#1611368

From	Rik van Riel <riel@redhat.com>
Date	2017-03-28 23:30 +0200
Message-ID	<tq6QG-5f5-5@gated-at.bofh.it>
In reply to	#1610014

On Tue, 2017-03-28 at 16:14 -0400, Luiz Capitulino wrote:

> And I think I was right, it looks like the nohz code is programming
> the tick period incorrectly when restarting the tick. The patch below
> fixes things for me, but I still have some homework todo and more
> testing before posting a patch for inclusion. Could you guys test it?

I spoke too soon.  After half an hour of runtime,
things have gotten aligned to give me about 50/50
user time and system time with your test case,
again.

This is on an 8 VCPU virtual machine, with
nohz_full=2-7, and the test case running on one
of the nohz_full CPUs.

> diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> index 7fe53be..9abe979 100644
> --- a/kernel/time/tick-sched.c
> +++ b/kernel/time/tick-sched.c
> @@ -1152,6 +1152,7 @@ static enum hrtimer_restart
> tick_sched_timer(struct hrtimer *timer)
>         struct pt_regs *regs = get_irq_regs();
>         ktime_t now = ktime_get();
>  
> +       ts->last_tick = now;
>         tick_sched_do_timer(now);
>  
>         /*

[toc] | [prev] | [next] | [standalone]

#1611373

From	Luiz Capitulino <lcapitulino@redhat.com>
Date	2017-03-28 23:40 +0200
Message-ID	<tq70m-5jM-11@gated-at.bofh.it>
In reply to	#1611368

On Tue, 28 Mar 2017 17:24:11 -0400
Rik van Riel <riel@redhat.com> wrote:

> On Tue, 2017-03-28 at 16:14 -0400, Luiz Capitulino wrote:
> 
> > And I think I was right, it looks like the nohz code is programming
> > the tick period incorrectly when restarting the tick. The patch below
> > fixes things for me, but I still have some homework todo and more
> > testing before posting a patch for inclusion. Could you guys test it?  
> 
> I spoke too soon.  After half an hour of runtime,
> things have gotten aligned to give me about 50/50
> user time and system time with your test case,
> again.

Hmmm, maybe it's incomplete. I still think that nohz might screwing
something up when re-activating the tick.

> 
> This is on an 8 VCPU virtual machine, with
> nohz_full=2-7, and the test case running on one
> of the nohz_full CPUs.
> 
> > diff --git a/kernel/time/tick-sched.c b/kernel/time/tick-sched.c
> > index 7fe53be..9abe979 100644
> > --- a/kernel/time/tick-sched.c
> > +++ b/kernel/time/tick-sched.c
> > @@ -1152,6 +1152,7 @@ static enum hrtimer_restart
> > tick_sched_timer(struct hrtimer *timer)
> >         struct pt_regs *regs = get_irq_regs();
> >         ktime_t now = ktime_get();
> >  
> > +       ts->last_tick = now;
> >         tick_sched_do_timer(now);
> >  
> >         /*  
>

[toc] | [prev] | [next] | [standalone]

#1612290

From	Rik van Riel <riel@redhat.com>
Date	2017-03-29 22:20 +0200
Message-ID	<tqseu-3C5-19@gated-at.bofh.it>
In reply to	#1610014

On Wed, 2017-03-29 at 13:16 -0400, Luiz Capitulino wrote:
> On Tue, 28 Mar 2017 13:24:06 -0400
> Luiz Capitulino <lcapitulino@redhat.com> wrote:
> 
> >  1. In my tracing I'm seeing that sometimes (always?) the
> >     time interval between two timer interrupts is less than 1ms
> 
> I think that's the root cause.
> 
> In this trace, we see the following:
> 
>  1. On CPU15, we transition from user-space to kernel-space because
>     of a timer interrupt (it's the tick)
> 
>  2. vtimer_delta() returns 0, because jiffies didn't change since the
>     last accounting
> 
>  3. While CPU15 is executing in kernel-space, jiffies is updated
>     by CPU0
> 
>  4. When going back to user-space, vtime_delta() returns non-zero
>     and the whole time is accounted for system time (observe how
>     the cputime parameter in account_system_time() is less than 1ms)

In other words, the tick on cpu0 is aligned
with the tick on the nohz_full cpus, and
jiffies is advanced while the nohz_full cpus
with an active tick happen to be in kernel
mode?

Frederic, can you think of any reason why
the tick on nohz_full CPUs would end up aligned
with the tick on cpu0, instead of running at some
random offset?

A random offset, or better yet a somewhat randomized
tick length to make sure that simultaneous ticks are
fairly rare and the vtime sampling does not end up
"in phase" with the jiffies incrementing, could make
the accounting work right again.

Of course, that assumes the above hypothesis is correct :)

[toc] | [prev] | [next] | [standalone]

#1612430

From	Frederic Weisbecker <fweisbec@gmail.com>
Date	2017-03-30 01:00 +0200
Message-ID	<tquJj-5gF-7@gated-at.bofh.it>
In reply to	#1612290

(Adding Thomas in Cc)

On Wed, Mar 29, 2017 at 04:08:45PM -0400, Rik van Riel wrote:
> On Wed, 2017-03-29 at 13:16 -0400, Luiz Capitulino wrote:
> > On Tue, 28 Mar 2017 13:24:06 -0400
> > Luiz Capitulino <lcapitulino@redhat.com> wrote:
> > 
> > >  1. In my tracing I'm seeing that sometimes (always?) the
> > >     time interval between two timer interrupts is less than 1ms
> > 
> > I think that's the root cause.
> > 
> > In this trace, we see the following:
> > 
> >  1. On CPU15, we transition from user-space to kernel-space because
> >     of a timer interrupt (it's the tick)
> > 
> >  2. vtimer_delta() returns 0, because jiffies didn't change since the
> >     last accounting
> > 
> >  3. While CPU15 is executing in kernel-space, jiffies is updated
> >     by CPU0
> > 
> >  4. When going back to user-space, vtime_delta() returns non-zero
> >     and the whole time is accounted for system time (observe how
> >     the cputime parameter in account_system_time() is less than 1ms)
> 
> In other words, the tick on cpu0 is aligned
> with the tick on the nohz_full cpus, and
> jiffies is advanced while the nohz_full cpus
> with an active tick happen to be in kernel
> mode?

Ah you found out faster than me :-)

> Frederic, can you think of any reason why
> the tick on nohz_full CPUs would end up aligned
> with the tick on cpu0, instead of running at some
> random offset?

tick_init_jiffy_update() takes that decision to align all ticks.

I'm not sure why. I don't see anything that could depend on that
wide tick synchronization. The jiffies update itself relies on ktime
to check when to update it. So even if the tick fires a bit later
on CPU 1 than on CPU 0, the jiffies updates should stay coherent and
should never exceed 999us delay in the worst case (for HZ=1000)

Now I might overlook something.

> 
> A random offset, or better yet a somewhat randomized
> tick length to make sure that simultaneous ticks are
> fairly rare and the vtime sampling does not end up
> "in phase" with the jiffies incrementing, could make
> the accounting work right again.
> 
> Of course, that assumes the above hypothesis is correct :)

I'm not sure that randomizing the tick start per CPU would be a
right solution. Somewhere in the world you can be sure the tick
randomization of some nohz_full CPU will coincide with the tick
of CPU 0 :o)

Or we could force that tick on nohz_full CPUs to be far from
CPU 0's tick... I'm not sure such a solution would be accepted though.

[toc] | [prev] | [next] | [standalone]

#1613041

From	Rik van Riel <riel@redhat.com>
Date	2017-03-30 15:00 +0200
Message-ID	<tqHQe-6vZ-11@gated-at.bofh.it>
In reply to	#1612430

On Thu, 2017-03-30 at 00:54 +0200, Frederic Weisbecker wrote:
> (Adding Thomas in Cc)
> 
> On Wed, Mar 29, 2017 at 04:08:45PM -0400, Rik van Riel wrote:
> > 
> > Frederic, can you think of any reason why
> > the tick on nohz_full CPUs would end up aligned
> > with the tick on cpu0, instead of running at some
> > random offset?
> 
> tick_init_jiffy_update() takes that decision to align all ticks.
> 
> I'm not sure why. 

I don't see why that would matter, either.

> I'm not sure that randomizing the tick start per CPU would be a
> right solution. Somewhere in the world you can be sure the tick
> randomization of some nohz_full CPU will coincide with the tick
> of CPU 0 :o)
> 
> Or we could force that tick on nohz_full CPUs to be far from
> CPU 0's tick... I'm not sure such a solution would be accepted
> though.

I am not sure we would have to force things.

Simply getting rid of tick_init_jiffy_update
and scheduling the next tick for "now + tick
period" might have the same effect, when the
tick gets stopped and restarted on nohz_full
CPUs.

[toc] | [prev] | [next] | [standalone]

#1612492

From	Wanpeng Li <kernellwp@gmail.com>
Date	2017-03-30 04:00 +0200
Message-ID	<tqxxv-7fz-1@gated-at.bofh.it>
In reply to	#1612290

2017-03-30 4:08 GMT+08:00 Rik van Riel <riel@redhat.com>:
> On Wed, 2017-03-29 at 13:16 -0400, Luiz Capitulino wrote:
>> On Tue, 28 Mar 2017 13:24:06 -0400
>> Luiz Capitulino <lcapitulino@redhat.com> wrote:
>>
>> >  1. In my tracing I'm seeing that sometimes (always?) the
>> >     time interval between two timer interrupts is less than 1ms
>>
>> I think that's the root cause.
>>
>> In this trace, we see the following:
>>
>>  1. On CPU15, we transition from user-space to kernel-space because
>>     of a timer interrupt (it's the tick)
>>
>>  2. vtimer_delta() returns 0, because jiffies didn't change since the
>>     last accounting
>>
>>  3. While CPU15 is executing in kernel-space, jiffies is updated
>>     by CPU0
>>
>>  4. When going back to user-space, vtime_delta() returns non-zero
>>     and the whole time is accounted for system time (observe how
>>     the cputime parameter in account_system_time() is less than 1ms)
>
> In other words, the tick on cpu0 is aligned
> with the tick on the nohz_full cpus, and
> jiffies is advanced while the nohz_full cpus
> with an active tick happen to be in kernel
> mode?
>
> Frederic, can you think of any reason why
> the tick on nohz_full CPUs would end up aligned
> with the tick on cpu0, instead of running at some
> random offset?
>
> A random offset, or better yet a somewhat randomized
> tick length to make sure that simultaneous ticks are
> fairly rare and the vtime sampling does not end up
> "in phase" with the jiffies incrementing, could make
> the accounting work right again.
>
> Of course, that assumes the above hypothesis is correct :)

There is such a feature skew_tick currently, refer to commit
5307c9556bc (tick: add tick skew boot option), w/ skew_tick=1 boot
parameter, the bug disappear, however, the commit also mentioned that
it will hurt power consumption. I will try Frederic's proposal which
is similar to my original idea "how bad would it be to revert to
sched_clock() instead of jiffies in vtime_delta()? We could use
nanosecond granularity to check deltas but only perform an actual
cputime update when that delta >= TICK_NSEC."

Regards,
Wanpeng Li

[toc] | [prev] | [next] | [standalone]

Page 1 of 3 [1] 2 3 Next page →

csiph-web

[BUG nohz]: wrong user and system time accounting

Contents

#1607903 — [BUG nohz]: wrong user and system time accounting

#1608040

#1608051

#1608056

#1608068

#1609456

#1608072

#1609427

#1610014

#1610378

#1611361

#1611370

#1611770

#1611906

#1611368

#1611373

#1612290

#1612430

#1613041

#1612492