Bug 217247 - [acpi] r265474 makes 11.0R unusable with Atom 330
Summary: [acpi] r265474 makes 11.0R unusable with Atom 330
Status: New
Alias: None
Product: Base System
Classification: Unclassified
Component: kern (show other bugs)
Version: 11.0-RELEASE
Hardware: amd64 Any
: --- Affects Only Me
Assignee: freebsd-acpi mailing list
URL:
Keywords: regression
Depends on:
Blocks:
 
Reported: 2017-02-20 10:25 UTC by Stéphane Lesimple
Modified: 2017-03-13 18:49 UTC (History)
2 users (show)

See Also:


Attachments
verbose dmesg of HEAD (r314326) (52.89 KB, text/plain)
2017-02-27 22:42 UTC, Stéphane Lesimple
no flags Details
sysctl from HEAD (1.57 KB, text/plain)
2017-02-28 19:41 UTC, Stéphane Lesimple
no flags Details
verbose dmesg of 11.0R (54.49 KB, text/plain)
2017-02-28 19:45 UTC, Stéphane Lesimple
no flags Details
sysctl from 11.0R (1.92 KB, text/plain)
2017-02-28 19:47 UTC, Stéphane Lesimple
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Stéphane Lesimple 2017-02-20 10:25:48 UTC
After upgrading my FreeBSD-based firewall from 10.3R to 11.0R, the boot time (from power-on to the login prompt) rocketed from ~1 minute to more than 45 minutes, and even when up, the system was extremely slow. The loadavg was >2, with no process really taking that much CPU time, and the number of IRQ was not too high (200-300 per sec) even if 20% of the time was spent in IRQ.

To rule out any oddity with my system config, I reproduced the problem with the bare official FreeBSD-10.3-RELEASE-amd64-memstick.img where the kernel takes 20s to boot, and FreeBSD-11.0-RELEASE-amd64-memstick.img takes more than 8 minutes, from "Booting..." to the login prompt.

So, it took me several days of manual bisecting-compiling-memstick-booting, and I finally found the culprit: base r265474

The diff is pretty straightforward, in /etc/defaults/rc.conf:

-performance_cx_lowest="HIGH"    # Online CPU idle state
+performance_cx_lowest="Cmax"    # Online CPU idle state
-economy_cx_lowest="HIGH"        # Offline CPU idle state
+economy_cx_lowest="Cmax"        # Offline CPU idle state

If I override these values by putting HIGH back in /etc/rc.conf.local, the problem disappears.

I was able to manually confirm that if I set dev.cpu.N.cx_lowest to C2 (or C3), the system is horribly slow and sluggish, and back to C1 ("HIGH"), it's usable again.

The commit message indicates that "This may not stay through 11.0-RELEASE, but at least having it on by default in -HEAD will expose (more) issues with broken hardware", so I guess my hardware is broken, even if I didn't observe such behavior previously under other OSes (namely Linux). I can imagine that anybody else booting FreeBSD 11.0 under such hardware would just give up, so it might be a good idea to detect this CPU on install and keep cx_lowest at C1?

root@fw:~ # sysctl hw.machine hw.model dev.cpu.0
hw.machine: amd64
hw.model: Intel(R) Atom(TM) CPU  330   @ 1.60GHz
dev.cpu.0.cx_method: C1/hlt C2/io C3/io
dev.cpu.0.cx_usage_counters: 10731 0 0
dev.cpu.0.cx_usage: 100.00% 0.00% 0.00% last 4432us
dev.cpu.0.cx_lowest: C1
dev.cpu.0.cx_supported: C1/1/0 C2/2/1 C3/3/85
dev.cpu.0.%parent: acpi0
dev.cpu.0.%pnpinfo: _HID=none _UID=0
dev.cpu.0.%location: handle=\_PR_.P001
dev.cpu.0.%driver: cpu
dev.cpu.0.%desc: ACPI CPU
Comment 1 Stéphane Lesimple 2017-02-20 10:28:08 UTC
Adding the commit author, adrian, in CC
Comment 2 Adrian Chadd freebsd_committer 2017-02-27 00:49:40 UTC
it sounds like something is broken with that sleep state handling. can you check the latest -head and see if it behaves any better/differently?
Comment 3 Konstantin Belousov freebsd_committer 2017-02-27 08:45:11 UTC
(In reply to Stéphane Lesimple from comment #0)
Please provide a verbose dmesg of the boot, and output of sysctl kern.timecounter kern.eventtimer for 10.3 and 11.0.

I am somewhat skeptical WRT the exact commit which you blame, since rc.conf settings cannot affect earliest boot, but you noted that the boot is slow.
Comment 4 Stéphane Lesimple 2017-02-27 19:15:58 UTC
(In reply to Adrian Chadd from comment #2)

Compiled HEAD this morning, namely base r314326 and booted it.
It does behave differently: at boot I couldn't observe the slowdown.

However after some digging, I found out that HEAD's /etc/default/rc.conf is different and now contains:

> performance_cx_lowest="NONE"

Where 11.0R contained

> performance_cx_lowest="Cmax"

(introduced by base r265474)

On my system, NONE translates to C1, as shown by sysctl -a, so that's why it behaves properly: it never tries to use C2 or C3.

I tried to manually set dev.cpu.X.cx_lowest to C2, and see if the slowdown was still there, but it wasn't. However sysctl indicates that my setting is completely ignored and the system always uses C1, as seen by cx_usage:

dev.cpu.0.cx_method: C1/hlt C2/io C3/io
dev.cpu.0.cx_usage_counters: 4617 0 0
dev.cpu.0.cx_usage: 100.00% 0.00% 0.00% last 49467us
dev.cpu.0.cx_lowest: C2
dev.cpu.0.cx_supported: C1/1/0 C2/2/1 C3/3/85
dev.cpu.0.%parent: acpi0
dev.cpu.0.%pnpinfo: _HID=none _UID=0
dev.cpu.0.%location: handle=\_PR_.P001
dev.cpu.0.%driver: cpu
dev.cpu.0.%desc: ACPI CPU

So this *is* indeed different from 11.0R. For some reason the kernel now chooses to keep C1 at all times, even if I tell it that C2 is okay. If you want me to try anything, just ask, I'm keeping HEAD's memstick.img around just in case.
Comment 5 Stéphane Lesimple 2017-02-27 19:27:12 UTC
(In reply to Konstantin Belousov from comment #3)

You're right, the early stage of the boot is the same between 10.3 and 11.0. The massive slowdown starts somewhat late in the boot process. What I called "boot process" here is timed from the "Booting..." message (right after the kernel is loaded) up to the moment where ttyv0 shows the "login:" prompt. Those two moments are easier to measure with a stopwatch. So this probably includes the start time of most (limited) userland stuff from the bare release memstick image, run with the "livecd" option.

Does that sounds more reasonable? In any case, I can for sure provide dmesgs and kern.{eventtimer,timecounter} for 10.3 and 11.0.
Comment 6 Konstantin Belousov freebsd_committer 2017-02-27 19:56:00 UTC
(In reply to Stéphane Lesimple from comment #5)
Since you have HEAD kernel, most interesting is the verbose dmesg from HEAD boot and sysctls from there.
Comment 7 Stéphane Lesimple 2017-02-27 22:42:36 UTC
Created attachment 180350 [details]
verbose dmesg of HEAD (r314326)

Here you go. This is the dmesg of a verbose boot under HEAD.

Note that as stated above, with this kernel, cx_lowest is set at C1 on bootup, and that even if manually set to C2 or more, 100% of the time is still spent in C1 for some reason.

If you think a verbose dmesg of 10.3R and/or 11.0R would be of use, just ask.
Comment 8 Konstantin Belousov freebsd_committer 2017-02-28 15:23:54 UTC
(In reply to Stéphane Lesimple from comment #7)
I also asked for sysctl output.

From what I see in the dmesg, your CPU's LAPIC does not work in C2/C3.  The fact that TSC is also not invariant forced the kernel to disable C2/C3 entrance, which you noted as well.

There is also r309189 which downgrades LAPIC eventtimer quality.  I am not sure that the commit is important for your machine, since it refuses to enter C2 at all.

Yes, I probably also want to see verbose dmesg and sysctl output for 11.0.  I might provide a recipe to restore C2/C3 usage after I see the data.
Comment 9 Stéphane Lesimple 2017-02-28 19:41:06 UTC
Created attachment 180369 [details]
sysctl from HEAD

Here is the previously missing sysctl output from a freshly booted HEAD
Comment 10 Stéphane Lesimple 2017-02-28 19:45:46 UTC
Created attachment 180372 [details]
verbose dmesg of 11.0R

Verbose dmesg of 11.0R (official memstick.img)
Comment 11 Stéphane Lesimple 2017-02-28 19:47:38 UTC
Created attachment 180373 [details]
sysctl from 11.0R

sysctl output from 11.0R, including dev.cpu.0 if it's of any use.

Note that due to the bug, the sysctl output is from roughly 8 minutes after boot (as reported by `uptime')
Comment 12 Konstantin Belousov freebsd_committer 2017-02-28 19:47:50 UTC
(In reply to Stéphane Lesimple from comment #9)
Do you have anything in loader.conf related to HPETs ?  You have HPET registered for timecounter, but not for eventtimer, which is weird.
Comment 13 Stéphane Lesimple 2017-02-28 20:23:39 UTC
(In reply to Konstantin Belousov from comment #12)

I don't, `grep -i hpet /boot/defaults/loader.conf /boot/loader.conf` returns zero lines on my HEAD test build.
Comment 14 Stéphane Lesimple 2017-03-13 18:49:49 UTC
Some new data points:

The oldest version I could try, 8.0-RELEASE, behaves the same with C2 as in any more recent version (up to HEAD). This problem was hidden before due to the cx_lowest default always being C1 up to 11.0R.

I also noticed that when C2 is set as cx_lowest, C1 is not used at all. Another interesting behavior is that the cx_usage_counters increases 10 times faster with C2 than with C1.
It might also be interesting to note that C3 is ignored even if advertised as supported (which is probably irrelevant to this bug).

# sysctl dev.cpu.0.cx_lowest=C1 ; sleep 10 ; sysctl dev.cpu.0.cx_usage_counters
dev.cpu.0.cx_lowest: C1 -> C1
dev.cpu.0.cx_usage_counters: 1192 0 0

# sysctl dev.cpu.0.cx_lowest=C2 ; sleep 10 ; sysctl dev.cpu.0.cx_usage_counters
dev.cpu.0.cx_lowest: C1 -> C2
dev.cpu.0.cx_usage_counters: 0 11122 0

# sysctl dev.cpu.0.cx_lowest=C3 ; sleep 10 ; sysctl dev.cpu.0.cx_usage_counters
dev.cpu.0.cx_lowest: C2 -> C3
dev.cpu.0.cx_usage_counters: 0 11048 0