load >= 1 while idle for no obvious reason with ACPI

[Hanno]

My idling server will stay at load >=1 if ACPI is active, for no obvious reason.

Adding "acpi=off" to grub will resolve this and load falls to 0.0x as expected.

But I use the power button to tell the box to shut down and without ACPI, systemd cannot respond to the power button's ACPI event.

My server is an Acer Easystore H340, that's a small NAS box with four disk bays and an Atom 230 in it. That's standard x86 hardware capable of running x86_64 kernels.

Recently, it was upgraded from 14.10 to 15.04 x86_64. Only after that upgrade did I notice the load >= 1 problem, although it may have been there in previous releases, already.

No idea how to debug this.

To resolve this, I either need
- a way to fix load >= 1 with ACPI
or
- a way to respond to the power button without ACPI

Thanks.
---
AlsaDevices:
 total 0
 crw-rw---- 1 root audio 116, 1 Jul 9 09:24 seq
 crw-rw---- 1 root audio 116, 33 Jul 9 09:24 timer
AplayDevices: Error: [Errno 2] No such file or directory
ApportVersion: 2.17.2-0ubuntu1.1
Architecture: amd64
ArecordDevices: Error: [Errno 2] No such file or directory
AudioDevicesInUse: Error: command ['fuser', '-v', '/dev/snd/seq', '/dev/snd/timer'] failed with exit code 1:
DistroRelease: Ubuntu 15.04
InstallationDate: Installed on 2015-03-16 (115 days ago)
InstallationMedia: Ubuntu-Server 14.04.2 LTS "Trusty Tahr" - Release amd64 (20150218.1)
IwConfig:
 eth0 no wireless extensions.

 lo no wireless extensions.
MachineType: Acer Aspire easyStore H340
Package: linux (not installed)
PciMultimedia:

ProcFB: 0 inteldrmfb
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-3.19.0-22-generic root=UUID=956a13ed-762e-4b00-8688-67f6339d5c37 ro nomdmonddf nomdmonisw nomdmonddf nomdmonisw nomdmonddf nomdmonisw
ProcVersionSignature: Ubuntu 3.19.0-22.22-generic 3.19.8-ckt1
RelatedPackageVersions:
 linux-restricted-modules-3.19.0-22-generic N/A
 linux-backports-modules-3.19.0-22-generic N/A
 linux-firmware 1.143.1
RfKill: Error: [Errno 2] No such file or directory
Tags: vivid vivid
Uname: Linux 3.19.0-22-generic x86_64
UnreportableReason: The report belongs to a package that is not installed.
UpgradeStatus: Upgraded to vivid on 2015-04-24 (76 days ago)
UserGroups:

_MarkForUpload: True
dmi.bios.date: 02/03/2009
dmi.bios.vendor: Phoenix Technologies LTD
dmi.bios.version: P03
dmi.board.asset.tag: 0123456789
dmi.board.name: WG945GCM
dmi.board.vendor: Acer
dmi.board.version: -1
dmi.chassis.asset.tag: No Asset Tag
dmi.chassis.type: 1
dmi.chassis.vendor: Acer
dmi.chassis.version: A
dmi.modalias: dmi:bvnPhoenixTechnologiesLTD:bvrP03:bd02/03/2009:svnAcer:pnAspireeasyStoreH340:pvr-1:rvnAcer:rnWG945GCM:rvr-1:cvnAcer:ct1:cvrA:
dmi.product.name: Aspire easyStore H340
dmi.product.version: -1
dmi.sys.vendor: Acer
---
ApportVersion: 2.17.2-0ubuntu1.1
Architecture: amd64
DistroRelease: Ubuntu 15.04
InstallationDate: Installed on 2015-03-16 (125 days ago)
InstallationMedia: Ubuntu-Server 14.04.2 LTS "Trusty Tahr" - Release amd64 (20150218.1)
Package: linux (not installed)
Tags: vivid
Uname: Linux 3.12.44-031244-generic x86_64
UnreportableReason: The running kernel is not an Ubuntu kernel
UpgradeStatus: Upgraded to vivid on 2015-04-24 (87 days ago)
UserGroups:

_MarkForUpload: True

[Brad Figg (brad-figg)]

This change was made by a bot.

[penalvch (penalvch)]

Hanno, thank you for reporting this and helping make Ubuntu better. Please execute the following command, as it will automatically gather debugging information, in a terminal:
apport-collect 1472293
When reporting bugs in the future please use apport by using 'ubuntu-bug' and the name of the package affected. You can learn more about this functionality at https://wiki.ubuntu.com/ReportingBugs.

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

@penalvch - I have provied the requested info. What can I do to debug this further?

[penalvch (penalvch)]

Hanno, could you please test the latest upstream kernel available from the very top line at the top of the page (the release names are irrelevant for testing, and please do not test the daily folder) following https://wiki.ubuntu.com/Kernel/MainlineBuilds ? It will allow additional upstream developers to examine the issue.

If the test did not allow you to test to the issue (ex. you couldn't boot into the OS) please make a comment in your report about this, and continue to test the next most recent kernel version until you can test to the issue. Once you've tested the upstream kernel, please comment on which kernel version specifically you tested. If this bug is fixed in the mainline kernel, please add the following tags by clicking on the yellow circle with a black pencil icon, next to the word Tags, located at the bottom of the report description:
kernel-fixed-upstream
kernel-fixed-upstream-X.Y-rcZ

Where X, Y, and Z are numbers corresponding to the kernel version.

If the mainline kernel does not fix this bug, please add the following tags:
kernel-bug-exists-upstream
kernel-bug-exists-upstream-X.Y-rcZ

Please note, an error to install the kernel does not fit the criteria of kernel-bug-exists-upstream.

Once testing of the latest upstream kernel is complete, please mark this bug's Status as Confirmed. Please let us know your results.

Thank you for your understanding.

[Hanno (hzulla)]

Thanks for the instructions.

Tested with 4.2.0-040200rc3.201507192329 (http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.2-rc3-unstable/linux-image-4.2.0-040200rc3-generic_4.2.0-040200rc3.201507192329_amd64.deb).

Problem not fixed with that kernel.

As reported before, adding "acpi=off" to grub will fix this and load quickly falls to 0.something and stays near 0. But without ACPI, I cannot use the power button anymore.

[Hanno (hzulla)]

Ok, so...

Tested with 3.14.1 [1]: problem is there :-(
Tested with 3.12.44 [2]: yay, problem not there! :-)
Tested with 3.13.11 [3]: problem is there :-(
Tested with 3.13.0 [4]: problem is there. :-(
Tested with 3.13.0-rc1 [5]: problem is there. :-(

So I can confirm that things work fine with 3.12.44 with ACPI on, while the problem starts to appear with 3.13.0-rc1 and ACPI on.

Let me know how I can investigate this further.

[1] http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.14.1-trusty/linux-image-3.14.1-031401-generic_3.14.1-031401.201404141220_amd64.deb
[2] http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.12.44-trusty/linux-image-3.12.44-031244-generic_3.12.44-031244.201506151235_amd64.deb
[3] http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.13.11.11-trusty/linux-image-3.13.11-03131111-generic_3.13.11-03131111.201411111336_amd64.deb
[4] http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.13-trusty/linux-image-3.13.0-031300-generic_3.13.0-031300.201401192235_amd64.deb
[5] http://kernel.ubuntu.com/~kernel-ppa/mainline/v3.13-rc1-trusty/linux-image-3.13.0-031300rc1-generic_3.13.0-031300rc1.201311221535_amd64.deb

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

apport information

[Hanno (hzulla)]

Hmm. Apport-collect wouldn't let me send the logs for 3.12.44, despite it being an Ubuntu kernel (or is it?)

[Hanno (hzulla)]

please ignore #25. And let me know if you need any other logs from the system while running 3.12.44.

[Hanno (hzulla)]

I was able to bisect the bug.

This is the result.

------------------------------------------

302822996fd572676bb66a7c4351f6faa0e4ddfd is the first bad commit
commit 302822996fd572676bb66a7c4351f6faa0e4ddfd
Author: Liu Chuansheng <email address hidden>
Date: Thu Sep 12 01:42:57 2013 +0800

    ACPI / osl: implement acpi_os_sleep() with msleep()

    Currently, acpi_os_sleep() uses schedule_timeout_interruptible()
    which can be interrupted by a signal, and that causes the real sleep
    time to be shorter.

    According to the ACPI spec:

     The Sleep term is used to implement long-term timing requirements.
     Execution is delayed for at least the required number of milliseconds.

    The sleeping time should be at least the required number msecs, so use
    msleep() which guarantees that to implement it.

    Signed-off-by: Liu Chuansheng <email address hidden>
    Signed-off-by: Rafael J. Wysocki <email address hidden>

:040000 040000 5a0d397cfcbf53c03390f2805b83754cb7837d84 f06197602aac58a9c6f3220232b71fbba2ddd3d2 M drivers

------------------------------------------

git bisect start
# bad: [6ce4eac1f600b34f2f7f58f9cd8f0503d79e42ae] Linux 3.13-rc1
git bisect bad 6ce4eac1f600b34f2f7f58f9cd8f0503d79e42ae
# good: [5e01dc7b26d9f24f39abace5da98ccbd6a5ceb52] Linux 3.12
git bisect good 5e01dc7b26d9f24f39abace5da98ccbd6a5ceb52
# good: [5cbb3d216e2041700231bcfc383ee5f8b7fc8b74] Merge branch 'akpm' (patches from Andrew Morton)
git bisect good 5cbb3d216e2041700231bcfc383ee5f8b7fc8b74
# bad: [e1f56c89b040134add93f686931cc266541d239a] mm: convert mm->nr_ptes to atomic_long_t
git bisect bad e1f56c89b040134add93f686931cc266541d239a
# good: [e21dd863acec8d3bc5166fb2a0c680a9982b37db] Merge branch 'mlx4'
git bisect good e21dd863acec8d3bc5166fb2a0c680a9982b37db
# good: [7f2dc5c4bcbff035b0d03f7aa78a182664b21e47] Merge tag 'dm-3.13-changes' of git://git.kernel.org/pub/scm/linux/kernel/git/device-mapper/linux-dm
git bisect good 7f2dc5c4bcbff035b0d03f7aa78a182664b21e47
# bad: [15d4cb9013ab7cdf10760aeabd07b007d635b321] Merge branch 'pm-cpufreq'
git bisect bad 15d4cb9013ab7cdf10760aeabd07b007d635b321
# good: [fbbcdc0744dace5fcc8147d11c5fb0791126848a] intel_pstate: skip the driver if ACPI has power mgmt option
git bisect good fbbcdc0744dace5fcc8147d11c5fb0791126848a
# bad: [5171f4fa744de840c2c20f5b65bd3ee1cd85d0e8] Merge branch 'acpi-assorted'
git bisect bad 5171f4fa744de840c2c20f5b65bd3ee1cd85d0e8
# good: [31c466c1af229b08bec56c6564b50311d9d660ca] Merge branch 'acpi-conversion'
git bisect good 31c466c1af229b08bec56c6564b50311d9d660ca
# good: [c0ced86d38f418448dce1ca8a825dfd16ee9a23a] Merge branch 'acpi-ipmi'
git bisect good c0ced86d38f418448dce1ca8a825dfd16ee9a23a
# good: [975bcabb05436d8b99214a2293d1d5b9c0b0ca08] Merge branch 'acpi-video'
git bisect good 975bcabb05436d8b99214a2293d1d5b9c0b0ca08
# bad: [e54968ca1eaa78749d7a7fc20227639a31dff629] ACPI / platform: Add ACPI IDs for Intel SST audio device
git bisect bad e54968ca1eaa78749d7a7fc20227639a31dff629
# bad: [16a26e85279fd672050ffc3637038366629e8653] ACPI / EC: Convert all printk() calls to dynamic debug function
git bisect bad 16a26e85279fd672050ffc3637038366629e8...

[Hanno (hzulla)]

Now what?

[Colin Ian King (colin-king)]

Installing perf and running perf-top may show us where abouts all the CPU is being consumed.

[Tim Gardner (timg-tpi)]

Can you further qualify the result of the bisect by building an otherwise unmodified Ubuntu 3.13.0-58.97 kernel with just that commit reverted ? It would also be instructive if you could try the HWE kernel linux-generic-lts-vivid.

[Seth Forshee (sforshee)]

The explanation seems pretty simple. That commit changes the ACPI implementation of the AML sleep operation to use uninterruptible sleep instead of interruptible sleep. Tasks in uninterruptible sleep contribute to load, while those in interruptible sleep do not. So there's no real change in your system load, just a change in how a specific instance of a task sleeping will be accounted for in the load calculation.

Since this code is only executed in response to an AML operation that implies that something in your BIOS is doing a lot of sleeps. If you attach a copy of your ACPI tables we can take a peek and see if we can find out more about the problem. Please run 'sudo acpidump > acpi-tables.txt' and attach acpi-tables.txt to this bug. Thanks!

[Hanno (hzulla)]

Here's the requested acpi table dump.

[Hanno (hzulla)]

perf top - here's a copy of the screen's first lines.

Samples: 1K of event 'cycles', Event count (approx.): 669342282
Overhead Shared Object Symbol
   6,47% [kernel] [k] number.isra.2
   6,18% [kernel] [k] format_decode
   6,17% [kernel] [k] kallsyms_expand_symbol.constprop.1
   5,00% [kernel] [k] vsnprintf
   3,88% [kernel] [k] strnlen
   2,88% [kernel] [k] string.isra.7
   2,76% perf [.] 0x000000000005a0b7
   2,41% libc-2.21.so [.] memchr
   2,29% [kernel] [k] pointer.isra.19
   1,88% libc-2.21.so [.] getdelim
   1,70% perf [.] 0x0000000000061b9c
   1,53% libc-2.21.so [.] 0x000000000014f054
   1,35% libc-2.21.so [.] __libc_calloc
   1,30% libc-2.21.so [.] 0x000000000014de22
   1,24% libc-2.21.so [.] _IO_feof
   1,19% [kernel] [k] apparmor_capable
   0,94% [kernel] [k] seq_read
   0,88% [kernel] [k] module_get_kallsym
   0,82% [kernel] [k] s_show
   0,77% perf [.] 0x0000000000063917
   0,76% [kernel] [k] clear_page
   0,71% [kernel] [k] update_iter
   0,70% perf [.] 0x0000000000061bae
   0,65% [kernel] [k] s_next
   0,59% [kernel] [k] seq_vprintf
   0,59% libc-2.21.so [.] strlen
   0,53% [kernel] [k] copy_user_generic_unrolled
   0,53% perf [.] 0x000000000009f873
   0,41% libc-2.21.so [.] 0x000000000014f058
   0,41% libc-2.21.so [.] 0x000000000008e179
   0,41% libc-2.21.so [.] 0x000000000008e14a
   0,41% perf [.] 0x0000000000063904
   0,41% perf [.] 0x000000000009f899
   0,41% perf [.] 0x000000000009f887
   0,41% perf [.] 0x0000000000061bab
   0,35% libc-2.21.so [.] 0x000000000008e182
   0,35% perf [.] 0x000000000009f884
   0,35% [kernel] [k] rw_verify_area
   0,35% [kernel] [k] strlcpy
   0,35% [kernel] [k] update_wall_time
   0,35% [kernel] [k] memcpy
   0,30% [kernel] [k] cap_capable
Press '?' for help on key bindings

[Hanno (hzulla)]

Tim, I can't quickly build another kernel right now. I'll do what you asked for later, possibly Monday.

[Hanno (hzulla)]

perf top - another one.

Samples: 16K of event 'cycles', Event count (approx.): 161005996
Overhead Shared Object Symbol
   9,01% libslang.so.2.3.0 [.] SLsmg_write_chars
   3,82% libslang.so.2.3.0 [.] SLtt_smart_puts
   3,63% perf [.] 0x000000000005a0b7
   1,98% perf [.] 0x00000000000a729e
   1,29% perf [.] 0x00000000000968c2
   1,24% libc-2.21.so [.] vfprintf
   1,20% [kernel] [k] menu_select
   1,02% perf [.] 0x00000000000a72b4
   0,91% perf [.] 0x00000000000633a5
   0,82% perf [.] 0x0000000000097e85
   0,80% [kernel] [k] acpi_os_read_port
   0,79% perf [.] 0x0000000000097e4f
   0,73% libslang.so.2.3.0 [.] 0x0000000000099dd7
   0,72% libslang.so.2.3.0 [.] 0x0000000000099de5
   0,67% perf [.] 0x00000000000a71e1
   0,62% libslang.so.2.3.0 [.] 0x0000000000099e41
   0,62% perf [.] 0x0000000000095bf7
   0,60% libslang.so.2.3.0 [.] 0x0000000000099dc1
   0,59% [kernel] [k] kmem_cache_alloc
   0,56% libslang.so.2.3.0 [.] SLsmg_write_wrapped_string
   0,55% [kernel] [k] __schedule
   0,54% libslang.so.2.3.0 [.] 0x0000000000099e20
   0,52% perf [.] 0x00000000000a7271
   0,52% [kernel] [k] timerqueue_add
   0,51% [kernel] [k] acpi_os_write_port
   0,51% perf [.] 0x000000000005a08b
   0,47% perf [.] 0x00000000000a72a2
   0,46% perf [.] 0x0000000000097e35
   0,44% [kernel] [k] int_sqrt
   0,41% [kernel] [k] update_blocked_averages
   0,40% [kernel] [k] find_busiest_group
   0,39% perf [.] 0x0000000000097e3f
   0,38% libslang.so.2.3.0 [.] 0x0000000000099dae
   0,38% libslang.so.2.3.0 [.] 0x0000000000099e2e
   0,38% libslang.so.2.3.0 [.] 0x0000000000099e0b
   0,38% libslang.so.2.3.0 [.] 0x0000000000099df5
   0,37% perf [.] 0x0000000000097df0
   0,37% [kernel] [k] enqueue_entity
   0,37% perf [.] 0x00000000000a71f5
   0,37% [kernel] [k] update_curr
   0,36% libslang.so.2.3.0 [.] 0x0000000000099ea7
   0,36% [kernel] [k] run_timer_softirq
no symbols found in /sbin/mdadm, maybe install a debug package?

Is this what you need or do I need to call perf top with different parameters?

[Colin Ian King (colin-king)]

So, there is a 500 ms poll on _PS0, polling on the state of \_SBI.INF which I believe is a Systems Management Interface (SMI) state field:

    Name (FWSO, "FWSO")
    Name (_PSC, 0x00) // _PSC: Power State Current
    Method (_PS0, 0, NotSerialized) // _PS0: Power State 0
    {
        Store (_PSC, Local0)
        Store (0x00, _PSC) /* \_PSC */
        If (LEqual (Local0, 0x03))
        {
            Store (0x01, \_SB.INF)
            While (\_SB.INF)
            {
                Store (0x20, \_SB.BCMD)
                Store (Zero, \_SB.SMIC)

                If (LAnd (LEqual (\_SB.INF, 0x01), LGreaterEqual (\_SB.OSTB, 0x04)))
                {
                    Sleep (0x01F4)
                }
            }
        }
    }

So it is plausible that every SMI may be producing a bunch of sleeps.

GPE L01 is also performing 2 x 100ms sleeps:

        Method (_L01, 0, NotSerialized) // _Lxx: Level-Triggered GPE
        {
            Store (0x01, DEBG) /* \DEBG */
            Sleep (0x64)
            Sleep (0x64)
            If (\_SB.PCI0.EXP1.HPCS)
            {
                If (\_SB.PCI0.EXP1.PDC1)
                {
                    Store (0x01, \_SB.PCI0.EXP1.PDC1)
                }

                If (\_SB.PCI0.EXP1.ABP1)
                {
                    Store (0x01, \_SB.PCI0.EXP1.ABP1)
                }

                Store (0x01, \_SB.PCI0.EXP1.HPCS)
                Notify (\_SB.PCI0.EXP1, 0x01) // Device Check
                If (\_SB.PCI0.EXP1.PDS1)
                {
                    Store (0x21, DEBG) /* \DEBG */
                    If (LEqual (\_SB.PCI0.EXP1.PXS1.X1DV, 0xFFFFFFFF))
                    {
                        Store (0x2F, DEBG) /* \DEBG */
                    }
                }
                Else
                {
                    Store (0x20, DEBG) /* \DEBG */
                }
            }
        }

And GPE L09 is performing a few 300 and 100ms sleeps:

        Method (_L09, 0, NotSerialized) // _Lxx: Level-Triggered GPE
        {
            Store (0x09, DEBG) /* \DEBG */
            Sleep (0x012C)
            Sleep (0x64)
            If (\_SB.PCI0.EXP1.PSP1)
            {
                Store (0x01, \_SB.PCI0.EXP1.PSP1)
                Store (0x01, \_SB.PCI0.EXP1.PMCS)
                Store (0x01, \_SB.PCI0.EXP1.PSP1)
                Notify (\_SB.PCI0.EXP1, 0x02) // Device Wake
            }

            If (\_SB.PCI0.EXP5.PSP5)
            {
                Store (0x01, \_SB.PCI0.EXP5.PSP5)
                Store (0x01, \_SB.PCI0.EXP5.PMCS)
                Notify (\_SB.PCI0.EXP5, 0x02) // Device Wake
            }
        }

..and these General Purpose Event handler are also performing some occasional sleeps too. Once can see how often these GPEs are being triggered using cat /sys/firmware/acpi/interrupts/gpe01 /sys/firmware/acpi/interrupts/gpe09

[Hanno (hzulla)]

cat /sys/firmware/acpi/interrupts/gpe01 /sys/firmware/acpi/interrupts/gpe09

   18137 enabled
       0 disabled

[Hanno (hzulla)]

Tim, I didn't test 3.13.0-58.97 but compiled an Ubuntu 3.19.0-23.24 kernel instead, with the problematic patch reverted.

Can confirm that the load will go back to below 1 with that.

[Hanno (hzulla)]

Thanks, Colin. I'm not familiar with ACPI, so can you please translate this to what I can do to fix this?

The EasyStore 340 isn't supported anymore and the device's BIOS appears to be the last one that was released for it, so I won't be able to have the manufacturer fix the BIOS.

[Colin Ian King (colin-king)]

Hi Hanno,

So, it is most probable that an external general purpose event (GPE) on a pin is causing an ACPI interrupt that services these specific events. Your firmware contains some ACPI AML code that the kernel ACPI driver executes every time that event gets serviced and this AML code performs some sleeps (probably to wait for some hardware to get it's job done) before it services the hardware device associated with that GPE.

As it stands, the machine is idle during those ACPI Sleep() calls (as mentioned by Seth earlier), so your CPU is actually idle and the load average stats are misleading.

[Tim Gardner (timg-tpi)]

Hanno - this appears to be a kernel accounting change. Given your BIOS it is not something we're going to be able to fix.