Shutting down domain takes a long time

[heinrich-ulbricht]

Qubes OS version
R4.0

Affected component(s) or functionality
Shutting down a domain.

Brief summary
Shutting down one of my domains takes ~40 seconds. Other domains only take ~6 seconds.

To Reproduce
Don't know how to reproduce. Works (not) on my machine:tm:.

Expected behavior
Domain shuts down fast.

Actual behavior
Domain takes ages.

Additional context
My domain has 600 GB private storage. I recently increased the size by ~60 GB, ignoring the advice to increase in steps of 10 GB. I just added 60 GB. Now I don't know if the slow shutdown is since then or if it is since I switched the template from Fedora 28 to Fedora 30 or not related at all. It might also be normal for such a size. Somebody familiar with the inner workings might know if some of those things could matter.

Solutions you've tried
Don't know where to start, which logs to consult or which tools to use.

Any help to get started diagnosing this is appreciated.

[marmarek]

Take a looks at /var/log/xen/console/guest-VMNAME.log (also available in qubes manager right click menu) for that domain. It should contain individual service stops during domain shutdown, including timestamps - it will give a hint what takes this long.

[heinrich-ulbricht]

@marmarek Looking at the most recent log file for the domain I can see that the log messages report successful shutdown (so it seems) almost immediately after clicking the "Shutdown" button in the Qubes menu. When I click Shutdown and look at the log I immediately see this:

[.[0;32m  OK  .[0m] Reached target .[0;1;39mShutdown.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mFinal Step.[0m.
[.[0;32m  OK  .[0m] Started .[0;1;39mPower-Off.[0m.
[.[0;32m  OK  .[0m] Reached target .[0;1;39mPower-Off.[0m.
[   35.852900] systemd-shutdown[1]: Syncing filesystems and block devices.
[   35.915401] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[   35.922197] systemd-journald[210]: Received SIGTERM from PID 1 (systemd-shutdow).
[   35.968467] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[   35.976329] systemd-shutdown[1]: Unmounting file systems.
[   35.980770] [1619]: Remounting '/usr/lib/modules' read-only in with options 'lowerdir=/tmp/modules,upperdir=/sysroot/lib/modules,workdir=/sysroot/lib/.modules_work'.
[   35.985098] [1620]: Unmounting '/usr/lib/modules'.
[   35.995188] [1621]: Remounting '/' read-only in with options 'discard'.
[   36.017008] EXT4-fs (xvda3): re-mounted. Opts: discard
[   36.027040] systemd-shutdown[1]: All filesystems unmounted.
[   36.027075] systemd-shutdown[1]: Deactivating swaps.
[   36.027192] systemd-shutdown[1]: All swaps deactivated.
[   36.027219] systemd-shutdown[1]: Detaching loop devices.
[   36.027512] systemd-shutdown[1]: All loop devices detached.
[   36.027542] systemd-shutdown[1]: Detaching DM devices.
[   36.172314] reboot: System halted

And then it takes ~40 seconds. No further log entries are added, so the log does not really help. Is this ok? Where would I look further?

[brendanhoar]

1. What physical storage are you using, SSD or HDD?
2. Are you configured with the standard LVM-thin, btrfs or standard file-based containers?
3. What was the initial version of Qubes installed?
4. Are you running standard or testing repos?

[heinrich-ulbricht]

@brendanhoar

1. classic HDD
2. standard LVM-thin in a separate pool
3. Qubes R4.0
   • did a migration lately, but from 4.0 to 4.0 to increase the size of my main-pool SSD; re-created the large pool on another HDD that SHOULD be the same model as the first one
   • I upgraded the underlying Fedora 28 TemplateVM to Fedora 30 lately
4. standard Qubes and Fedora repos

Your questions lead me to do some more testing:

• I switched the TemplateVM to Fedora 30 and Fedora 28 Minimal - no change, the long shutdown time persists

Shutdown time currently is ~50 seconds in all cases.

The first time I noticed the long shutdown is after increasing the private storage by a large amount. But it might be that I did not notice the long shutdown time before during regular shutdown. But I'm certain it used to be a lot faster. If I could pinpoint it to a slow HDD or something this would be fine. I'd just like to see some log where the delay can be seen. Maybe it's a timeout or something.

[heinrich-ulbricht]

Just had look into the oldest xen log file I have, which is from Oct 06. It looks different for shutdown:

         Starting Power-Off...
[25187.655862] systemd-shutdow: 25 output lines suppressed due to ratelimiting
[25187.759906] systemd-shutdown[1]: Syncing filesystems and block devices.
[25187.839439] systemd-shutdown[1]: Sending SIGTERM to remaining processes...
[25187.842755] systemd-journald[203]: Received SIGTERM from PID 1 (systemd-shutdow).
[25187.874552] systemd-shutdown[1]: Sending SIGKILL to remaining processes...
[25187.877111] systemd-shutdown[1]: Unmounting file systems.
[25187.879350] [2493]: Remounting '/usr/lib/modules' read-only in with options 'lowerdir=/tmp/modules,upperdir=/sysroot/lib/modules,workdir=/sysroot/lib/.modules_work'.
[25187.887041] [2494]: Unmounting '/usr/lib/modules'.
[25187.896060] [2495]: Remounting '/' read-only in with options 'discard'.
[25187.923818] EXT4-fs (xvda3): re-mounted. Opts: discard
[25187.927815] systemd-shutdown[1]: All filesystems unmounted.
[25187.927830] systemd-shutdown[1]: Deactivating swaps.
[25187.927869] systemd-shutdown[1]: All swaps deactivated.
[25187.927880] systemd-shutdown[1]: Detaching loop devices.
[25187.928048] systemd-shutdown[1]: All loop devices detached.
[25187.928060] systemd-shutdown[1]: Detaching DM devices.
[25187.954533] xenbus: xenbus_dev_shutdown: device/vbd/51840: Closed != Connected, skipping
[25187.993300] reboot: System halted

The xenbus line is gone in the current log. But then again those changes might be to kernel or xen updates. And the delay is not covered in the log.

[heinrich-ulbricht]

guid.domain.log differs from other domains. It shows:

Icon size: 128x128
libvchan_is_eof
Icon size: 128x128
domain dead
Failed to connect to gui-agent

These log entries seem to be unique to this domain:

domain dead
Failed to connect to gui-agent

Maybe it's just a reporting issue? Somebody not noticing the shutdown already happened?

[marmarek]

Those particular messages are probably unrelated, but I have another idea: during that long shutdown observe output of xl list, specifically state column. Is it -b---- or something else when that long delay happens?
If something else, check what version of qubes-libvchan-xen do you have, specifically if 4.0.7 or older - a related change was included there (that could improve this).

[heinrich-ulbricht]

@marmarek
During shutdown I can observe the state in xl list change like this over time (domain being the name of my domain):

• domain: r----- (time: 14.1)
• domain: -b---- (time: 20.2)
• domain: r----- (time: 21.0)
• (null): --ps-- (time: 21.0)
• (null): --ps-d (time: 21.0)

Note how the domain name at some point is replaced by (null) and the time stops.

It stays like (null): --ps-d (21.0) for about 8 seconds, then the entry disappears while the domain is still shutting down for many more seconds according to the Qubes Domains list.

In my VM I have version 4.0.7 of qubes-libvchan-xen.

[user@domain ~]$ dnf list installed | grep qubes-libvchan-xen
qubes-libvchan-xen.x86_64                   4.0.7-1.fc30                          @qubes-vm-r4.0-current

Does this shed some light?

[brendanhoar]

1. What model of HDD is this? Seagate or Western Digital? Does it report it supports ... trim or unmap? SHR-based HDDs now sometimes do, and it's possible they take more time to process a blkdiscard than SSDs do (which may be occurring when removing volatile/snapshot volumes during VM shutdown).
2. By any chance, did you change the qubes-wide default pool from the primary (SSD) pool to the secondary (HDD) pool?
3. Where is the template for this VM located, SSD or HDD?
4. When you grep the output of sudo lvs for the name of your running VM and the name of the template it is based on...in which pools do the standard, volatile and snapshot volumes reside?

[heinrich-ulbricht]

@brendanhoar

1. It's a Western Digital WD10EAVS from years ago. So SHR, trim etc. shouldn't be things to consider (right?)
2. Yes, I temporarily changed the qubes-wide default pool from the primary (SSD) pool to the secondary pool to restore the large domain to the HDD pool. Then I changed it back to the SSD pool.
3. The template is located on the SSD.
4. Find the grep of the running VM below; pool00 is on the SSD, vg_contoso/lv_contoso on the HDD

[heinrich@dom0 console]$ sudo lvs | grep contoso
  vm-contoso-root-snap                               qubes_dom0 Vwi-aotz--  21.72g pool00    vm-fedora-30                         56.84                                  
  lv_contoso                                         vg_contoso  twi-aotz-- 931.27g                                                             61.82  39.53                           
  vm-contoso-private                                 vg_contoso  Vwi-a-tz-- 585.94g lv_contoso vm-contoso-private-1572293911-back                 98.26                                  
  vm-contoso-private-1572268964-back                 vg_contoso  Vwi-a-tz-- 585.94g lv_contoso                                                   98.26                                  
  vm-contoso-private-1572293911-back                 vg_contoso  Vwi-a-tz-- 585.94g lv_contoso vm-contoso-private-1572268964-back                 98.26                                  
  vm-contoso-private-snap                            vg_contoso  Vwi-aotz-- 585.94g lv_contoso vm-contoso-private                                 98.26                                  
  vm-contoso-volatile                                vg_contoso  Vwi-aotz--  10.00g lv_contoso 

Do you see anything in there that looks odd?