[systemd-devel] Long waiting for swap device

[Nikolai Zhubr]

Hi,

Please disregard. The delay in question was not caused by swap.
Probably I'll come back for advice later when I gather more info.
Still in progress.


Thank you.
Nikolai

07.01.2015 20:59, me wrote:
> Hi,
>
> Looking at bootlog console messages, I noticed something strange.
> systemd says:
>
> Expecting device dev-disk-by-x2duuid-4c25...
> ... and soon adds:
> A start job is running for dev-disk-by-x2duuid-4c25...
> ... and it keeps waiting for some seconds.
> Also, "systemd-analyze blame" lists "dev-disk-by-x2duuid-4c25..." among
> top time-eaters.
>
> The "uuid-4c25..." device is actually a swap partition (specified in
> fstab), so systemd is correct that this device needs to appear and be
> activeted as swap. If it matters, swap is located on raid1 device
> (/dev/md1) which consists of /dev/sda5 and /dev/sdb5, while physical
> disks sda and sdb are just regular sata harddisks of equal geometry.
>
> However, AFAICS the said "uuid-4c25..." device is already present before
> the "Expecting device ..." message appears. I think this can also be
> illustrated by journalctl | grep 4c25:
> ---------------- cut ----------------
> 17:36:56 kernel: Kernel command line:
> BOOT_IMAGE=/boot/vmlinuz-3.16.6-2-desktop
> root=UUID=588d9a9c-4c4e-4400-9e2b-a79f5fce670e
> resume=/dev/disk/by-uuid/4c25dd37-c555-4fbf-8349-f1470d0e924c
> systemd.log_level=debug showopts vga=normal
> 17:36:56 systemd[1]: Installed new job
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.device/start
> as 34
> 17:36:56 systemd[1]: Expecting device
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.device...
>
> 17:36:57 systemd[1]:
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.device
> changed dead -> plugged
> 17:36:57 systemd[1]: Job
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.device/start
> finished, result=done
> 17:36:57 systemd[1]: Found device
> /dev/disk/by-uuid/4c25dd37-c555-4fbf-8349-f1470d0e924c.
> 17:36:58 systemd[1]:
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.device
> changed dead -> plugged
> 17:37:11 systemd[1]: Installed new job
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.swap/start
> as 122
> 17:37:11 systemd[1]: Installed new job
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.device/start
> as 123
> 17:37:12 systemd[1]: Merged into installed job
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.swap/start
> as 122
> 17:37:12 systemd[1]: Merged into installed job
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.device/start
> as 123
> 17:37:18 systemd[1]:
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.swap changed
> dead -> activating
> 17:37:13 systemd[1]:
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.device
> changed dead -> plugged
> 17:37:13 systemd[1]: Job
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.device/start
> finished, result=done
> 17:37:13 systemd[1]: Found device
> /dev/disk/by-uuid/4c25dd37-c555-4fbf-8349-f1470d0e924c.
> 17:37:18 systemd[632]: Executing: /sbin/swapon
> /dev/disk/by-uuid/4c25dd37-c555-4fbf-8349-f1470d0e924c
> 17:37:18 systemd[1]:
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.swap changed
> activating -> activating-done
> 17:37:18 systemd[1]: Job
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.swap/start
> finished, result=done
> 17:37:18 systemd[1]: Activated swap
> /dev/disk/by-uuid/4c25dd37-c555-4fbf-8349-f1470d0e924c.
> 17:37:18 systemd[1]: Child 632 belongs to
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.swap
> 17:37:18 systemd[1]:
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.swap swap
> process exited, code=exited status=0
> 17:37:18 systemd[1]:
> dev-disk-by\x2duuid-4c25dd37\x2dc555\x2d4fbf\x2d8349\x2df1470d0e924c.swap changed
> activating-done -> active
> ---------------- cut ----------------
> Here I'd compare this:
> 17:36:57 systemd[1]: Found device /dev/disk/by-uuid/4c25...
> ...and
> 17:37:18 systemd[632]: Executing: /sbin/swapon /dev/disk/by-uuid/4c25...
> -- the delay is over 20 seconds! Ok, there are some other actions taken
> in between, unrelated of swap, and they consume some time too, but
> still, why waiting for device that is already available?
> Any hints?
>
> Thank you in advance,
> Nikolai
> _______________________________________________
> systemd-devel mailing list
> systemd-devel at lists.freedesktop.org
> http://lists.freedesktop.org/mailman/listinfo/systemd-devel