[steve.langasek at ubuntu.com: Re: [QA] Release Meeting 2012-04-06]

Fri Apr 6 19:01:34 UTC 2012

[Resending to the right kernel team address]

Cc:ing the kernel team; folks, there seems to be some strange behavior in
the kernel that causes our boot speed tests to sometimes turn out much
slower than normal.

On Fri, Apr 06, 2012 at 11:54:49AM +0200, Jean-Baptiste Lallement wrote:
> === Boot speed Testing ===
> http://reports.qa.ubuntu.com/reports/boot-speed/

> 1 run yesterday on AMD64 took 12 seconds more than the average to boot
> http://reports.qa.ubuntu.com/reports/boot-speed/acer-veriton-01/2012-04-05_14-14-20/bootchart.png

> The same occurred on i386 on Mar. 31 (54.66s) and Apr. 01 (49.83s)
> http://reports.qa.ubuntu.com/reports/boot-speed/acer-veriton-01/2012-03-31_11-57-21/bootchart.png
> http://reports.qa.ubuntu.com/reports/boot-speed/acer-veriton-02/2012-03-31_14-25-29/bootchart.png
> http://reports.qa.ubuntu.com/reports/boot-speed/acer-veriton-01/2012-04-01_19-37-05/bootchart.png
> http://reports.qa.ubuntu.com/reports/boot-speed/acer-veriton-02/2012-04-01_15-13-56/bootchart.png

This is very interesting.  Although most of the added time is attributed to
the plumbing layer, when I look at dmesg for the two runs 
(http://reports.qa.ubuntu.com/reports/boot-speed/acer-veriton-01/2012-04-05_14-14-20/dmesg
vs.
http://reports.qa.ubuntu.com/reports/boot-speed/acer-veriton-01/2012-04-05_09-55-24/dmesg)
and vdiff them, it's evident that the slower boot is showing itself to be
slower very early on, starting with:

[    0.004007] Calibrating delay loop (skipped), value calculated using timer frequency.. 3591.01 BogoMIPS (lpj=7182020)
[    0.004018] pid_max: default: 32768 minimum: 301
[    0.004079] Security Framework initialized
[    0.004119] AppArmor: AppArmor initialized

vs.

[    0.008007] Calibrating delay loop (skipped), value calculated using timer frequency.. 3590.99 BogoMIPS (lpj=7181980)
[    0.008018] pid_max: default: 32768 minimum: 301
[    0.008079] Security Framework initialized
[    0.008118] AppArmor: AppArmor initialized

so we start out right off the bat with a 4ms difference in timing, which
grows steadily to 13ms by the time we free the extra memory for the initrd;
then we make up 8ms here...

[    0.506003] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    0.828286] Freeing initrd memory: 13836k freed

[    0.519059] serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
[    0.833537] Freeing initrd memory: 13840k freed

the first substantial difference between the two seems to be with the TSC
calibration:

[    0.000000] Fast TSC calibration using PIT
[    0.000000] Detected 1795.505 MHz processor.

[    0.000000] Fast TSC calibration failed
[    0.000000] TSC: PIT calibration matches HPET. 1 loops
[    0.000000] Detected 1795.495 MHz processor.

Unfortunately on i386 the dmesg log doesn't go all the way to the beginning
of boot, so I can't check for similar differences there.

Then things really start to drift apart as soon as we start looking at the
disk:

[    1.097471] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.143716]  sda: sda1 sda2 < sda5 >
[    1.144710] sd 0:0:0:0: [sda] Attached SCSI disk

[    1.106372] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.168798]  sda: sda1 sda2 < sda5 >
[    1.169777] sd 0:0:0:0: [sda] Attached SCSI disk

and from there on, there's a general pattern of things being slower on the
slow boot than on the fast ones - particularly where I/O is concerned (which
is consistent with what the boot charts show), but even things like driver
initialization are slowed down in comparison.

Do you kernel folks have any idea what could be causing this occasional
slowdown?  It doesn't look like a CPU frequency issue, yet something is
definitely slowing down the whole system.

-- 
Steve Langasek                   Give me a lever long enough and a Free OS
Debian Developer                   to set it on, and I can move the world.
Ubuntu Developer                                    http://www.debian.org/
slangasek at ubuntu.com                                     vorlon at debian.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 828 bytes
Desc: Digital signature
URL: <https://lists.ubuntu.com/archives/ubuntu-release/attachments/20120406/760eda3b/attachment.pgp>