Hi,

In git/news I only found these changes which sounded to be relevant: f51cbe92c0 qemu: Allow migration over UNIX socket c69915ccaf peer2peer migration: allow connecting to local sockets But I'm not using unix: and in the logs the only unix: mentions are for the qemu monitor and qemu-guest-agent.

On Tue, Nov 24, 2020 at 4:30 PM Peter Krempa <pkrempa(a)redhat.com&gt; wrote: > > On Tue, Nov 24, 2020 at 16:05:53 +0100, Christian Ehrhardt wrote: > > Hi, > > [...] BTW to reduce the scope what to think about - I have rebuilt 6.8 as well it works. Thereby I can confirm that the offending change should be in between 6.8.0 -> 6.9.0.

> > In git/news I only found these changes which sounded to be relevant: > > f51cbe92c0 qemu: Allow migration over UNIX socket > > c69915ccaf peer2peer migration: allow connecting to local sockets > > But I'm not using unix: and in the logs the only unix: mentions are for the > > qemu monitor and qemu-guest-agent. > > One very important part of '--tunnelled' migration is the use of > virStream APIs to transport the migration data. Perhaps something there > is broken since it doesn't reproduce when not using the tunnel Thanks for the hint Peter. I was now looking there as well, but other than the switch to g_new0 there is neither a change carrying the words "stream" nor one that is affecting the related files that implement virStream*. -- Christian Ehrhardt Staff Engineer, Ubuntu Server Canonical Ltd

On Wed, Nov 25, 2020 at 01:28:09PM +0100, Christian Ehrhardt wrote: > On Wed, Nov 25, 2020 at 10:55 AM Christian Ehrhardt > <christian.ehrhardt(a)canonical.com&gt; wrote: > > > > On Tue, Nov 24, 2020 at 4:30 PM Peter Krempa <pkrempa(a)redhat.com&gt; wrote: > > > > > > On Tue, Nov 24, 2020 at 16:05:53 +0100, Christian Ehrhardt wrote: > > > > Hi, > > > > > > [...] > > > > BTW to reduce the scope what to think about - I have rebuilt 6.8 as > > well it works. > > Thereby I can confirm that the offending change should be in between > > 6.8.0 -> 6.9.0. > > I was able to get this working in git bisect builds from git between > v6.8 / v6.9. > I identified the following offending commit: > 7d959c30 rpc: Fix virt-ssh-helper detection > > Ok that makes a bit of sense, first we had in 6.8 > f8ec7c84 rpc: use new virt-ssh-helper binary for remote tunnelling > That makes it related to tunneling which matches our broken use-case. > > The identified commit "7d959c30 rpc: Fix virt-ssh-helper detection" might > finally really enable the new helper and that is then broken? > > With that knowledge I was able to confirm that it really is the native mode > > $ virsh migrate --unsafe --live --p2p --tunnelled h-migr-test > qemu+ssh://testkvm-hirsute-to/system?proxy=netcat > <works> > $ virsh migrate --unsafe --live --p2p --tunnelled h-migr-test > qemu+ssh://testkvm-hirsute-to/system?proxy=native > <hangs> > > I recently discussed with Andrea if we'd need apparmor rules for > virt-ssh-helper, > but there are no denials nor libvirt log entries related to virt-ssh-helper. > But we don't need such rules since it is spawned on the ssh login and > not under libvirtd itself. > > PS output of the hanging receiving virt-ssh-helper (looks not too unhappy): > Source: > 4 0 41305 1 20 0 1627796 23360 poll_s Ssl ? > 0:05 /usr/sbin/libvirtd > 0 0 41523 41305 20 0 9272 4984 poll_s S ? > 0:02 \_ ssh -T -e none -- testkvm-hirsute-to sh -c 'virt-ssh-helper > 'qemu:///system'' > Target > 4 0 213 1 20 0 13276 4132 poll_s Ss ? > 0:00 sshd: /usr/sbin/sshd -D [listener] 0 of 250-500 startups > 4 0 35148 213 20 0 19048 11320 poll_s Ss ? > 0:02 \_ sshd: root@notty > 4 0 35206 35148 20 0 2584 544 do_wai Ss ? > 0:00 \_ sh -c virt-ssh-helper qemu:///system > 0 0 35207 35206 20 0 81348 26684 - R ? > 0:34 \_ virt-ssh-helper qemu:///system > > I've looked at it with strace [1] and gdb for backtraces [2] - it is > not dead or stuck and keeps working. > Could it be just so slow that it appears to hang until it times out? > Or is the event mechanism having issues and it wakes up too rarely? Lets take migration out of the picture. What if you simply do virsh -c qemu+ssh://testkvm-hirsute-to/system?proxy=native list does that work ?

Regards, Daniel -- |: https://berrange.com -o- https://www.flickr.com/photos/dberrange :| |: https://libvirt.org -o- https://fstop138.berrange.com :| |: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|

On Wed, Nov 25, 2020 at 02:33:44PM +0100, Christian Ehrhardt wrote: > On Wed, Nov 25, 2020 at 1:38 PM Daniel P. Berrangé <berrange(a)redhat.com&gt; wrote: > > > > On Wed, Nov 25, 2020 at 01:28:09PM +0100, Christian Ehrhardt wrote: > > > On Wed, Nov 25, 2020 at 10:55 AM Christian Ehrhardt > > > <christian.ehrhardt(a)canonical.com&gt; wrote: > > > > > > > > On Tue, Nov 24, 2020 at 4:30 PM Peter Krempa <pkrempa(a)redhat.com&gt; wrote: > > > > > > > > > > On Tue, Nov 24, 2020 at 16:05:53 +0100, Christian Ehrhardt wrote: > > > > > > Hi, > > > > > > > > > > [...] > > > > > > > > BTW to reduce the scope what to think about - I have rebuilt 6.8 as > > > > well it works. > > > > Thereby I can confirm that the offending change should be in between > > > > 6.8.0 -> 6.9.0. > > > > > > I was able to get this working in git bisect builds from git between > > > v6.8 / v6.9. > > > I identified the following offending commit: > > > 7d959c30 rpc: Fix virt-ssh-helper detection > > > > > > Ok that makes a bit of sense, first we had in 6.8 > > > f8ec7c84 rpc: use new virt-ssh-helper binary for remote tunnelling > > > That makes it related to tunneling which matches our broken use-case. > > > > > > The identified commit "7d959c30 rpc: Fix virt-ssh-helper detection" might > > > finally really enable the new helper and that is then broken? > > > > > > With that knowledge I was able to confirm that it really is the native mode > > > > > > $ virsh migrate --unsafe --live --p2p --tunnelled h-migr-test > > > qemu+ssh://testkvm-hirsute-to/system?proxy=netcat > > > <works> > > > $ virsh migrate --unsafe --live --p2p --tunnelled h-migr-test > > > qemu+ssh://testkvm-hirsute-to/system?proxy=native > > > <hangs> > > > > > > I recently discussed with Andrea if we'd need apparmor rules for > > > virt-ssh-helper, > > > but there are no denials nor libvirt log entries related to virt-ssh-helper. > > > But we don't need such rules since it is spawned on the ssh login and > > > not under libvirtd itself. > > > > > > PS output of the hanging receiving virt-ssh-helper (looks not too unhappy): > > > Source: > > > 4 0 41305 1 20 0 1627796 23360 poll_s Ssl ? > > > 0:05 /usr/sbin/libvirtd > > > 0 0 41523 41305 20 0 9272 4984 poll_s S ? > > > 0:02 \_ ssh -T -e none -- testkvm-hirsute-to sh -c 'virt-ssh-helper > > > 'qemu:///system'' > > > Target > > > 4 0 213 1 20 0 13276 4132 poll_s Ss ? > > > 0:00 sshd: /usr/sbin/sshd -D [listener] 0 of 250-500 startups > > > 4 0 35148 213 20 0 19048 11320 poll_s Ss ? > > > 0:02 \_ sshd: root@notty > > > 4 0 35206 35148 20 0 2584 544 do_wai Ss ? > > > 0:00 \_ sh -c virt-ssh-helper qemu:///system > > > 0 0 35207 35206 20 0 81348 26684 - R ? > > > 0:34 \_ virt-ssh-helper qemu:///system > > > > > > I've looked at it with strace [1] and gdb for backtraces [2] - it is > > > not dead or stuck and keeps working. > > > Could it be just so slow that it appears to hang until it times out? > > > Or is the event mechanism having issues and it wakes up too rarely? > > > > Lets take migration out of the picture. What if you simply do > > > > virsh -c qemu+ssh://testkvm-hirsute-to/system?proxy=native list > > > > does that work ? > > Yes it does, no hang and proper results Ok, so that shows virt-ssh-helper is not completely broken at least. Makes me think there is possibly something related to streams code that causes the issue. You might try the virsh "console" or "vol-upload" commands to test the streams stuff in isolation. If that also works, then the problem is specific to migration,

and we'll probably wnt to colllect debug level logs from src+dst hosts.

Regards, Daniel -- |: https://berrange.com -o- https://www.flickr.com/photos/dberrange :| |: https://libvirt.org -o- https://fstop138.berrange.com :| |: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|

On Wed, Nov 25, 2020 at 04:49:14PM +0100, Christian Ehrhardt wrote: > Thanks for the hint Daniel, it is indeed not migration specific - it > seems that virs-ssh-helper is just very slow. > > rm testfile; virsh -c > qemu+ssh://testkvm-hirsute-to/system?proxy=netcat vol-download --pool > uvtool h-migr-test.qcow testfile & for i in $(seq 1 20); do sleep 1s; > ll -laFh testfile; done > [1] 42285 > -rw-r--r-- 1 root root 24M Nov 25 15:20 testfile > -rw-r--r-- 1 root root 220M Nov 25 15:20 testfile > -rw-r--r-- 1 root root 396M Nov 25 15:20 testfile > -rw-r--r-- 1 root root 558M Nov 25 15:20 testfile > -rw-r--r-- 1 root root 756M Nov 25 15:20 testfile > -rw-r--r-- 1 root root 868M Nov 25 15:20 testfile > [1]+ Done virsh -c > qemu+ssh://testkvm-hirsute-to/system?proxy=netcat vol-download --pool > uvtool h-migr-test.qcow testfile > > rm testfile; virsh -c > qemu+ssh://testkvm-hirsute-to/system?proxy=native vol-download --pool > uvtool h-migr-test.qcow testfile & for i in $(seq 1 20); do sleep 1s; > ll -laFh testfile; done > [1] 42307 > -rw-r--r-- 1 root root 1.8M Nov 25 15:21 testfile > -rw-r--r-- 1 root root 6.8M Nov 25 15:21 testfile > -rw-r--r-- 1 root root 9.8M Nov 25 15:21 testfile > -rw-r--r-- 1 root root 13M Nov 25 15:21 testfile > -rw-r--r-- 1 root root 15M Nov 25 15:21 testfile > -rw-r--r-- 1 root root 16M Nov 25 15:21 testfile > -rw-r--r-- 1 root root 18M Nov 25 15:21 testfile > -rw-r--r-- 1 root root 19M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 21M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 22M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 23M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 25M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 26M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 27M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 28M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 29M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 30M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 31M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 32M Nov 25 15:22 testfile > -rw-r--r-- 1 root root 32M Nov 25 15:22 testfile > > That is ~150-200 MB/s vs 1-5 MB/s and as seen it seems to start slow > AND degrades further. > I'm not at 90MB overall and down to ~150 KB/s > > > and we'll probably wnt to colllect debug > > level logs from src+dst hosts. > > I already had debug level logs of the migration [1] attached to the > launchpad bug I use to take my notes on this. > Taken with these configs: > log_filters="1:qemu 1:libvirt 3:object 3:json 3:event 1:util" > log_outputs="1:file:/var/log/libvirtd.log" > > You can fetch the logs (of a migration), but I'm happy to generate you > logs of any other command (or with other log settings) as you'd prefer > them. > > The network used in this case is a bridge between two containers, but > we can cut out more components. > I found that the same vol-download vs 127.0.0.1 gives the same results. > That in turn makes it easier to gather results as we only need one system. Yep, that's useful, I'm able to reproduce this problem myself too now. Will do some local tests and report back...

On Wed, Nov 25, 2020 at 05:00:20PM +0000, Daniel P. Berrangé wrote: > On Wed, Nov 25, 2020 at 04:36:39PM +0000, Daniel P. Berrangé wrote: > > On Wed, Nov 25, 2020 at 04:49:14PM +0100, Christian Ehrhardt wrote: > > > I found that the same vol-download vs 127.0.0.1 gives the same results. > > > That in turn makes it easier to gather results as we only need one system. > > > > Yep, that's useful, I'm able to reproduce this problem myself too > > now. Will do some local tests and report back... > > Sigh, the problem is way too many reallocs, repeatedly growing and shrinking > the buffer we use for I/O. > > I guess we never noticed this awfulness in the virsh console code it was > copied from, as the data volumes are lower. > > Switching to a fixed size buffer makes it massively faster. I'll prep a > patch asap. Actually, it is also important to have a bigger buffer. Using a 1 MB buffer makes all the difference in throughput.