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/ [email protected] [email protected]
signature.asc
Description: Digital signature
-- Ubuntu-release mailing list [email protected] Modify settings or unsubscribe at: https://lists.ubuntu.com/mailman/listinfo/ubuntu-release
