dvm starting extremly slow -> guid

59 views
Skip to first unread message

Qru

unread,
Jul 25, 2017, 8:18:21 PM7/25/17
to qubes...@googlegroups.com
Hi,

some days ago I installed the fedora-25 template, but didn't use it
because first I wanted to test it.
I also updated my templates (around 20) and dom0.

Then I noticed that starting a dvm takes really long (around 45
Seconds).
Before it was about 3 seconds, which is somehow acceptable. But 40
seconds?

I now changed the dvm to fedora-25 to perhaps improve the behaviour but
the dvm startet even slower (around 50 seconds).

To test it, I startet the dvm from the dom0-console:

[user@dom0 ~]$ sh - c 'echo firefox | usr/lib/qubes/qfile-daemon-dvm
qubes.VMShell dom0 DEFAULT red'
time=1500551220.14, qfile-daemon-dvm init
time=1500551220.14, creating DispVM
time=1500551220.19, collection loaded
time=1500551220.19, VM created
time=1500551220.2, VM starting
time=1500551220.2, creating config file
time=1500551220.31, calling restore
time=1500551221.25, done
time=1500551221.27, done qubesdb
time=1500551221.27, resumed
time=1500551221.46, qrexec done
time=1500551271.78, guid done
time=1500551271.78, VM started
time=1500551271.79, reloading firewall
time=1500551271.8, starting VM process

It seems that guid startup takes 50 seconds. What is going on there or
how can I debug it further?

Qru

P R

unread,
Jul 26, 2017, 5:07:59 AM7/26/17
to Qru, qubes...@googlegroups.com
Hello,

Am 26.07.2017 2:18 vorm. schrieb "Qru" <q...@openmailbox.org>:

Then I noticed that starting a dvm takes really long (around 45 Seconds).
Before it was about 3 seconds, which is somehow acceptable. But 40 seconds?

I have also migrated all AppVMs to Fedora 25 and discovered the same behavior.
Running the same command ...

To test it, I startet the dvm from the dom0-console:
[user@dom0 ~]$ sh - c 'echo firefox | usr/lib/qubes/qfile-daemon-dvm qubes.VMShell dom0 DEFAULT red'

I discovered also that the startups stalls between

time=1500551221.46, qrexec done

... and ...

time=1500551271.78, guid done

Between qrexec done and guid done I loose ~40 seconds.

I made another test with a Fedora 23 based DVM by recreating the disposable VM in dom0:

[user@dom0 ~]$ qvm-create-default-dvm fedora-23

After that launching the same command:

[user@dom0 ~]$ sh - c 'echo firefox | usr/lib/qubes/qfile-daemon-dvm qubes.VMShell dom0 DEFAULT red'

Finishes in ~ 12 seconds, so the problem with the slow bootup seems to be somewhere in the Fedora 25 Template.

Any idea where to look further and was is happening exactly between "qrexec done" and "guid done"?

- PhR

Unman

unread,
Jul 26, 2017, 10:08:26 AM7/26/17
to P R, Qru, qubes...@googlegroups.com
I see the same thing with a Debian 9 template - but not with
an 8 that's been upgraded.

P R

unread,
Jul 26, 2017, 10:18:56 AM7/26/17
to Unman, qubes...@googlegroups.com, Qru
Hello,


Am 26.07.2017 4:08 nachm. schrieb "Unman" <un...@thirdeyesecurity.org>:

I see the same thing with a Debian 9 template - but not with
an 8 that's been upgraded.

It looks to me, like we have either a package missing or we need to tweak the configuration in the AppVM template or in dom0, I am not sure if there is anything that can be configured in dom0.


From the documentation it seems that the AppVM template only needs to have 'perl-encode' installed:


An idea could be to built a DVM template from the fedora-24-minimal package, install perl-encode and look how fast the disp-vm will start.

- PhR

Patrik Hagara

unread,
Jul 26, 2017, 10:25:05 AM7/26/17
to P R, Qru, qubes...@googlegroups.com
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

On 07/26/2017 11:07 AM, 'P R' via qubes-users wrote:
> Any idea where to look further and was is happening exactly
> between "qrexec done" and "guid done"?

Try running

systemd-analyze blame

in the DispVM for both old and new template, maybe some service is
misbehaving.


Cheers,
Patrik

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2

iQIcBAEBCAAGBQJZeKY3AAoJEFwecd8DH5rltNgQALHpr26mgIecFszwulTk8uZn
xqo/kN+knukTf+K/Km9ZvQcjxQWWYcvuYz33UqpyZYZkmGb6Cs1FOl0ZUp/cH6xW
IFX8qyou+0JLStT28yZbaeXpKruKXUKXs6UNEk7ABz5A5wPxSpWIr+l2BESArl4c
/AAqE+TWeF+N+YYM41ZrpJPBvvzvK941jOrS5hRPIaSVmrAgYK4y1xrCOespY+65
lOhqF97Qvjbf35qBWbLbzUHg014Xd63bPr0wviHww9+KBmGfivTjI4vramfRxPEs
/jHYZf/RskbocxHbOe/ZDn0n7ZJu5ozjl49TLT7UXC7kxf8ZnfVdPkQ7STSvGV8f
GDMn7uG8bZrouVaWxWIJWfivC9DBHuDm6rEFyPLHptPVxAXspIOG9LeQxrZmbB1M
7X2QoHI0cWyQLu3jR3GMnQMdtkwBeeuClydTKQor3PQOuzNmNsFgmRv35XAHlmvq
N4yvheglk5tA9/QnVFt7aQKBUIkKMCEJwW/M+H3rjBUySTSoZZDDnu/ZyCYB5+sF
zAcCH1Jbum3mUs62CejF8wCw54sdRBASZcabOx0ngLXvq0/FbFO0DJOctO9MyESu
WpsACRDOCJi8jtE8t9clCbaQL3fecCAHvoJ5MM+LwOA/Ct+ixmWiSE53TfPIS+tf
s97IOlkn3Up7rrJN6ufp
=0K4P
-----END PGP SIGNATURE-----
0x031F9AE5.asc
0x031F9AE5.asc.sig

cooloutac

unread,
Jul 27, 2017, 2:54:26 PM7/27/17
to qubes-users, p.rasc...@googlemail.com, q...@openmailbox.org
same thing has been happening to me and I was going to make a post about it, but then it just fixed itself. I'm also using fedora-25 for the dvm.

PhR

unread,
Jul 30, 2017, 4:26:48 PM7/30/17
to Patrik Hagara, Qru, qubes...@googlegroups.com
Hello Patrik,


On 07/26/2017 04:24 PM, Patrik Hagara wrote:
> On 07/26/2017 11:07 AM, 'P R' via qubes-users wrote:
>> Any idea where to look further and was is happening exactly
>> between "qrexec done" and "guid done"?
> Try running
>
> systemd-analyze blame
>
> in the DispVM for both old and new template, maybe some service is
> misbehaving.
Thank your for the hint, I've run 'systemd-analyze blame' in the dvm,
which was based on the fedora-23-image and launches firefox within 15
seconds.

I've also run 'systemd-analyze blame' in my fedora-25 based dvm, which
is currently launching firefox in 62 seconds (vs. 15 seconds with a
fedora-23 dvm)

I've compared the output of systemd-analyse blame in both dvms and the
greatest difference is within the last few lines (I have attached the
full output at the bottom of this email):

Fedora-25 DVM: starting a disposable Firefox within 60-70 seconds = very
slow!

1min 41.053s qubes-update-check.service
20.913s qubes-dvm.service
17.748s ldconfig.service
8.011s dev-xvdd.device
3.482s systemd-hwdb-update.service

Fedora-23 DVM: starting a disposable Firefox within 15 seconds

16.052s qubes-dvm.service
15.864s ldconfig.service
6.085s dev-xvdd.device
2.774s systemd-hwdb-update.service

As such my conclusion:

1) qubes-dvm.service seems to eat up more time compared to the fedora-23dvm
2) an additional service "qubes-update-check.service" seems to be
running in the fedora-25 dvm which is not included in the fedora-23 dvm.

Someone has more ideas where to look further.
Is the timestamp the starting time of the service? If so,
qubes-dvm.service runs much much longer in the fedora-25 dvm.
More important question: what are the options to fix this?

-------

Output of systemd-analyse blame in my fedora-23 DVM:

16.052s qubes-dvm.service
15.864s ldconfig.service
6.085s dev-xvdd.device
2.774s systemd-hwdb-update.service
2.549s systemd-udevd.service
2.464s dev-xvdb.device
1.899s qubes-mount-dirs.service
1.819s qubes-sysinit.service
1.747s systemd-tmpfiles-setup-dev.service
958ms systemd-journal-flush.service
951ms abrtd.service
527ms auditd.service
505ms systemd-fsck-root.service
435ms qubes-db.service
427ms abrt-ccpp.service
400ms qubes-iptables.service
359ms upower.service
327ms polkit.service
312ms qubes-misc-post.service
259ms systemd-udev-trigger.service
251ms systemd-tmpfiles-setup.service
238ms proc-xen.mount
236ms systemd-journal-catalog-update.service
233ms dev-mqueue.mount
230ms kmod-static-nodes.service
221ms fedora-readonly.service
219ms systemd-logind.service
201ms systemd-sysctl.service
195ms systemd-vconsole-setup.service
177ms systemd-journald.service
176ms cups.service
166ms systemd-remount-fs.service
162ms systemd-sysusers.service
157ms us...@1000.service
149ms fedora-loadmodules.service
124ms tmp.mount
121ms iio-sensor-proxy.service
106ms systemd-hostnamed.service
101ms udisks2.service
99ms sys-kernel-debug.mount
94ms qubes-meminfo-writer.service
92ms systemd-user-sessions.service
83ms systemd-modules-load.service
79ms rtkit-daemon.service
77ms dev-xvdc1.swap
67ms xendriverdomain.service
61ms qubes-gui-agent.service
60ms sys-fs-fuse-connections.mount
48ms systemd-random-seed.service
47ms systemd-update-utmp.service
38ms dracut-shutdown.service
36ms qubes-qrexec-agent.service
17ms systemd-update-done.service
17ms sys-kernel-config.mount
14ms systemd-update-utmp-runlevel.service


Output of systemd-analyse blame in my fedora-25 DVM:

1min 41.053s qubes-update-check.service
20.913s qubes-dvm.service
17.748s ldconfig.service
8.011s dev-xvdd.device
3.482s systemd-hwdb-update.service
3.183s qubes-mount-dirs.service
3.059s systemd-udevd.service
2.431s dev-xvdb.device
2.001s qubes-sysinit.service
1.901s systemd-tmpfiles-setup-dev.service
1.683s systemd-journal-flush.service
1.448s qubes-db.service
1.170s qubes-misc-post.service
1.068s systemd-fsck-root.service
1.039s systemd-random-seed.service
880ms xendriverdomain.service
858ms systemd-logind.service
813ms fedora-readonly.service
795ms abrt-ccpp.service
668ms polkit.service
588ms abrtd.service
503ms systemd-sysctl.service
501ms systemd-journald.service
463ms auditd.service
453ms systemd-tmpfiles-setup.service
440ms qubes-iptables.service
404ms systemd-journal-catalog-update.service
364ms us...@1000.service
357ms fedora-loadmodules.service
336ms tmp.mount
320ms sys-kernel-debug.mount
314ms iio-sensor-proxy.service
289ms systemd-modules-load.service
286ms dev-mqueue.mount
242ms proc-xen.mount
216ms upower.service
179ms cups.service
172ms systemd-udev-trigger.service
168ms rtkit-daemon.service
156ms systemd-sysusers.service
150ms systemd-remount-fs.service
145ms kmod-static-nodes.service
145ms dev-xvdc1.swap
115ms udisks2.service
113ms systemd-update-utmp-runlevel.service
94ms systemd-update-utmp.service
84ms systemd-vconsole-setup.service
72ms systemd-user-sessions.service
71ms qubes-gui-agent.service
60ms systemd-hostnamed.service
35ms qubes-meminfo-writer.service
33ms dracut-shutdown.service
17ms systemd-update-done.service
16ms sys-kernel-config.mount
8ms qubes-qrexec-agent.service


- PhR

PhR

unread,
Jul 30, 2017, 5:05:05 PM7/30/17
to cooloutac, qubes-users, q...@openmailbox.org
Hello,

just a followup to my last post:


On 07/27/2017 08:54 PM, cooloutac wrote:
> same thing has been happening to me and I was going to make a post about it, but then it just fixed itself. I'm also using fedora-25 for the dvm.
I have updated my fedora-25 template and also dom0 and it seems that the
slow DVM startup problem has been either solved or it "fixed itself" :-)

After applying the updates the fedora 25 DVM starts faster than the
fedora 23 DVM within 9 seconds, compared to 15 seconds (fedora 23) on a
lenovo X200 with 8GB RAM.

Just for reference / the googlemail mailing-list archives the result of
systemd-analyze blame:

25.151s qubes-meminfo-writer.service
25.074s qubes-iptables.service
25.066s abrtd.service
14.087s qubes-dvm.service
995ms dev-xvdd.device
546ms qubes-mount-dirs.service
507ms qubes-misc-post.service
459ms qubes-sysinit.service
425ms vpnagentd.service
382ms abrt-ccpp.service
318ms systemd-udev-trigger.service
298ms systemd-journal-flush.service
293ms cups.service
289ms udisks2.service
237ms systemd-udevd.service
208ms systemd-modules-load.service
207ms systemd-fsck-root.service
185ms kmod-static-nodes.service
180ms upower.service
179ms sys-kernel-debug.mount
171ms systemd-logind.service
139ms dev-xvdb.device
137ms us...@1000.service
127ms systemd-journald.service
125ms xendriverdomain.service
123ms systemd-remount-fs.service
118ms proc-xen.mount
110ms systemd-vconsole-setup.service
105ms auditd.service
101ms qubes-early-vm-config.service
100ms systemd-random-seed.service
96ms fedora-readonly.service
82ms qubes-db.service
74ms polkit.service
73ms dev-mqueue.mount
70ms systemd-user-sessions.service
69ms qubes-gui-agent.service
64ms rtkit-daemon.service
60ms systemd-tmpfiles-setup-dev.service
59ms systemd-tmpfiles-setup.service
58ms fedora-loadmodules.service
57ms systemd-sysctl.service
52ms sys-kernel-config.mount
29ms systemd-update-utmp-runlevel.service
17ms systemd-update-utmp.service
16ms dev-xvdc1.swap
13ms qubes-qrexec-agent.service
12ms dracut-shutdown.service
10ms tmp.mount

- PhR
Reply all
Reply to author
Forward
0 new messages