Bug 1055228 - Boot pauses for approx 7 seconds.
Summary: Boot pauses for approx 7 seconds.
Keywords:
Status: CLOSED UPSTREAM
Alias: None
Product: Fedora
Classification: Fedora
Component: kernel
Version: 20
Hardware: Unspecified
OS: Unspecified
unspecified
low
Target Milestone: ---
Assignee: Stanislaw Gruszka
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-01-19 17:17 UTC by Gareth Williams
Modified: 2014-06-13 15:12 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2014-06-13 15:12:58 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
Output of dmesg (70.63 KB, text/plain)
2014-01-19 17:20 UTC, Gareth Williams
no flags Details
dmesg for normal kernel with acpi_no_auto_ssdt option (72.39 KB, text/plain)
2014-01-24 19:00 UTC, Gareth Williams
no flags Details
dmesg for debug kernel with acpi_no_auto_ssdt option (74.02 KB, text/plain)
2014-01-24 19:01 UTC, Gareth Williams
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Linux Kernel 70891 0 None None None Never

Description Gareth Williams 2014-01-19 17:17:03 UTC
Description of problem: Kernel takes over 9 seconds to boot.


Version-Release number of selected component (if applicable): 3.12.7-300, 3.11.10-301


How reproducible: Always


Steps to Reproduce:
1. Boot laptop
2. After login, type 'systemd-analyze' at cmd prompt.
3.

Actual results: Shows approx 9.8 seconds for kernel


Expected results: 1-2 seconds for kernel


Additional info:  This is not a regression on the two kernels mentioned above - it has always been slow on this laptop (approx 2 months old).

Booting with 'acpi_no_auto_ssdt' resolves the boot time issue, but the laptop won't sleep when lid shut.

Comment 1 Gareth Williams 2014-01-19 17:20:56 UTC
Created attachment 852430 [details]
Output of dmesg

Comment 2 Gareth Williams 2014-01-21 18:52:13 UTC
I installed 'kernel-debug' in order to try and use the acpi.debug_level and acpi.debug_layer, but strangely enough, when I boot with this kernel there is no delay!

I've rebooted many times in succession and the result is the same - normal kernel has a delay, while the debug kernel doesn't.  This is with the 3.12.8-300 kernel which arrived today on my laptop.

Comment 3 Stanislaw Gruszka 2014-01-24 18:41:49 UTC
Could you show dmesg on debug-kernel and on normal kernel with acpi_no_auto_ssdt option ?

Comment 4 Gareth Williams 2014-01-24 19:00:29 UTC
Created attachment 855155 [details]
dmesg for normal kernel with acpi_no_auto_ssdt option

Comment 5 Gareth Williams 2014-01-24 19:01:26 UTC
Created attachment 855156 [details]
dmesg for debug kernel with acpi_no_auto_ssdt option

Comment 6 Stanislaw Gruszka 2014-02-13 11:08:15 UTC
I could not find reason of the delay examining source code (ACPICA is terrible mess). Let's try to debug it.

I build standard kernel with just CONFIG_ACPI_DEBUG=y, since all other debug options are disabled, perhaps bug will manifest itself on that kernel:
http://koji.fedoraproject.org/koji/taskinfo?taskID=6521516

If bug is reproducible on it, please provide log output with  "acpi.debug_layer=0xffffffff acip.debug_level=0x0307ff4f" . If that will generate too match or too less output, we will have to tune those mask, but for now let's try them.

Comment 7 Gareth Williams 2014-02-13 20:36:39 UTC
I've managed to install the kernel and boot with it.  I had to set log_buf_len=128M to get data (32M was too small - 64M might have worked).

I had to zip the dmesg file to make it under the 20000Kb limit, but even then, it failed to upload.  I've therefore uploaded the zip to my Dropbox account.  It is available here:- https://dl.dropboxusercontent.com/u/90149727/dmesg.zip

It consists of the dmesg as you requested and dmesg with no extra boot parameters.  I've been using 'grep Interpreter\ Enabled' to spot the delay. You'll notice that there is a delay of about 6 seconds on the standard boot but no delay with the boot options you requested (presumably the 1.8 seconds is due to the extra logging).  In desperation, I tried booting with acpi.debug_level and acpi.debug_layer set to 0x0, but that still had the delay.

If you need any more info, just shout!

Comment 8 Stanislaw Gruszka 2014-02-14 11:00:55 UTC
Thanks for the logs. I hoped that verbose prints will show us where the delay is, but unfortunately they do not. It looks like this is strange race condition, not reproducible if we enable debugging, i.e. when slow down execution of some functions. Let's try to debug mutexes only, perhaps this give some more light on the issue. Please provide logs with "acpi.debug_layer=0xffffffff acip.debug_level=0x03000000"

Comment 9 Gareth Williams 2014-02-14 14:49:44 UTC
All done.  As before, dmesg is zipped and available at https://dl.dropboxusercontent.com/u/90149727/dmesg_mutex.zip

Kind regards.

Comment 10 Stanislaw Gruszka 2014-02-17 13:59:20 UTC
Unfortunately it does not show reason of delay. I'm run out of ideas now, let's report problem to upstream maintainers. They might ask you to install upstream vanilla kernel test patches (or even do bisection maybe), but I not see any other chance to fix the problem. I'll write email to proper maintainers and CC you.

Comment 11 Gareth Williams 2014-02-17 14:06:48 UTC
Thank you for all your help so far.  I've been contemplating installing another distro as a dual-boot in order to check this.  I'll go ahead and install Arch Linux and see what happens there.  I believe that they use vanilla kernels in Arch, so that may shed a light on the issue.

Comment 12 Justin M. Forbes 2014-05-21 19:39:37 UTC
*********** MASS BUG UPDATE **************

We apologize for the inconvenience.  There is a large number of bugs to go through and several of them have gone stale.  Due to this, we are doing a mass bug update across all of the Fedora 20 kernel bugs.

Fedora 20 has now been rebased to 3.14.4-200.fc20.  Please test this kernel update (or newer) and let us know if you issue has been resolved or if it is still present with the newer kernel.

If you experience different issues, please open a new bug report for those.

Comment 13 Gareth Williams 2014-05-22 05:22:57 UTC
I've just booted with kernel 3.14.4-200 and the kernel took 7.562 seconds.  dmesg showed the delay of 5 seconds at the same point, so the newer kernel hasn't fixed the issue.

Comment 14 Gareth Williams 2014-05-22 05:24:03 UTC
Bug 70891 hasn't been worked on for two months.  I've asked for an update...

Comment 15 Gareth Williams 2014-06-13 15:12:58 UTC
After some great support from Lv Zheng, the upstream bug has been marked as RESOLVED_CODE_FIX and will no doubt filter it's way down to Fedora sometime soon.

Thanks for all your help.


Note You need to log in before you can comment on or make changes to this bug.