| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <20130824195945.44760@gmx.com> Date: Sat, 24 Aug 2013 21:59:45 +0200 From: "Tibor Billes" <tbilles@....com> To: paulmck@...ux.vnet.ibm.com Cc: linux-kernel@...r.kernel.org Subject: Re: Unusually high system CPU usage with recent kernels 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 > 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 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. Tibor -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@...r.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists