[1.] One line summary of the problem: acpi regression first bad commit 02b771b64b73226052d6e731a0987db3b47281e9 [2.] Full description of the problem/report: I found what I believe is a regression on my Gateway ne570 laptop. The problem is reproducible with kernels v4.7-rc7, v4.4.13 and v4.3. I found dmesg and kern.log were filling with messages like this: Jul 10 17:01:10 buus-ne570 kernel: [ 57.741630] ACPI Error: Method reached maximum reentrancy limit (255) (20150818/dsmethod-341) Jul 10 17:01:10 buus-ne570 kernel: [ 57.803775] ACPI Error: Method reached maximum reentrancy limit (255) (20150818/dsmethod-341) Jul 10 17:01:10 buus-ne570 kernel: [ 57.866294] ACPI Error: Method reached maximum reentrancy limit (255) (20150818/dsmethod-341) Jul 10 17:01:10 buus-ne570 kernel: [ 57.928403] ACPI Error: Method reached maximum reentrancy limit (255) (20150818/dsmethod-341) With the latest stable kernel, 4.7-rc7, the ACPI error messages have changed to reflect a newer version, specifically: Jul 16 12:59:18 buus-ne570 kernel: [ 78.862942] ACPI Error: Method reached maximum reentrancy limit (255) (20160422/dsmethod-340) These messages are repeated several times a second, and then pause for several seconds, then start again. I believe they are the cause of more sluggish behavior than with the older kernels. I have also found that if the machine is idle, there's a pause in the "ACPI Error" messages. I think it depends on how much writing to disk is going on, but that's just a gut feeling. I'm not quite sure how to verify that assumption, or if it would help diagnose the problem. I believe the problem is a regression, because it did not occur with kernels v3.16.7, v3.19.8, or v4.2.8. git bisecting the linux-stable kernel led me to this commit: # first bad commit: [02b771b64b73226052d6e731a0987db3b47281e9] ACPI / EC: Fix an issue caused by the serialized _Qxx evaluations commit 02b771b64b73226052d6e731a0987db3b47281e9 Author: Lv Zheng <lv.zheng@intel.com> Date: Wed Aug 12 11:12:02 2015 +0800 ACPI / EC: Fix an issue caused by the serialized _Qxx evaluations It is proven that Windows evaluates _Qxx handlers in a parallel way. This patch follows this fact, splits _Qxx evaluations from the NOTIFY queue to form a separate queue, so that _Qxx evaluations can be queued up on different CPUs rather than being queued up on a CPU0 bound queue. Event handling related callbacks are also renamed and sorted in this patch. Link: https://bugzilla.kernel.org/show_bug.cgi?id=94411 Reported-and-tested-by: Gabriele Mazzotta <gabriele.mzt@gmail.com> Signed-off-by: Lv Zheng <lv.zheng@intel.com> Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com> I can provide an annotated "git bisect log" associating commits from the linux-stable tree with the deb packages I built, installed, and tested to arrive at the "first bad commit". [3.] Keywords (i.e., modules, networking, kernel): [4.] Kernel version (from /proc/version): Linux version 4.7.0-040700rc7-generic (kernel@gloin) (gcc version 5.4.0 20160609 (Ubuntu 5.4.0-6ubuntu1) ) #201607110032 SMP Mon Jul 11 04:34:25 UTC 2016 [5.] Output of Oops.. message (if applicable) with symbolic information resolved (see Documentation/oops-tracing.txt) Not applicable [6.] A small shell script or example program which triggers the problem (if possible) Not applicable [7.] Environment [7.1.] Software (add the output of the ver_linux script here) Linux buus-ne570 4.7.0-040700rc7-generic #201607110032 SMP Mon Jul 11 04:34:25 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux GNU C 5.4.0 GNU Make 4.1 Binutils 2.26.1 Util-linux 2.27.1 Mount 2.27.1 Module-init-tools 22 E2fsprogs 1.42.13 Jfsutils 1.1.15 Pcmciautils 018 PPP 2.4.7 Linux C Library 2.23 Dynamic linker (ldd) 2.23 Linux C++ Library 6.0.21 Procps 3.3.10 Net-tools 1.60 Kbd 1.15.5 Console-tools 1.15.5 Sh-utils 8.25 Udev 229 Wireless-tools 30 Modules Loaded ac acer_wmi ahci ansi_cprng arc4 ath ath3k ath9k ath9k_common ath9k_hw autofs4 battery bluetooth bnep btbcm btintel btrtl btusb button ccm cdrom cfg80211 coretemp crc16 crc32c_intel crc32_pclmul crct10dif_pclmul cryptd ctr dm_mod drbg drm drm_kms_helper efi_pstore efivarfs efivars ehci_hcd ehci_pci evdev ext4 fat fjes fuse ghash_clmulni_intel hid hid_generic hidp hmac i2c_algo_bit i915 intel_cstate intel_powerclamp intel_rapl intel_rapl_perf irqbypass jbd2 jfs joydev kvm kvm_intel libahci libata libphy lp lpc_ich mac80211 mbcache media mei mei_me mfd_core mmc_core nls_cp437 nls_utf8 parport parport_pc ppdev pps_core psmouse ptp rfcomm rfkill scsi_mod sdhci sdhci_pci sd_mod serio_raw sg shpchp snd snd_hda_codec snd_hda_codec_generic snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_core snd_hda_intel snd_hwdep snd_pcm snd_rawmidi snd_seq snd_seq_device snd_seq_midi snd_seq_midi_event snd_timer soundcore sparse_keymap sr_mod tg3 tpm tpm_tis usb_common usbcore uvcvideo vfat video videobuf2_core videobuf2_memops videobuf2_v4l2 videobuf2_vmalloc videodev wmi x86_pkg_temp_thermal xhci_hcd xhci_pci [7.2.] Processor information (from /proc/cpuinfo): Intel(R) Core(TM) i3-3217U CPU @ 1.80GHz I'll provide the full output if you want it. [7.3.] Module information (from /proc/modules): I can provide this if you want it. [7.4.] Loaded driver and hardware information (/proc/ioports, /proc/iomem) I can provide this if you want it. [7.5.] PCI information ('lspci -vvv' as root) I can provide this if you want it. [7.6.] SCSI information (from /proc/scsi/scsi) Doesn't exist. [7.7.] Other information that might be relevant to the problem (please look in /proc and include all information that you think to be relevant): I can provide acpidump output, not sure if I can attach emails sent to linux-acpi list, so I'm not attaching it now. dmi.bios.date: 10/08/2013 dmi.bios.vendor: Insyde Corp. dmi.bios.version: V2.06 dmi.board.asset.tag: Type2 - Board Asset Tag dmi.board.name: EA50_CX dmi.board.vendor: Gateway dmi.board.version: V2.06 dmi.chassis.asset.tag: Acer Asset Tag String dmi.chassis.type: 10 dmi.chassis.vendor: Insyde Corp. dmi.chassis.version: V2.06 dmi.modalias: dmi:bvnInsydeCorp.:bvrV2.06:bd10/08/2013:svnGateway:pnNE570:pvrV2.06:rvnGateway:rnEA50_CX:rvrV2.06:cvnInsydeCorp.:ct10:cvrV2.06: dmi.product.name: NE570 dmi.product.version: V2.06 dmi.sys.vendor: Gateway [X.] Other notes, patches, fixes, workarounds: This machine has the latest UEFI firmware available from the manufacturer, Insyde v2.06. FWIW, I believe the Gateway NE570 is a re-branded Acer Aspire E1-570.
Created attachment 224321 [details] acpidump output
Created attachment 224331 [details] dmidecode output
Created attachment 224341 [details] The boot kernel log
This looks like a different issue that the EC one. It's more about a bug of ACPICA's thread_count, not EC. Let's first do some tests to capture the affected control method. I'll paste a debug patch later. Also please upload /proc/cpuinfo here. Thanks and best regards -Lv
Created attachment 224351 [details] [PATCH] Disable tracer after the culprit is detected 1. Please upload /proc/cpuinfo here. 2. Please apply this patch and build the kernel, then boot the kernel with: acpi.trace_state=enable And upload the dmesg output here. Hope the attached patch can help to reduce the output to obtain what we want. You can also tune the log buffer size with "log_buf_len=" kernel parameter. If you still cannot obtain the full boot log, please just upload the partial one and let me think different debugging approach. Thanks and best regards -Lv
Created attachment 224371 [details] /proc/cpuinfo
Created attachment 224381 [details] Dmesg output with 224351 patch It just occurred to me, I did not CONFIG_ACPI_DEBUG in .config. Maybe I should have? If so, let me know and I will recompile and test.
(In reply to H Buus from comment #7) > Created attachment 224381 [details] > Dmesg output with 224351 patch > > It just occurred to me, I did not CONFIG_ACPI_DEBUG in .config. Maybe I > should have? If so, let me know and I will recompile and test. Yes, you should have CONFIG_ACPI_DEBUG enabled. Sorry that I forgot to mentione. The full documentation of this facility can be found at: Documentation/acpi/method-tracing.txt. Thanks and best regards -Lv
Created attachment 224841 [details] Dmesg with CONFIG_ACPI_DEBUG=y and acpi.trace_state=enabled
I found 380 _Q47 Begin, but only 108 _Q47 End. Thus the "reentrancy limit" error is triggered. However I need to know why, let me think it first. Thanks and best regards -Lv
Created attachment 224951 [details] [PATCH] ACPI / EC: Reduce parallelism for EC _Qxx evaluations Looks like the system_wq is not suitable during the period ACPICA is not improved. Let me work this around using a special workqueue with parallel executions limitted. Please try this patch to see if it can stop the regression. Thanks -Lv
Created attachment 225521 [details] dmesg with ec-paral1.patch That seems to work. The attached dmesg3.out is stitched together from two captures of dmesg output. When I grepped, I got these counts: $ grep -c 'Begin.*_Q47' dmesg3.out 4380 $ grep -c 'End.*_Q47' dmesg3.out 4323 4380-4323=57 looks much better than 380-108=272 After running for over 1820 seconds, I disabled trace_state, especially since I know I have overflowed the dmesg log. That is with log_buf_len=4M. I will keep it running, since the longest it has taken to trigger the regression was after 2140 seconds of uptime. I'll report back in a few hours.
Looking good. The kernel has been running for almost 7 hours, and still no "Method reached maximum reentrancy limit" errors.
However this is still dependent on the number of online cpus. Due to the ACPICA limitation, we could further make the max_active as 2 or configurable when this is upstreamed. In the future, when ACPICA is improved, we can use a greater number. Anyway, thanks for the report. I'll refine the patch and send it to the upstream. In the meanwhile, I'll mark this bug as resolved. Best regards -Lv
(In reply to H Buus from comment #12) > Created attachment 225521 [details] > dmesg with ec-paral1.patch > > That seems to work. The attached dmesg3.out is stitched together from two > captures of dmesg output. When I grepped, I got these counts: > $ grep -c 'Begin.*_Q47' dmesg3.out > 4380 > $ grep -c 'End.*_Q47' dmesg3.out > 4323 > > 4380-4323=57 looks much better than 380-108=272 We should use WQ_UNBOUND here. Please help me to do one more test. I'll post the patch later.
Created attachment 225791 [details] [PATCH] ACPI / EC: Fix a regression by reducing parallel _Qxx evaluations Please try this patch and upload the dmesg output. I want to know if Begin-End can be limited to a reasonable value. If you still can see breakage. Please modify /sys/devices/virtual/workqueue/kec_query/max_alive to help to find a best fit value. Thanks in advance. Best regards -Lv
I won't be able to do this until Wednesday. I assume I should revert the ec-paral1.patch, right?
(In reply to H Buus from comment #17) > I won't be able to do this until Wednesday. That's OK. > I assume I should revert the ec-paral1.patch, right? Yes. :) Thanks -Lv
(In reply to H Buus from comment #17) > I won't be able to do this until Wednesday. I assume I should revert the > ec-paral1.patch, right? No need to do further tests. We just decided to use the version 1 for the Linux upstream. Thanks -Lv
OK. Let me know if you change your mind.
Patch upstreamed: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=e1191bd4f Closing... Thanks