Re: Unusually high system CPU usage with recent kernels

From: Paul E. McKenney
Date: Sat Aug 24 2013 - 17:07:22 EST


On Sat, Aug 24, 2013 at 09:59:45PM +0200, Tibor Billes wrote:
> From: Paul E. McKenney Sent: 08/22/13 12:09 AM
> > On Wed, Aug 21, 2013 at 11:05:51PM +0200, Tibor Billes wrote:
> > > > From: Paul E. McKenney Sent: 08/21/13 09:12 PM
> > > > On Wed, Aug 21, 2013 at 08:14:46PM +0200, Tibor Billes wrote:
> > > > > > From: Paul E. McKenney Sent: 08/20/13 11:43 PM
> > > > > > On Tue, Aug 20, 2013 at 10:52:26PM +0200, Tibor Billes wrote:
> > > > > > > > From: Paul E. McKenney Sent: 08/20/13 04:53 PM
> > > > > > > > On Tue, Aug 20, 2013 at 08:01:28AM +0200, Tibor Billes wrote:
> > > > > > > > > Hi,
> > > > > > > > >
> > > > > > > > > I was using the 3.9.7 stable release and tried to upgrade to the 3.10.x series.
> > > > > > > > > The 3.10.x series was showing unusually high (>75%) system CPU usage in some
> > > > > > > > > situations, making things really slow. The latest stable I tried is 3.10.7.
> > > > > > > > > I also tried 3.11-rc5, they both show this behaviour. This behaviour doesn't
> > > > > > > > > show up when the system is idling, only when doing some CPU intensive work,
> > > > > > > > > like compiling with multiple threads. Compiling with only one thread seems not
> > > > > > > > > to trigger this behaviour.
> > > > > > > > >
> > > > > > > > > To be more precise I did a `perf record -a` while compiling a large C++ program
> > > > > > > > > with scons using 4 threads, the result is appended at the end of this email.
> > > > > > > >
> > > > > > > > New one on me! You are running a mainstream system (x86_64), so I am
> > > > > > > > surprised no one else noticed.
> > > > > > > >
> > > > > > > > Could you please send along your .config file?
> > > > > > >
> > > > > > > Here it is
> > > > > >
> > > > > > Interesting. I don't see RCU stuff all that high on the list, but
> > > > > > the items I do see lead me to suspect RCU_FAST_NO_HZ, which has some
> > > > > > relevance to the otherwise inexplicable group of commits you located
> > > > > > with your bisection. Could you please rerun with CONFIG_RCU_FAST_NO_HZ=n?
> > > > > >
> > > > > > If that helps, there are some things I could try.
> > > > >
> > > > > It did help. I didn't notice anything unusual when running with CONFIG_RCU_FAST_NO_HZ=n.
> > > >
> > > > Interesting. Thank you for trying this -- and we at least have a
> > > > short-term workaround for this problem. I will put a patch together
> > > > for further investigation.
> > >
> > > I don't specifically need this config option so I'm fine without it in
> > > the long term, but I guess it's not supposed to behave like that.
> >
> > OK, good, we have a long-term workload for your specific case,
> > even better. ;-)
> >
> > But yes, there are situations where RCU_FAST_NO_HZ needs to work
> > a bit better. I hope you will bear with me with a bit more
> > testing...
> >
> > > > In the meantime, could you please tell me how you were measuring
> > > > performance for your kernel builds? Wall-clock time required to complete
> > > > one build? Number of builds completed per unit time? Something else?
> > >
> > > Actually, I wasn't all this sophisticated. I have a system monitor
> > > applet on my top panel (using MATE, Linux Mint), four little graphs,
> > > one of which shows CPU usage. Different colors indicate different kind
> > > of CPU usage. Blue shows user space usage, red shows system usage, and
> > > two more for nice and iowait. During a normal compile it's almost
> > > completely filled with blue user space CPU usage, only the top few
> > > pixels show some iowait and system usage. With CONFIG_RCU_FAST_NO_HZ
> > > set, about 3/4 of the graph was red system CPU usage, the rest was
> > > blue. So I just looked for a pile of red on my graphs when I tested
> > > different kernel builds. But also compile speed was horrible I couldn't
> > > wait for the build to finish. Even the UI got unresponsive.
> >
> > We have been having problems with CPU accounting, but this one looks
> > quite real.
> >
> > > Now I did some measuring. In the normal case a compile finished in 36
> > > seconds, compiled 315 object files. Here are some output lines from
> > > dstat -tasm --vm during compile:
> > > ----system---- ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- ----swap--- ------memory-usage----- -----virtual-memory----
> > >     time     |usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw | used  free| used  buff  cach  free|majpf minpf alloc  free
> > > 21-08 21:48:05| 91   8   2   0   0   0|   0  5852k|   0     0 |   0     0 |1413  1772 |   0  7934M| 581M 58.0M  602M 6553M|   0    71k   46k   54k
> > > 21-08 21:48:06| 93   6   1   0   0   0|   0  2064k| 137B  131B|   0     0 |1356  1650 |   0  7934M| 649M 58.0M  604M 6483M|   0    72k   47k   28k
> > > 21-08 21:48:07| 86  11   4   0   0   0|   0  5872k|   0     0 |   0     0 |2000  2991 |   0  7934M| 577M 58.0M  627M 6531M|   0    99k   67k   79k
> > > 21-08 21:48:08| 87   9   3   0   0   0|   0  2840k|   0     0 |   0     0 |2558  4164 |   0  7934M| 597M 58.0M  632M 6507M|   0    96k   57k   51k
> > > 21-08 21:48:09| 93   7   1   0   0   0|   0  3032k|   0     0 |   0     0 |1329  1512 |   0  7934M| 641M 58.0M  626M 6469M|   0    61k   48k   39k
> > > 21-08 21:48:10| 93   6   0   0   0   0|   0  4984k|   0     0 |   0     0 |1160  1146 |   0  7934M| 572M 58.0M  628M 6536M|   0    50k   40k   57k
> > > 21-08 21:48:11| 86   9   6   0   0   0|   0  2520k|   0     0 |   0     0 |2947  4760 |   0  7934M| 605M 58.0M  631M 6500M|   0   103k   55k   45k
> > > 21-08 21:48:12| 90   8   2   0   0   0|   0  2840k|   0     0 |   0     0 |2674  4179 |   0  7934M| 671M 58.0M  635M 6431M|   0    84k   59k   42k
> > > 21-08 21:48:13| 90   9   1   0   0   0|   0  4656k|   0     0 |   0     0 |1223  1410 |   0  7934M| 643M 58.0M  638M 6455M|   0    90k   62k   68k
> > > 21-08 21:48:14| 91   8   1   0   0   0|   0  3572k|   0     0 |   0     0 |1432  1828 |   0  7934M| 647M 58.0M  641M 6447M|   0    81k   59k   57k
> > > 21-08 21:48:15| 91   8   1   0   0   0|   0  5116k| 116B    0 |   0     0 |1194  1295 |   0  7934M| 605M 58.0M  644M 6487M|   0    69k   54k   64k
> > > 21-08 21:48:16| 87  10   3   0   0   0|   0  5140k|   0     0 |   0     0 |1761  2586 |   0  7934M| 584M 58.0M  650M 6502M|   0   105k   64k   68k
> > >
> > > The abnormal case compiled only 182 object file in 6 and a half minutes,
> > > then I stopped it. The same dstat output for this case:
> > > ----system---- ----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- ----swap--- ------memory-usage----- -----virtual-memory----
> > >     time     |usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw | used  free| used  buff  cach  free|majpf minpf alloc  free
> > > 21-08 22:10:49| 27  62   0   0  11   0|   0     0 | 210B    0 |   0     0 |1414  3137k|   0  7934M| 531M 57.6M  595M 6611M|   0  1628  1250   322
> > > 21-08 22:10:50| 25  60   4   0  11   0|   0    88k| 126B    0 |   0     0 |1337  3110k|   0  7934M| 531M 57.6M  595M 6611M|   0    91   128   115
> > > 21-08 22:10:51| 26  63   0   0  11   0|   0   184k| 294B    0 |   0     0 |1411  3147k|   0  7934M| 531M 57.6M  595M 6611M|   0  1485   814   815
> > > 21-08 22:10:52| 26  63   0   0  11   0|   0     0 | 437B  239B|   0     0 |1355  3160k|   0  7934M| 531M 57.6M  595M 6611M|   0    24    94    97
> > > 21-08 22:10:53| 26  63   0   0  11   0|   0     0 | 168B    0 |   0     0 |1397  3155k|   0  7934M| 531M 57.6M  595M 6611M|   0   479   285   273
> > > 21-08 22:10:54| 26  63   0   0  11   0|   0  4096B| 396B  324B|   0     0 |1346  3154k|   0  7934M| 531M 57.6M  595M 6611M|   0    27   145   145
> > > 21-08 22:10:55| 26  63   0   0  11   0|   0    60k|   0     0 |   0     0 |1353  3148k|   0  7934M| 531M 57.6M  595M 6610M|   0    93   117    36
> > > 21-08 22:10:56| 26  63   0   0  11   0|   0     0 |   0     0 |   0     0 |1341  3172k|   0  7934M| 531M 57.6M  595M 6610M|   0   158    87    74
> > > 21-08 22:10:57| 26  62   1   0  11   0|   0     0 |  42B   60B|   0     0 |1332  3162k|   0  7934M| 531M 57.6M  595M 6610M|   0    56    82    78
> > > 21-08 22:10:58| 26  63   0   0  11   0|   0     0 |   0     0 |   0     0 |1334  3178k|   0  7934M| 531M 57.6M  595M 6610M|   0    26    56    56
> > > 21-08 22:10:59| 26  63   0   0  11   0|   0     0 |   0     0 |   0     0 |1336  3179k|   0  7934M| 531M 57.6M  595M 6610M|   0     3    33    32
> > > 21-08 22:11:00| 26  63   0   0  11   0|   0    24k|  90B  108B|   0     0 |1347  3172k|   0  7934M| 531M 57.6M  595M 6610M|   0    41    73    71
> > >
> > > I have four logical cores so 25% makes up 1 core. I don't know if the ~26% user CPU usage has anthing to do with this fact or just coincidence. The rest is ~63% system and ~11% hardware interrupt. Do these support what you suspect?
> >
> > The massive increase in context switches does come as a bit of a surprise!
> > It does rule out my initial suspicion of lock contention, but then again
> > the fact that you have only four CPUs made that pretty unlikely to begin
> > with.
> >
> > 2.4k average context switches in the good case for the full run vs. 3,156k
> > for about half of a run in the bad case. That is an increase of more
> > than three orders of magnitude!
> >
> > Yow!!!
> >
> > Page faults are actually -higher- in the good case. You have about 6.5GB
> > free in both cases, so you are not running out of memory. Lots more disk
> > writes in the good case, perhaps consistent with its getting more done.
> > Networking is negligible in both cases.
> >
> > Lots of hardware interrupts in the bad case as well. Would you be willing
> > to take a look at /proc/interrupts before and after to see which one you
> > are getting hit with? (Or whatever interrupt tracking tool you prefer.)
>
> Here are the results.
>
> Good case before:
>           CPU0       CPU1       CPU2       CPU3      
>  0:         17          0          0          0   IO-APIC-edge      timer
>  1:        356          1         68          4   IO-APIC-edge      i8042
>  8:          0          0          1          0   IO-APIC-edge      rtc0
>  9:        330         14        449         71   IO-APIC-fasteoi   acpi
> 12:         10        108        269       2696   IO-APIC-edge      i8042
> 16:         36         10        111          2   IO-APIC-fasteoi   ehci_hcd:usb1
> 17:         20          3         25          4   IO-APIC-fasteoi   mmc0
> 21:          3          0         34          0   IO-APIC-fasteoi   ehci_hcd:usb2
> 40:          0          1         12         11   PCI-MSI-edge      mei_me
> 41:      10617        173       9959        292   PCI-MSI-edge      ahci
> 42:        862         11        186         26   PCI-MSI-edge      xhci_hcd
> 43:        107         77         27        102   PCI-MSI-edge      i915
> 44:       5322         20        434         22   PCI-MSI-edge      iwlwifi
> 45:        180          0        183         86   PCI-MSI-edge      snd_hda_intel
> 46:          0          3          0          0   PCI-MSI-edge      eth0
> NMI:          1          0          0          0   Non-maskable interrupts
> LOC:      16312      15177      10840       8995   Local timer interrupts
> SPU:          0          0          0          0   Spurious interrupts
> PMI:          1          0          0          0   Performance monitoring interrupts
> IWI:       1160        523       1031        481   IRQ work interrupts
> RTR:          3          0          0          0   APIC ICR read retries
> RES:      14976      16135       9973      10784   Rescheduling interrupts
> CAL:        482        457        151        370   Function call interrupts
> TLB:         70        106        352        230   TLB shootdowns
> TRM:          0          0          0          0   Thermal event interrupts
> THR:          0          0          0          0   Threshold APIC interrupts
> MCE:          0          0          0          0   Machine check exceptions
> MCP:          2          2          2          2   Machine check polls
> ERR:          0
> MIS:          0
>
> Good case after:
>           CPU0       CPU1       CPU2       CPU3      
>  0:         17          0          0          0   IO-APIC-edge      timer
>  1:        367          1         81          4   IO-APIC-edge      i8042
>  8:          0          0          1          0   IO-APIC-edge      rtc0
>  9:        478         14        460         71   IO-APIC-fasteoi   acpi
> 12:         10        108        269       2696   IO-APIC-edge      i8042
> 16:         36         10        111          2   IO-APIC-fasteoi   ehci_hcd:usb1
> 17:         20          3         25          4   IO-APIC-fasteoi   mmc0
> 21:          3          0         34          0   IO-APIC-fasteoi   ehci_hcd:usb2
> 40:          0          1         12         11   PCI-MSI-edge      mei_me
> 41:      16888        173       9959        292   PCI-MSI-edge      ahci
> 42:       1102         11        186         26   PCI-MSI-edge      xhci_hcd
> 43:        107        132         27        136   PCI-MSI-edge      i915
> 44:       6943         20        434         22   PCI-MSI-edge      iwlwifi
> 45:        180          0        183         86   PCI-MSI-edge      snd_hda_intel
> 46:          0          3          0          0   PCI-MSI-edge      eth0
> NMI:          4          3          3          3   Non-maskable interrupts
> LOC:      26845      24780      19025      17746   Local timer interrupts
> SPU:          0          0          0          0   Spurious interrupts
> PMI:          4          3          3          3   Performance monitoring interrupts
> IWI:       1637        751       1287        695   IRQ work interrupts
> RTR:          3          0          0          0   APIC ICR read retries
> RES:      26511      26673      18791      20194   Rescheduling interrupts
> CAL:        510        480        151        370   Function call interrupts
> TLB:        361        292        575        461   TLB shootdowns
> TRM:          0          0          0          0   Thermal event interrupts
> THR:          0          0          0          0   Threshold APIC interrupts
> MCE:          0          0          0          0   Machine check exceptions
> MCP:          2          2          2          2   Machine check polls
> ERR:          0
> MIS:          0
>
> Bad case before:
>           CPU0       CPU1       CPU2       CPU3      
>  0:         17          0          0          0   IO-APIC-edge      timer
>  1:        172          3         78          3   IO-APIC-edge      i8042
>  8:          0          1          0          0   IO-APIC-edge      rtc0
>  9:       1200        148        395         81   IO-APIC-fasteoi   acpi
> 12:       1625          2        348         10   IO-APIC-edge      i8042
> 16:         26         23        115          0   IO-APIC-fasteoi   ehci_hcd:usb1
> 17:         16          3         12         21   IO-APIC-fasteoi   mmc0
> 21:          2          2         33          0   IO-APIC-fasteoi   ehci_hcd:usb2
> 40:          0          0         14         10   PCI-MSI-edge      mei_me
> 41:      15776        374       8497        687   PCI-MSI-edge      ahci
> 42:       1297        829        115         24   PCI-MSI-edge      xhci_hcd
> 43:        103        149          9        212   PCI-MSI-edge      i915
> 44:      13151        101        511         91   PCI-MSI-edge      iwlwifi
> 45:        153        159          0        122   PCI-MSI-edge      snd_hda_intel
> 46:          0          1          1          0   PCI-MSI-edge      eth0
> NMI:         32         31         31         31   Non-maskable interrupts
> LOC:      82504      82732      74172      75985   Local timer interrupts
> SPU:          0          0          0          0   Spurious interrupts
> PMI:         32         31         31         31   Performance monitoring interrupts
> IWI:      17816      16278      13833      13282   IRQ work interrupts
> RTR:          3          0          0          0   APIC ICR read retries
> RES:      18784      21084      13313      12946   Rescheduling interrupts
> CAL:        393        422        306        356   Function call interrupts
> TLB:        231        176        235        191   TLB shootdowns
> TRM:          0          0          0          0   Thermal event interrupts
> THR:          0          0          0          0   Threshold APIC interrupts
> MCE:          0          0          0          0   Machine check exceptions
> MCP:          3          3          3          3   Machine check polls
> ERR:          0
> MIS:          0
>
> Bad case after:
>           CPU0       CPU1       CPU2       CPU3      
>  0:         17          0          0          0   IO-APIC-edge      timer
>  1:        415          3         85          3   IO-APIC-edge      i8042
>  8:          0          1          0          0   IO-APIC-edge      rtc0
>  9:       1277        148        428         81   IO-APIC-fasteoi   acpi
> 12:       1625          2        348         10   IO-APIC-edge      i8042
> 16:         26         23        115          0   IO-APIC-fasteoi   ehci_hcd:usb1
> 17:         16          3         12         21   IO-APIC-fasteoi   mmc0
> 21:          2          2         33          0   IO-APIC-fasteoi   ehci_hcd:usb2
> 40:          0          0         14         10   PCI-MSI-edge      mei_me
> 41:      17814        374       8497        687   PCI-MSI-edge      ahci
> 42:       1567        829        115         24   PCI-MSI-edge      xhci_hcd
> 43:        103        177          9        242   PCI-MSI-edge      i915
> 44:      14956        101        511         91   PCI-MSI-edge      iwlwifi
> 45:        153        159          0        122   PCI-MSI-edge      snd_hda_intel
> 46:          0          1          1          0   PCI-MSI-edge      eth0
> NMI:         36         35         34         34   Non-maskable interrupts
> LOC:      92429      92708      81714      84071   Local timer interrupts
> SPU:          0          0          0          0   Spurious interrupts
> PMI:         36         35         34         34   Performance monitoring interrupts
> IWI:      22594      19658      17439      14257   IRQ work interrupts
> RTR:          3          0          0          0   APIC ICR read retries
> RES:      21491      24670      14618      14569   Rescheduling interrupts
> CAL:        441        439        306        356   Function call interrupts
> TLB:        232        181        274        465   TLB shootdowns
> TRM:          0          0          0          0   Thermal event interrupts
> THR:          0          0          0          0   Threshold APIC interrupts
> MCE:          0          0          0          0   Machine check exceptions
> MCP:          3          3          3          3   Machine check polls
> ERR:          0
> MIS:          0

Lots more local timer interrupts, which is consistent with the higher
time in interrupt handlers for the bad case.

> > One hypothesis is that your workload and configuration are interacting
> > with RCU_FAST_NO_HZ to force very large numbers of RCU grace periods.
> > Could you please check for this by building with CONFIG_RCU_TRACE=y,
> > mounting debugfs somewhere and dumping rcu/rcu_sched/rcugp before and
> > after each run?
>
> Good case before:
> completed=8756  gpnum=8757  age=0  max=21
> after:
> completed=14686  gpnum=14687  age=0  max=21
>
> Bad case before:
> completed=22970  gpnum=22971  age=0  max=21
> after:
> completed=26110  gpnum=26111  age=0  max=21

In the good case, (14686-8756)/40=148.25 grace periods per second, which
is a fast but reasonable rate given your HZ=250. Not a large difference
in the number of grace periods, but extrapolating for the longer runtime,
maybe ten times as much. But not much change in grace-period rate per
unit time.

> The test scenario was the following in both cases (mixed english and pseudo-bash):
> reboot, login, start terminal
> cd project
> rm -r build
> cat /proc/interrupts >> somefile ; cat /sys/kernel/debug/rcu/rcu_sched/rcugp >> somefile
> scons -j4
> wait ~40 sec (good case finished, Ctrl-C in bad case)
> cat /proc/interrupts >> somefile ; cat /sys/kernel/debug/rcu/rcu_sched/rcugp >> somefile
>
> I stopped the build in the bad case after about the same time the good
> case finished, so the extra interrupts and RCU grace periods because of the
> longer runtime don't fake the results.

That procedure works for me, thank you for laying it out carefully.

I believe I see what is going on and how to fix it, though it may take
me a bit to work things through and get a good patch.

Thank you very much for your testing efforts!

Thanx, Paul

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/