Re: Very slow boot and sluggish when SERVER changes 4.9 to 4.19

Nick Rickard <ltsp-6wBexXPKtwSGHxnzd0C9Llpr/1R2p/[email protected]> Sat, 31 Aug 2019 12:19:42 +0100
Newsgroups gmane.linux.terminal-server.general
Organization NickRickard
Message-ID <[email protected]>
As a follow-up / conclusion.

Server kernel now updated from 4.19.0-4-amd64 to 4.19.0-5-amd64 and that 
seems to have fixed the issue. The clients boot at normal speed again. 
Nothing obvious in the kernel changelog but 4.19 does seem to have had 
some other network 'wierdness' (dhcp issues) so maybe it was part of a 
wider network issue.

Never completely satisfactory to not know what caused and fixed the 
issue but it's gone for the moment so I won't complain.

Thanks for the hints and suggestions.

Nick.

On 24/04/2019 17:56, Nick Rickard wrote:
>>
>> You don't have the following bits of a normal boot; I'd assume that 
>> Devuan doesn't run the correct init script there:
>> [    7.022171] random: fast init done
>> [   12.916705] random: crng init done
>>
>> This still doesn't explain why a server kernel change introduces this 
>> though.
>>
> 
> Sorry, overzealous pruning of the dmesg. Both those bits do appear (logs 
> below).
> 
> I checked for entropy on client and server with 'cat 
> /proc/sys/kernel/random/entropy_avail' and both seemed okay, but 
> installed 'haveged' on the client and server anyway.
> 
> 
> DMESG for 4.19 chroot, 4.9 server:
> [    0.000000] Linux version 4.19.0-4-amd64 
> ([email protected]) (gcc version 8.3.0 (Debian 8.3.0-2)) #1 
> SMP Debian 4.19.28-2 (2019-03-15)
> [    0.000000] Command line: BOOT_IMAGE=vmlinuz-4.19.0-4-amd64 ro 
> initrd=initrd.img-4.19.0-4-amd64 init=/sbin/init-ltsp quiet 
> root=/dev/nfs ip=dhcp boot=nfs BOOTIF=[IP ADDRESS HIDDEN]
> ...
> [    2.432691] hid-generic 0003:04F2:0402.0003: input,hiddev0,hidraw2: 
> USB HID v1.11 Device [Chicony USB Keyboard] on usb-0000:00:1a.0-1.2/input1
> [    4.882700] r8169 0000:02:00.0 eth0: Link is Up - 1Gbps/Full - flow 
> control rx/tx
> [    4.882710] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> [    5.873810] FS-Cache: Loaded
> [    5.890401] RPC: Registered named UNIX socket transport module.
> [    5.890403] RPC: Registered udp transport module.
> [    5.890404] RPC: Registered tcp transport module.
> [    5.890404] RPC: Registered tcp NFSv4.1 backchannel transport module.
> [    5.905740] FS-Cache: Netfs 'nfs' registered for caching
> [    5.972674] random: fast init done
> [    6.429544] urandom_read: 1 callbacks suppressed
> [    6.429546] random: mktemp: uninitialized urandom read (10 bytes read)
> [    8.408730] udevd[561]: starting version 3.2.7
> [    8.570264] random: udevd: uninitialized urandom read (16 bytes read)
> [    8.574816] random: udevd: uninitialized urandom read (16 bytes read)
> [    8.574839] random: udevd: uninitialized urandom read (16 bytes read)
> [    8.588026] udevd[561]: specified group 'kvm' unknown
> [    8.702769] udevd[561]: starting eudev-3.2.7
> ...
> [    9.098815] random: crng init done
> [    9.098816] random: 2 urandom warning(s) missed due to ratelimiting
> ...
> [   17.045533] Installing knfsd (copyright (C) 1996 [email protected]).
> [   23.035162] elogind-daemon[2126]: New seat seat0.
> [   35.100732] fuse init (API version 7.27)
> 
> 
> 
> DMESG for 4.19 chroot, 4.19 server:
> [    0.000000] Linux version 4.19.0-4-amd64 
> ([email protected]) (gcc version 8.3.0 (Debian 8.3.0-2)) #1 
> SMP Debian 4.19.28-2 (2019-03-15)
> [    0.000000] Command line: BOOT_IMAGE=vmlinuz-4.19.0-4-amd64 ro 
> initrd=initrd.img-4.19.0-4-amd64 init=/sbin/init-ltsp quiet 
> root=/dev/nfs ip=dhcp boot=nfs BOOTIF=[IP ADDRESS HIDDEN]
> ...
> [    2.528667] hid-generic 0003:04F2:0402.0003: input,hiddev0,hidraw2: 
> USB HID v1.11 Device [Chicony USB Keyboard] on usb-0000:00:1a.0-1.2/input1
> [    5.134887] r8169 0000:02:00.0 eth0: Link is Up - 1Gbps/Full - flow 
> control rx/tx
> [    5.134896] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
> [    5.909957] FS-Cache: Loaded
> [    5.926807] RPC: Registered named UNIX socket transport module.
> [    5.926809] RPC: Registered udp transport module.
> [    5.926810] RPC: Registered tcp transport module.
> [    5.926810] RPC: Registered tcp NFSv4.1 backchannel transport module.
> [    5.939861] FS-Cache: Netfs 'nfs' registered for caching
> [    6.450234] random: fast init done
> [   18.093974] urandom_read: 1 callbacks suppressed
> [   18.093976] random: mktemp: uninitialized urandom read (10 bytes read)
> [   39.902701] udevd[559]: starting version 3.2.7
> [   40.083513] random: udevd: uninitialized urandom read (16 bytes read)
> [   40.089447] random: udevd: uninitialized urandom read (16 bytes read)
> [   40.089470] random: udevd: uninitialized urandom read (16 bytes read)
> [   40.135699] udevd[559]: specified group 'kvm' unknown
> [   40.435964] udevd[559]: starting eudev-3.2.7
> ...
> [   41.322721] random: crng init done
> [   41.322723] random: 2 urandom warning(s) missed due to ratelimiting
> ...
> [  103.808955] Installing knfsd (copyright (C) 1996 [email protected]).
> [  185.153199] elogind-daemon[2137]: New seat seat0.
> [  317.835217] fuse init (API version 7.27)
> 
> 
> 
> So clearly the 'random' part is causing an initial pause but the whole 
> boot process is sluggish by a factor of about 5, and this sluggishness 
> continues post login. And the 'random' issue is clearly not entirely 
> happy but the messages between the two startups are identical so I don't 
> think it's a newly introduced issue - sorry for any noise caused. 
> Monitoring the network load between client and server during bootup and 
> usage shows nothing odd, nowhere near the bandwidth so it's not a 
> spurious process flooding the network link. And server load is never 
> troubled.
> 
> So I'm now thinking that for some reason the server is serving the 
> client much slower under 4.19 compared to 4.9. That would explain why 
> the change of server kernel does have an impact for an unchanged chroot. 
> And the first variance in the timestamps comes when the client network 
> is brought up - 5.13sec (4.19) versus 4.88sec (4.9).
> 
> So I'm not sure where to poke next. For the moment I'll stay with 4.9 on 
> the server as I have a working system and see if others experience any 
> similar issues as 4.19 rolls out in the next Debian (and Devuan) release.
> 
> Nick.
> 
> 
> 
> _____________________________________________________________________
> Ltsp-discuss mailing list.   To un-subscribe, or change prefs, goto:
>       https://lists.sourceforge.net/lists/listinfo/ltsp-discuss
> For additional LTSP help,   try #ltsp channel on irc.freenode.net


_____________________________________________________________________
Ltsp-discuss mailing list.   To un-subscribe, or change prefs, goto:
      https://lists.sourceforge.net/lists/listinfo/ltsp-discuss
For additional LTSP help,   try #ltsp channel on irc.freenode.net