Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1607903 > unrolled thread
| Started by | Luiz Capitulino <lcapitulino@redhat.com> |
|---|---|
| First post | 2017-03-23 22:00 +0100 |
| Last post | 2017-03-27 04:00 +0200 |
| Articles | 8 — 4 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
| 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]
| 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]
| 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]
| 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]
| 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]
| 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]
| 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]
| 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] | [standalone]
Back to top | Article view | linux.kernel
csiph-web