Feeling a bit bored (and waiting for some replies to questions elsewhere) I decided to look and see where all my boot time is going. There are two very obvious pauses in the dmesg output:-
[ 2.934091] ata8: SATA link down (SStatus 0 SControl 300) [ 2.934130] ata7: SATA link down (SStatus 0 SControl 300) [ 18.251024] Adding 9936892k swap on /dev/sda5. Priority:-1 extents:1 across:9936892k [ 20.088037] <30>udev[292]: starting version 167 [ 20.133565] lp: driver loaded but no devices found ... ... ... [ 23.959982] FS-Cache: Loaded [ 24.133173] FS-Cache: Netfs 'nfs' registered for caching [ 24.143427] Installing knfsd (copyright (C) 1996 okir@monad.swb.de). [ 24.353496] type=1400 audit(1323793685.691:10): apparmor="STATUS" operation="profile_replace" na> [ 24.353957] type=1400 audit(1323793685.691:11): apparmor="STATUS" operation="profile_load" name=> [ 34.486168] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,commit=0 [ 36.986993] svc: failed to register lockdv1 RPC service (errno 97). [ 36.987111] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory [ 36.996319] NFSD: starting 90-second grace period ... ... ... [ 38.612346] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 49.294292] eth0: no IPv6 routers present
I don't think that last gap waiting for IPv6 routers is relevant, I can do just about anything before that happens. So, any ideas what may be causing that first 16 second gap and/or the second ten second gap?
On Tue, Dec 13, 2011 at 04:43:51PM +0000, Chris Green wrote:
Feeling a bit bored (and waiting for some replies to questions elsewhere) I decided to look and see where all my boot time is going. There are two very obvious pauses in the dmesg output:-
[ 2.934091] ata8: SATA link down (SStatus 0 SControl 300) [ 2.934130] ata7: SATA link down (SStatus 0 SControl 300) [ 18.251024] Adding 9936892k swap on /dev/sda5. Priority:-1 extents:1 across:9936892k
Swap is turned on by userspace. So the gap is probably coming from whatever your startup scripts are doing at this point.
[ 20.088037] <30>udev[292]: starting version 167 [ 20.133565] lp: driver loaded but no devices found ... ... ... [ 23.959982] FS-Cache: Loaded [ 24.133173] FS-Cache: Netfs 'nfs' registered for caching [ 24.143427] Installing knfsd (copyright (C) 1996 okir@monad.swb.de). [ 24.353496] type=1400 audit(1323793685.691:10): apparmor="STATUS" operation="profile_replace" na> [ 24.353957] type=1400 audit(1323793685.691:11): apparmor="STATUS" operation="profile_load" name=> [ 34.486168] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,commit=0 [ 36.986993] svc: failed to register lockdv1 RPC service (errno 97). [ 36.987111] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory [ 36.996319] NFSD: starting 90-second grace period ... ... ... [ 38.612346] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 49.294292] eth0: no IPv6 routers present
I don't think that last gap waiting for IPv6 routers is relevant, I can do just about anything before that happens. So, any ideas what may be causing that first 16 second gap and/or the second ten second gap?
The IPv6 message will appear when eth0 is configured, again something that's driven by startup scripts. I'm assuming sda1 is /, so the remount is at the point the system has decided it's clean and ready to go.
Given that the pauses are userland driven you're going to need full boot output rather than just dmesg to figure how what's taking the time.
J.
On Tue, Dec 13, 2011 at 09:43:16AM -0800, Jonathan McDowell wrote:
On Tue, Dec 13, 2011 at 04:43:51PM +0000, Chris Green wrote:
Feeling a bit bored (and waiting for some replies to questions elsewhere) I decided to look and see where all my boot time is going. There are two very obvious pauses in the dmesg output:-
[ 2.934091] ata8: SATA link down (SStatus 0 SControl 300) [ 2.934130] ata7: SATA link down (SStatus 0 SControl 300) [ 18.251024] Adding 9936892k swap on /dev/sda5. Priority:-1 extents:1 across:9936892kSwap is turned on by userspace. So the gap is probably coming from whatever your startup scripts are doing at this point.
[ 20.088037] <30>udev[292]: starting version 167 [ 20.133565] lp: driver loaded but no devices found ... ... ... [ 23.959982] FS-Cache: Loaded [ 24.133173] FS-Cache: Netfs 'nfs' registered for caching [ 24.143427] Installing knfsd (copyright (C) 1996 okir@monad.swb.de). [ 24.353496] type=1400 audit(1323793685.691:10): apparmor="STATUS" operation="profile_replace" na> [ 24.353957] type=1400 audit(1323793685.691:11): apparmor="STATUS" operation="profile_load" name=> [ 34.486168] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,commit=0 [ 36.986993] svc: failed to register lockdv1 RPC service (errno 97). [ 36.987111] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory [ 36.996319] NFSD: starting 90-second grace period ... ... ... [ 38.612346] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 49.294292] eth0: no IPv6 routers presentI don't think that last gap waiting for IPv6 routers is relevant, I can do just about anything before that happens. So, any ideas what may be causing that first 16 second gap and/or the second ten second gap?
The IPv6 message will appear when eth0 is configured, again something that's driven by startup scripts. I'm assuming sda1 is /, so the remount is at the point the system has decided it's clean and ready to go.
Given that the pauses are userland driven you're going to need full boot output rather than just dmesg to figure how what's taking the time.
OK, thank you, I'll go and dig around in the user start-up etc.
On Tuesday 13 December 2011 17:52:20 Chris Green wrote:
On Tue, Dec 13, 2011 at 09:43:16AM -0800, Jonathan McDowell wrote:
On Tue, Dec 13, 2011 at 04:43:51PM +0000, Chris Green wrote:
Feeling a bit bored (and waiting for some replies to questions elsewhere) I decided to look and see where all my boot time is going. There are two very obvious pauses in the dmesg output:-
[ 2.934091] ata8: SATA link down (SStatus 0 SControl 300) [ 2.934130] ata7: SATA link down (SStatus 0 SControl 300) [ 18.251024] Adding 9936892k swap on /dev/sda5. Priority:-1extents:1 across:9936892k
Swap is turned on by userspace. So the gap is probably coming from whatever your startup scripts are doing at this point.
[ 20.088037] <30>udev[292]: starting version 167 [ 20.133565] lp: driver loaded but no devices found ... ... ... [ 23.959982] FS-Cache: Loaded [ 24.133173] FS-Cache: Netfs 'nfs' registered for caching [ 24.143427] Installing knfsd (copyright (C) 1996okir@monad.swb.de). [ 24.353496] type=1400 audit(1323793685.691:10): apparmor="STATUS" operation="profile_replace" na> [ 24.353957] type=1400 audit(1323793685.691:11): apparmor="STATUS" operation="profile_load" name=> [ 34.486168] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro,commit=0 [ 36.986993] svc: failed to register lockdv1 RPC service (errno 97). [ 36.987111] NFSD: Using /var/lib/nfs/v4recovery as the NFSv4 state recovery directory [ 36.996319] NFSD: starting 90-second grace period ... ... ... [ 38.612346] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 49.294292] eth0: no IPv6 routers present
I don't think that last gap waiting for IPv6 routers is relevant, I can do just about anything before that happens. So, any ideas what may be causing that first 16 second gap and/or the second ten second gap?
The IPv6 message will appear when eth0 is configured, again something that's driven by startup scripts. I'm assuming sda1 is /, so the remount is at the point the system has decided it's clean and ready to go.
Given that the pauses are userland driven you're going to need full boot output rather than just dmesg to figure how what's taking the time.
OK, thank you, I'll go and dig around in the user start-up etc.
You could try running boot chart: http://www.bootchart.org/
Stuart Bailey BSc (hons) CEng CITP MBCS LinuSoft (Managing Director) Linux Specialist & Software Developer ~~~~~~~~~~~~~~~~~~~~~~~ Phone: (0845) 658 3563 Direct: +44 (0) 1953 878162 Fax: +44 (0) 1603 858583 ~~~~~~~~~~~~~~~~~~~~~~~ http://www.linusoft.co.uk
__________ Information from ESET Mail Security, version of virus signature database 6709 (20111213) __________
The message was checked by ESET Mail Security. http://www.eset.com
On Tue, Dec 13, 2011 at 06:05:19PM +0000, Stuart Bailey wrote:
Given that the pauses are userland driven you're going to need full boot output rather than just dmesg to figure how what's taking the time.
OK, thank you, I'll go and dig around in the user start-up etc.
You could try running boot chart: http://www.bootchart.org/
I seem to remember running that a few years ago, I'll install it and see what it tells me.
-
Chris Green -
Jonathan McDowell -
Stuart Bailey