Re: starting to look at qemu savevm performance, a first regression detected

Re: starting to look at qemu savevm performance, a first regression detected

[Claudio Fontana]

On 3/7/22 10:51 AM, Daniel P. Berrangé wrote:
> On Mon, Mar 07, 2022 at 10:44:56AM +0100, Claudio Fontana wrote:
>> Hello Daniel,
>>
>> On 3/7/22 10:27 AM, Daniel P. Berrangé wrote:
>>> On Sat, Mar 05, 2022 at 02:19:39PM +0100, Claudio Fontana wrote:
>>>>
>>>> Hello all,
>>>>
>>>> I have been looking at some reports of bad qemu savevm performance in large VMs (around 20+ Gb),
>>>> when used in libvirt commands like:
>>>>
>>>>
>>>> virsh save domain /dev/null
>>>>
>>>>
>>>>
>>>> I have written a simple test to run in a Linux centos7-minimal-2009 guest, which allocates and touches 20G mem.
>>>>
>>>> With any qemu version since around 2020, I am not seeing more than 580 Mb/Sec even in the most ideal of situations.
>>>>
>>>> This drops to around 122 Mb/sec after commit: cbde7be900d2a2279cbc4becb91d1ddd6a014def .
>>>>
>>>> Here is the bisection for this particular drop in throughput:
>>>>
>>>> commit cbde7be900d2a2279cbc4becb91d1ddd6a014def (HEAD, refs/bisect/bad)
>>>> Author: Daniel P. Berrangé <berrange@redhat.com>
>>>> Date:   Fri Feb 19 18:40:12 2021 +0000
>>>>
>>>>     migrate: remove QMP/HMP commands for speed, downtime and cache size
>>>>     
>>>>     The generic 'migrate_set_parameters' command handle all types of param.
>>>>     
>>>>     Only the QMP commands were documented in the deprecations page, but the
>>>>     rationale for deprecating applies equally to HMP, and the replacements
>>>>     exist. Furthermore the HMP commands are just shims to the QMP commands,
>>>>     so removing the latter breaks the former unless they get re-implemented.
>>>>     
>>>>     Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
>>>>     Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
>>>
>>> That doesn't make a whole lot of sense as a bisect result.
>>> How reliable is that bisect end point ? Have you bisected
>>> to that point more than once ?
>>
>> I did run through the bisect itself only once, so I'll double check that.
>> The results seem to be reproducible almost to the second though, a savevm that took 35 seconds before the commit takes 2m 48 seconds after.
>>
>> For this test I am using libvirt v6.0.0.
>>
>> If it helps, these are the current_migration->parameters pre-commit (captured in qemu_savevm_state_iterate):
>>
>>
>> pre-commit: in qemu_savevm_state_iterate:
>>
>> (gdb) p current_migration->parameters
> 
>>   tls_authz = 0x0, has_max_bandwidth = true, max_bandwidth = 9223372036853727232, has_downtime_limit = true, downtime_limit = 300,
> 
> snip
> 
>> and post-commit: in qemu_savevm_state_iterate:
>>
>> (gdb) p current_migration->parameters
> 
> snip
> 
>>   tls_authz = 0x0, has_max_bandwidth = true, max_bandwidth = 134217728, has_downtime_limit = true, downtime_limit = 300,
> 
>> so there seems to be a difference in the max_bandwidth parameter,
>> do we have a limit suddenly having effect for max_bandwidth after the commit?
> 
> Yes, that's very strange. I think we'll need to capture the QMP commands that
> libvirt is sending to QEMU, so see if there';s a difference in what it sends.
> This might indicate a latent bug in libvirt.


In the pre-commit case I see:

2022-03-07 10:41:00.928+0000: 132544: info : qemuMonitorJSONIOProcessLine:235 : QEMU_MONITOR_RECV_EVENT: mon=0x7f0fd00028a0 event={"timestamp": {"seconds": 1646649660, "microseconds": 927920}, "event": "STOP"}
2022-03-07 10:41:00.929+0000: 132544: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7f0fd00028a0 reply={"return": {}, "id": "libvirt-13"}
2022-03-07 10:41:00.934+0000: 132549: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7f0fd00028a0 msg={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-14"}^M
 fd=-1
2022-03-07 10:41:00.934+0000: 132544: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7f0fd00028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-14"}^M
 len=93 ret=93 errno=0
2022-03-07 10:41:00.935+0000: 132544: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7f0fd00028a0 reply={"return": {}, "id": "libvirt-14"}
2022-03-07 10:41:00.936+0000: 132549: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7f0fd00028a0 msg={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-15"}^M
 fd=32
2022-03-07 10:41:00.936+0000: 132544: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7f0fd00028a0 buf={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-15"}^M
 len=72 ret=72 errno=0
2022-03-07 10:41:00.936+0000: 132544: info : qemuMonitorIOWrite:457 : QEMU_MONITOR_IO_SEND_FD: mon=0x7f0fd00028a0 fd=32 ret=72 errno=0
2022-03-07 10:41:00.937+0000: 132544: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7f0fd00028a0 reply={"return": {}, "id": "libvirt-15"}
2022-03-07 10:41:00.937+0000: 132549: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7f0fd00028a0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-16"}^M
 fd=-1
2022-03-07 10:41:00.937+0000: 132544: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7f0fd00028a0 buf={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-16"}^M
 len=112 ret=112 errno=0


In the post-commit case I see:


2022-03-07 10:47:07.316+0000: 134386: info : qemuMonitorJSONIOProcessLine:235 : QEMU_MONITOR_RECV_EVENT: mon=0x7fa4380028a0 event={"timestamp": {"seconds": 1646650027, "microseconds": 316537}, "event": "STOP"}
2022-03-07 10:47:07.317+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"return": {}, "id": "libvirt-13"}
2022-03-07 10:47:07.322+0000: 134391: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7fa4380028a0 msg={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-14"}^M
 fd=-1
2022-03-07 10:47:07.322+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-14"}^M
 len=93 ret=93 errno=0
2022-03-07 10:47:07.324+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"id": "libvirt-14", "error": {"class": "CommandNotFound", "desc": "The command migrate_set_speed has not been found"}}
2022-03-07 10:47:07.324+0000: 134391: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'migrate_set_speed': The command migrate_set_speed has not been found
2022-03-07 10:47:07.324+0000: 134391: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7fa4380028a0 msg={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-15"}^M
 fd=32
2022-03-07 10:47:07.324+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-15"}^M
 len=72 ret=72 errno=0
2022-03-07 10:47:07.324+0000: 134386: info : qemuMonitorIOWrite:457 : QEMU_MONITOR_IO_SEND_FD: mon=0x7fa4380028a0 fd=32 ret=72 errno=0
2022-03-07 10:47:07.325+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"return": {}, "id": "libvirt-15"}
2022-03-07 10:47:07.326+0000: 134391: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7fa4380028a0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-16"}^M
 fd=-1
2022-03-07 10:47:07.326+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-16"}^M
 len=112 ret=112 errno=0
2022-03-07 10:47:07.328+0000: 134386: info : qemuMonitorJSONIOProcessLine:235 : QEMU_MONITOR_RECV_EVENT: mon=0x7fa4380028a0 event={"timestamp": {"seconds": 1646650027, "microseconds": 327843}, "event": "MIGRATION", "data": {"status": "setup"}}
2022-03-07 10:47:07.328+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"return": {}, "id": "libvirt-16"}
2022-03-07 10:47:07.449+0000: 134386: info : qemuMonitorJSONIOProcessLine:235 : QEMU_MONITOR_RECV_EVENT: mon=0x7fa4380028a0 event={"timestamp": {"seconds": 1646650027, "microseconds": 449199}, "event": "MIGRATION_PASS", "data": {"pass": 1}}
2022-03-07 10:47:07.449+0000: 134386: info : qemuMonitorJSONIOProcessLine:235 : QEMU_MONITOR_RECV_EVENT: mon=0x7fa4380028a0 event={"timestamp": {"seconds": 1646650027, "microseconds": 449363}, "event": "MIGRATION", "data": {"status": "active"}}
2022-03-07 10:47:07.807+0000: 134387: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7fa4380028a0 msg={"execute":"query-migrate","id":"libvirt-17"}^M
 fd=-1
2022-03-07 10:47:07.807+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"query-migrate","id":"libvirt-17"}^M
 len=47 ret=47 errno=0
2022-03-07 10:47:07.809+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"return": {"blocked": false, "expected-downtime": 300, "status": "active", "setup-time": 121, "total-time": 481, "ram": {"total": 32213049344, "postcopy-requests": 0, "dirty-sync-count": 1, "multifd-bytes": 0, "pages-per-second": 971380, "page-size": 4096, "remaining": 31357165568, "mbps": 70.597440000000006, "transferred": 28723376, "duplicate": 202401, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 26849280, "normal": 6555}}, "id": "libvirt-17"}
2022-03-07 10:47:20.063+0000: 134386: info : qemuMonitorJSONIOProcessLine:235 : QEMU_MONITOR_RECV_EVENT: mon=0x7fa4380028a0 event={"timestamp": {"seconds": 1646650040, "microseconds": 63299}, "event": "MIGRATION_PASS", "data": {"pass": 2}}
2022-03-07 10:47:20.068+0000: 134386: info : qemuMonitorJSONIOProcessLine:235 : QEMU_MONITOR_RECV_EVENT: mon=0x7fa4380028a0 event={"timestamp": {"seconds": 1646650040, "microseconds": 68660}, "event": "MIGRATION_PASS", "data": {"pass": 3}}
2022-03-07 10:47:20.142+0000: 134386: info : qemuMonitorJSONIOProcessLine:235 : QEMU_MONITOR_RECV_EVENT: mon=0x7fa4380028a0 event={"timestamp": {"seconds": 1646650040, "microseconds": 142735}, "event": "MIGRATION", "data": {"status": "completed"}}
2022-03-07 10:47:20.143+0000: 134391: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7fa4380028a0 msg={"execute":"query-migrate","id":"libvirt-18"}^M
 fd=-1
2022-03-07 10:47:20.143+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"query-migrate","id":"libvirt-18"}^M
 len=47 ret=47 errno=0
2022-03-07 10:47:20.145+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"return": {"blocked": false, "status": "completed", "setup-time": 121, "downtime": 79, "total-time": 12815, "ram": {"total": 32213049344, "postcopy-requests": 0, "dirty-sync-count": 3, "multifd-bytes": 0, "pages-per-second": 32710, "page-size": 4096, "remaining": 0, "mbps": 584.63040491570825, "transferred": 927267953, "duplicate": 7655360, "dirty-pages-rate": 0, "skipped": 0, "normal-bytes": 856694784, "normal": 209154}}, "id": "libvirt-18"}
2022-03-07 10:47:20.145+0000: 134391: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7fa4380028a0 msg={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-19"}^M
 fd=-1
2022-03-07 10:47:20.145+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-19"}^M
 len=93 ret=93 errno=0
2022-03-07 10:47:20.146+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"id": "libvirt-19", "error": {"class": "CommandNotFound", "desc": "The command migrate_set_speed has not been found"}}
2022-03-07 10:47:20.147+0000: 134391: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'migrate_set_speed': The command migrate_set_speed has not been found
2022-03-07 10:47:20.150+0000: 134391: info : qemuMonitorClose:917 : QEMU_MONITOR_CLOSE: mon=0x7fa4380028a0 refs=2


> 
> If you libvirt_log_filters=2:qemu_monitor   then it ought to capture the
> QMP commands.
> 
> Regards,
> Daniel
> 

Re: starting to look at qemu savevm performance, a first regression detected

[Daniel P. Berrangé]

On Mon, Mar 07, 2022 at 12:19:22PM +0100, Claudio Fontana wrote:
> On 3/7/22 10:51 AM, Daniel P. Berrangé wrote:
> > On Mon, Mar 07, 2022 at 10:44:56AM +0100, Claudio Fontana wrote:
> >> Hello Daniel,
> >>
> >> On 3/7/22 10:27 AM, Daniel P. Berrangé wrote:
> >>> On Sat, Mar 05, 2022 at 02:19:39PM +0100, Claudio Fontana wrote:
> >>>>
> >>>> Hello all,
> >>>>
> >>>> I have been looking at some reports of bad qemu savevm performance in large VMs (around 20+ Gb),
> >>>> when used in libvirt commands like:
> >>>>
> >>>>
> >>>> virsh save domain /dev/null
> >>>>
> >>>>
> >>>>
> >>>> I have written a simple test to run in a Linux centos7-minimal-2009 guest, which allocates and touches 20G mem.
> >>>>
> >>>> With any qemu version since around 2020, I am not seeing more than 580 Mb/Sec even in the most ideal of situations.
> >>>>
> >>>> This drops to around 122 Mb/sec after commit: cbde7be900d2a2279cbc4becb91d1ddd6a014def .
> >>>>
> >>>> Here is the bisection for this particular drop in throughput:
> >>>>
> >>>> commit cbde7be900d2a2279cbc4becb91d1ddd6a014def (HEAD, refs/bisect/bad)
> >>>> Author: Daniel P. Berrangé <berrange@redhat.com>
> >>>> Date:   Fri Feb 19 18:40:12 2021 +0000
> >>>>
> >>>>     migrate: remove QMP/HMP commands for speed, downtime and cache size
> >>>>     
> >>>>     The generic 'migrate_set_parameters' command handle all types of param.
> >>>>     
> >>>>     Only the QMP commands were documented in the deprecations page, but the
> >>>>     rationale for deprecating applies equally to HMP, and the replacements
> >>>>     exist. Furthermore the HMP commands are just shims to the QMP commands,
> >>>>     so removing the latter breaks the former unless they get re-implemented.
> >>>>     
> >>>>     Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
> >>>>     Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> >>>
> >>> That doesn't make a whole lot of sense as a bisect result.
> >>> How reliable is that bisect end point ? Have you bisected
> >>> to that point more than once ?
> >>
> >> I did run through the bisect itself only once, so I'll double check that.
> >> The results seem to be reproducible almost to the second though, a savevm that took 35 seconds before the commit takes 2m 48 seconds after.
> >>
> >> For this test I am using libvirt v6.0.0.

I've just noticed this.  That version of libvirt is 2 years old and
doesn't have full support for migrate_set_parameters.


> 2022-03-07 10:47:20.145+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-19"}^M
>  len=93 ret=93 errno=0
> 2022-03-07 10:47:20.146+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"id": "libvirt-19", "error": {"class": "CommandNotFound", "desc": "The command migrate_set_speed has not been found"}}
> 2022-03-07 10:47:20.147+0000: 134391: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'migrate_set_speed': The command migrate_set_speed has not been found

We see the migrate_set_speed failing and libvirt obviously ignores that
failure.

In current libvirt migrate_set_speed is not used as it properly
handles migrate_set_parameters AFAICT.

I think you just need to upgrade libvirt if you want to use this
newer QEMU version

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 :|

Re: starting to look at qemu savevm performance, a first regression detected

[Claudio Fontana]

On 3/7/22 1:00 PM, Daniel P. Berrangé wrote:
> On Mon, Mar 07, 2022 at 12:19:22PM +0100, Claudio Fontana wrote:
>> On 3/7/22 10:51 AM, Daniel P. Berrangé wrote:
>>> On Mon, Mar 07, 2022 at 10:44:56AM +0100, Claudio Fontana wrote:
>>>> Hello Daniel,
>>>>
>>>> On 3/7/22 10:27 AM, Daniel P. Berrangé wrote:
>>>>> On Sat, Mar 05, 2022 at 02:19:39PM +0100, Claudio Fontana wrote:
>>>>>>
>>>>>> Hello all,
>>>>>>
>>>>>> I have been looking at some reports of bad qemu savevm performance in large VMs (around 20+ Gb),
>>>>>> when used in libvirt commands like:
>>>>>>
>>>>>>
>>>>>> virsh save domain /dev/null
>>>>>>
>>>>>>
>>>>>>
>>>>>> I have written a simple test to run in a Linux centos7-minimal-2009 guest, which allocates and touches 20G mem.
>>>>>>
>>>>>> With any qemu version since around 2020, I am not seeing more than 580 Mb/Sec even in the most ideal of situations.
>>>>>>
>>>>>> This drops to around 122 Mb/sec after commit: cbde7be900d2a2279cbc4becb91d1ddd6a014def .
>>>>>>
>>>>>> Here is the bisection for this particular drop in throughput:
>>>>>>
>>>>>> commit cbde7be900d2a2279cbc4becb91d1ddd6a014def (HEAD, refs/bisect/bad)
>>>>>> Author: Daniel P. Berrangé <berrange@redhat.com>
>>>>>> Date:   Fri Feb 19 18:40:12 2021 +0000
>>>>>>
>>>>>>     migrate: remove QMP/HMP commands for speed, downtime and cache size
>>>>>>     
>>>>>>     The generic 'migrate_set_parameters' command handle all types of param.
>>>>>>     
>>>>>>     Only the QMP commands were documented in the deprecations page, but the
>>>>>>     rationale for deprecating applies equally to HMP, and the replacements
>>>>>>     exist. Furthermore the HMP commands are just shims to the QMP commands,
>>>>>>     so removing the latter breaks the former unless they get re-implemented.
>>>>>>     
>>>>>>     Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
>>>>>>     Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
>>>>>
>>>>> That doesn't make a whole lot of sense as a bisect result.
>>>>> How reliable is that bisect end point ? Have you bisected
>>>>> to that point more than once ?
>>>>
>>>> I did run through the bisect itself only once, so I'll double check that.
>>>> The results seem to be reproducible almost to the second though, a savevm that took 35 seconds before the commit takes 2m 48 seconds after.
>>>>
>>>> For this test I am using libvirt v6.0.0.
> 
> I've just noticed this.  That version of libvirt is 2 years old and
> doesn't have full support for migrate_set_parameters.
> 
> 
>> 2022-03-07 10:47:20.145+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-19"}^M
>>  len=93 ret=93 errno=0
>> 2022-03-07 10:47:20.146+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"id": "libvirt-19", "error": {"class": "CommandNotFound", "desc": "The command migrate_set_speed has not been found"}}
>> 2022-03-07 10:47:20.147+0000: 134391: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'migrate_set_speed': The command migrate_set_speed has not been found
> 
> We see the migrate_set_speed failing and libvirt obviously ignores that
> failure.
> 
> In current libvirt migrate_set_speed is not used as it properly
> handles migrate_set_parameters AFAICT.
> 
> I think you just need to upgrade libvirt if you want to use this
> newer QEMU version
> 
> Regards,
> Daniel
> 

Got it, this explains it, sorry for the noise on this.

I'll continue to investigate the general issue of low throughput with virsh save / qemu savevm .

Thanks,

CLaudio

Re: starting to look at qemu savevm performance, a first regression detected

[Daniel P. Berrangé]

On Mon, Mar 07, 2022 at 01:09:55PM +0100, Claudio Fontana wrote:
> On 3/7/22 1:00 PM, Daniel P. Berrangé wrote:
> > On Mon, Mar 07, 2022 at 12:19:22PM +0100, Claudio Fontana wrote:
> >> On 3/7/22 10:51 AM, Daniel P. Berrangé wrote:
> >>> On Mon, Mar 07, 2022 at 10:44:56AM +0100, Claudio Fontana wrote:
> >>>> Hello Daniel,
> >>>>
> >>>> On 3/7/22 10:27 AM, Daniel P. Berrangé wrote:
> >>>>> On Sat, Mar 05, 2022 at 02:19:39PM +0100, Claudio Fontana wrote:
> >>>>>>
> >>>>>> Hello all,
> >>>>>>
> >>>>>> I have been looking at some reports of bad qemu savevm performance in large VMs (around 20+ Gb),
> >>>>>> when used in libvirt commands like:
> >>>>>>
> >>>>>>
> >>>>>> virsh save domain /dev/null
> >>>>>>
> >>>>>>
> >>>>>>
> >>>>>> I have written a simple test to run in a Linux centos7-minimal-2009 guest, which allocates and touches 20G mem.
> >>>>>>
> >>>>>> With any qemu version since around 2020, I am not seeing more than 580 Mb/Sec even in the most ideal of situations.
> >>>>>>
> >>>>>> This drops to around 122 Mb/sec after commit: cbde7be900d2a2279cbc4becb91d1ddd6a014def .
> >>>>>>
> >>>>>> Here is the bisection for this particular drop in throughput:
> >>>>>>
> >>>>>> commit cbde7be900d2a2279cbc4becb91d1ddd6a014def (HEAD, refs/bisect/bad)
> >>>>>> Author: Daniel P. Berrangé <berrange@redhat.com>
> >>>>>> Date:   Fri Feb 19 18:40:12 2021 +0000
> >>>>>>
> >>>>>>     migrate: remove QMP/HMP commands for speed, downtime and cache size
> >>>>>>     
> >>>>>>     The generic 'migrate_set_parameters' command handle all types of param.
> >>>>>>     
> >>>>>>     Only the QMP commands were documented in the deprecations page, but the
> >>>>>>     rationale for deprecating applies equally to HMP, and the replacements
> >>>>>>     exist. Furthermore the HMP commands are just shims to the QMP commands,
> >>>>>>     so removing the latter breaks the former unless they get re-implemented.
> >>>>>>     
> >>>>>>     Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
> >>>>>>     Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> >>>>>
> >>>>> That doesn't make a whole lot of sense as a bisect result.
> >>>>> How reliable is that bisect end point ? Have you bisected
> >>>>> to that point more than once ?
> >>>>
> >>>> I did run through the bisect itself only once, so I'll double check that.
> >>>> The results seem to be reproducible almost to the second though, a savevm that took 35 seconds before the commit takes 2m 48 seconds after.
> >>>>
> >>>> For this test I am using libvirt v6.0.0.
> > 
> > I've just noticed this.  That version of libvirt is 2 years old and
> > doesn't have full support for migrate_set_parameters.
> > 
> > 
> >> 2022-03-07 10:47:20.145+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-19"}^M
> >>  len=93 ret=93 errno=0
> >> 2022-03-07 10:47:20.146+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"id": "libvirt-19", "error": {"class": "CommandNotFound", "desc": "The command migrate_set_speed has not been found"}}
> >> 2022-03-07 10:47:20.147+0000: 134391: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'migrate_set_speed': The command migrate_set_speed has not been found
> > 
> > We see the migrate_set_speed failing and libvirt obviously ignores that
> > failure.
> > 
> > In current libvirt migrate_set_speed is not used as it properly
> > handles migrate_set_parameters AFAICT.
> > 
> > I think you just need to upgrade libvirt if you want to use this
> > newer QEMU version
> > 
> > Regards,
> > Daniel
> > 
> 
> Got it, this explains it, sorry for the noise on this.
> 
> I'll continue to investigate the general issue of low throughput with virsh save / qemu savevm .

BTW, consider measuring with the --bypass-cache flag to virsh save.
This causes libvirt to use a I/O helper that uses O_DIRECT when
saving the image. This should give more predictable results by
avoiding the influence of host I/O cache which can be in a differnt
state of usage each time you measure.  It was also intended that
by avoiding hitting cache, saving the memory image of a large VM
will not push other useful stuff out of host I/O  cache which can
negatively impact other running VMs.

Also it is possible to configure compression on the libvirt side
which may be useful if you have spare CPU cycles, but your storage
is slow. See 'save_image_format' in the /etc/libvirt/qemu.conf

With 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 :|

Re: starting to look at qemu savevm performance, a first regression detected

[Claudio Fontana]

On 3/7/22 1:20 PM, Daniel P. Berrangé wrote:
> On Mon, Mar 07, 2022 at 01:09:55PM +0100, Claudio Fontana wrote:
>> On 3/7/22 1:00 PM, Daniel P. Berrangé wrote:
>>> On Mon, Mar 07, 2022 at 12:19:22PM +0100, Claudio Fontana wrote:
>>>> On 3/7/22 10:51 AM, Daniel P. Berrangé wrote:
>>>>> On Mon, Mar 07, 2022 at 10:44:56AM +0100, Claudio Fontana wrote:
>>>>>> Hello Daniel,
>>>>>>
>>>>>> On 3/7/22 10:27 AM, Daniel P. Berrangé wrote:
>>>>>>> On Sat, Mar 05, 2022 at 02:19:39PM +0100, Claudio Fontana wrote:
>>>>>>>>
>>>>>>>> Hello all,
>>>>>>>>
>>>>>>>> I have been looking at some reports of bad qemu savevm performance in large VMs (around 20+ Gb),
>>>>>>>> when used in libvirt commands like:
>>>>>>>>
>>>>>>>>
>>>>>>>> virsh save domain /dev/null
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>> I have written a simple test to run in a Linux centos7-minimal-2009 guest, which allocates and touches 20G mem.
>>>>>>>>
>>>>>>>> With any qemu version since around 2020, I am not seeing more than 580 Mb/Sec even in the most ideal of situations.
>>>>>>>>
>>>>>>>> This drops to around 122 Mb/sec after commit: cbde7be900d2a2279cbc4becb91d1ddd6a014def .
>>>>>>>>
>>>>>>>> Here is the bisection for this particular drop in throughput:
>>>>>>>>
>>>>>>>> commit cbde7be900d2a2279cbc4becb91d1ddd6a014def (HEAD, refs/bisect/bad)
>>>>>>>> Author: Daniel P. Berrangé <berrange@redhat.com>
>>>>>>>> Date:   Fri Feb 19 18:40:12 2021 +0000
>>>>>>>>
>>>>>>>>     migrate: remove QMP/HMP commands for speed, downtime and cache size
>>>>>>>>     
>>>>>>>>     The generic 'migrate_set_parameters' command handle all types of param.
>>>>>>>>     
>>>>>>>>     Only the QMP commands were documented in the deprecations page, but the
>>>>>>>>     rationale for deprecating applies equally to HMP, and the replacements
>>>>>>>>     exist. Furthermore the HMP commands are just shims to the QMP commands,
>>>>>>>>     so removing the latter breaks the former unless they get re-implemented.
>>>>>>>>     
>>>>>>>>     Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
>>>>>>>>     Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
>>>>>>>
>>>>>>> That doesn't make a whole lot of sense as a bisect result.
>>>>>>> How reliable is that bisect end point ? Have you bisected
>>>>>>> to that point more than once ?
>>>>>>
>>>>>> I did run through the bisect itself only once, so I'll double check that.
>>>>>> The results seem to be reproducible almost to the second though, a savevm that took 35 seconds before the commit takes 2m 48 seconds after.
>>>>>>
>>>>>> For this test I am using libvirt v6.0.0.
>>>
>>> I've just noticed this.  That version of libvirt is 2 years old and
>>> doesn't have full support for migrate_set_parameters.
>>>
>>>
>>>> 2022-03-07 10:47:20.145+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-19"}^M
>>>>  len=93 ret=93 errno=0
>>>> 2022-03-07 10:47:20.146+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"id": "libvirt-19", "error": {"class": "CommandNotFound", "desc": "The command migrate_set_speed has not been found"}}
>>>> 2022-03-07 10:47:20.147+0000: 134391: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'migrate_set_speed': The command migrate_set_speed has not been found
>>>
>>> We see the migrate_set_speed failing and libvirt obviously ignores that
>>> failure.
>>>
>>> In current libvirt migrate_set_speed is not used as it properly
>>> handles migrate_set_parameters AFAICT.
>>>
>>> I think you just need to upgrade libvirt if you want to use this
>>> newer QEMU version
>>>
>>> Regards,
>>> Daniel
>>>
>>
>> Got it, this explains it, sorry for the noise on this.
>>
>> I'll continue to investigate the general issue of low throughput with virsh save / qemu savevm .
> 
> BTW, consider measuring with the --bypass-cache flag to virsh save.
> This causes libvirt to use a I/O helper that uses O_DIRECT when
> saving the image. This should give more predictable results by
> avoiding the influence of host I/O cache which can be in a differnt
> state of usage each time you measure.  It was also intended that
> by avoiding hitting cache, saving the memory image of a large VM
> will not push other useful stuff out of host I/O  cache which can
> negatively impact other running VMs.
> 
> Also it is possible to configure compression on the libvirt side
> which may be useful if you have spare CPU cycles, but your storage
> is slow. See 'save_image_format' in the /etc/libvirt/qemu.conf
> 
> With regards,
> Daniel
> 

Hi Daniel, thanks for these good info,

regarding slow storage, for these tests I am saving to /dev/null to avoid having to take storage into account
(and still getting low bandwidth unfortunately) so I guess compression is out of the question.

Thanks!

Claudio

Re: starting to look at qemu savevm performance, a first regression detected

[Dr. David Alan Gilbert]

* Claudio Fontana (cfontana@suse.de) wrote:
> On 3/7/22 1:20 PM, Daniel P. Berrangé wrote:
> > On Mon, Mar 07, 2022 at 01:09:55PM +0100, Claudio Fontana wrote:
> >> On 3/7/22 1:00 PM, Daniel P. Berrangé wrote:
> >>> On Mon, Mar 07, 2022 at 12:19:22PM +0100, Claudio Fontana wrote:
> >>>> On 3/7/22 10:51 AM, Daniel P. Berrangé wrote:
> >>>>> On Mon, Mar 07, 2022 at 10:44:56AM +0100, Claudio Fontana wrote:
> >>>>>> Hello Daniel,
> >>>>>>
> >>>>>> On 3/7/22 10:27 AM, Daniel P. Berrangé wrote:
> >>>>>>> On Sat, Mar 05, 2022 at 02:19:39PM +0100, Claudio Fontana wrote:
> >>>>>>>>
> >>>>>>>> Hello all,
> >>>>>>>>
> >>>>>>>> I have been looking at some reports of bad qemu savevm performance in large VMs (around 20+ Gb),
> >>>>>>>> when used in libvirt commands like:
> >>>>>>>>
> >>>>>>>>
> >>>>>>>> virsh save domain /dev/null
> >>>>>>>>
> >>>>>>>>
> >>>>>>>>
> >>>>>>>> I have written a simple test to run in a Linux centos7-minimal-2009 guest, which allocates and touches 20G mem.
> >>>>>>>>
> >>>>>>>> With any qemu version since around 2020, I am not seeing more than 580 Mb/Sec even in the most ideal of situations.
> >>>>>>>>
> >>>>>>>> This drops to around 122 Mb/sec after commit: cbde7be900d2a2279cbc4becb91d1ddd6a014def .
> >>>>>>>>
> >>>>>>>> Here is the bisection for this particular drop in throughput:
> >>>>>>>>
> >>>>>>>> commit cbde7be900d2a2279cbc4becb91d1ddd6a014def (HEAD, refs/bisect/bad)
> >>>>>>>> Author: Daniel P. Berrangé <berrange@redhat.com>
> >>>>>>>> Date:   Fri Feb 19 18:40:12 2021 +0000
> >>>>>>>>
> >>>>>>>>     migrate: remove QMP/HMP commands for speed, downtime and cache size
> >>>>>>>>     
> >>>>>>>>     The generic 'migrate_set_parameters' command handle all types of param.
> >>>>>>>>     
> >>>>>>>>     Only the QMP commands were documented in the deprecations page, but the
> >>>>>>>>     rationale for deprecating applies equally to HMP, and the replacements
> >>>>>>>>     exist. Furthermore the HMP commands are just shims to the QMP commands,
> >>>>>>>>     so removing the latter breaks the former unless they get re-implemented.
> >>>>>>>>     
> >>>>>>>>     Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
> >>>>>>>>     Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> >>>>>>>
> >>>>>>> That doesn't make a whole lot of sense as a bisect result.
> >>>>>>> How reliable is that bisect end point ? Have you bisected
> >>>>>>> to that point more than once ?
> >>>>>>
> >>>>>> I did run through the bisect itself only once, so I'll double check that.
> >>>>>> The results seem to be reproducible almost to the second though, a savevm that took 35 seconds before the commit takes 2m 48 seconds after.
> >>>>>>
> >>>>>> For this test I am using libvirt v6.0.0.
> >>>
> >>> I've just noticed this.  That version of libvirt is 2 years old and
> >>> doesn't have full support for migrate_set_parameters.
> >>>
> >>>
> >>>> 2022-03-07 10:47:20.145+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-19"}^M
> >>>>  len=93 ret=93 errno=0
> >>>> 2022-03-07 10:47:20.146+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"id": "libvirt-19", "error": {"class": "CommandNotFound", "desc": "The command migrate_set_speed has not been found"}}
> >>>> 2022-03-07 10:47:20.147+0000: 134391: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'migrate_set_speed': The command migrate_set_speed has not been found
> >>>
> >>> We see the migrate_set_speed failing and libvirt obviously ignores that
> >>> failure.
> >>>
> >>> In current libvirt migrate_set_speed is not used as it properly
> >>> handles migrate_set_parameters AFAICT.
> >>>
> >>> I think you just need to upgrade libvirt if you want to use this
> >>> newer QEMU version
> >>>
> >>> Regards,
> >>> Daniel
> >>>
> >>
> >> Got it, this explains it, sorry for the noise on this.
> >>
> >> I'll continue to investigate the general issue of low throughput with virsh save / qemu savevm .
> > 
> > BTW, consider measuring with the --bypass-cache flag to virsh save.
> > This causes libvirt to use a I/O helper that uses O_DIRECT when
> > saving the image. This should give more predictable results by
> > avoiding the influence of host I/O cache which can be in a differnt
> > state of usage each time you measure.  It was also intended that
> > by avoiding hitting cache, saving the memory image of a large VM
> > will not push other useful stuff out of host I/O  cache which can
> > negatively impact other running VMs.
> > 
> > Also it is possible to configure compression on the libvirt side
> > which may be useful if you have spare CPU cycles, but your storage
> > is slow. See 'save_image_format' in the /etc/libvirt/qemu.conf
> > 
> > With regards,
> > Daniel
> > 
> 
> Hi Daniel, thanks for these good info,
> 
> regarding slow storage, for these tests I am saving to /dev/null to avoid having to take storage into account
> (and still getting low bandwidth unfortunately) so I guess compression is out of the question.

What type of speeds do you get if you try a migrate to a netcat socket?

Dave

> Thanks!
> 
> Claudio
> 
-- 
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

bad qemu savevm to /dev/null performance (600 MiB/s max) (Was: Re: starting to look at qemu savevm performance, a first regression detected)

[Claudio Fontana]

On 3/7/22 1:28 PM, Dr. David Alan Gilbert wrote:
> * Claudio Fontana (cfontana@suse.de) wrote:
>> On 3/7/22 1:20 PM, Daniel P. Berrangé wrote:
>>> On Mon, Mar 07, 2022 at 01:09:55PM +0100, Claudio Fontana wrote:
>>>> On 3/7/22 1:00 PM, Daniel P. Berrangé wrote:
>>>>> On Mon, Mar 07, 2022 at 12:19:22PM +0100, Claudio Fontana wrote:
>>>>>> On 3/7/22 10:51 AM, Daniel P. Berrangé wrote:
>>>>>>> On Mon, Mar 07, 2022 at 10:44:56AM +0100, Claudio Fontana wrote:
>>>>>>>> Hello Daniel,
>>>>>>>>
>>>>>>>> On 3/7/22 10:27 AM, Daniel P. Berrangé wrote:
>>>>>>>>> On Sat, Mar 05, 2022 at 02:19:39PM +0100, Claudio Fontana wrote:
>>>>>>>>>>
>>>>>>>>>> Hello all,
>>>>>>>>>>
>>>>>>>>>> I have been looking at some reports of bad qemu savevm performance in large VMs (around 20+ Gb),
>>>>>>>>>> when used in libvirt commands like:
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> virsh save domain /dev/null
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> I have written a simple test to run in a Linux centos7-minimal-2009 guest, which allocates and touches 20G mem.
>>>>>>>>>>
>>>>>>>>>> With any qemu version since around 2020, I am not seeing more than 580 Mb/Sec even in the most ideal of situations.
>>>>>>>>>>
>>>>>>>>>> This drops to around 122 Mb/sec after commit: cbde7be900d2a2279cbc4becb91d1ddd6a014def .
>>>>>>>>>>
>>>>>>>>>> Here is the bisection for this particular drop in throughput:
>>>>>>>>>>
>>>>>>>>>> commit cbde7be900d2a2279cbc4becb91d1ddd6a014def (HEAD, refs/bisect/bad)
>>>>>>>>>> Author: Daniel P. Berrangé <berrange@redhat.com>
>>>>>>>>>> Date:   Fri Feb 19 18:40:12 2021 +0000
>>>>>>>>>>
>>>>>>>>>>     migrate: remove QMP/HMP commands for speed, downtime and cache size
>>>>>>>>>>     
>>>>>>>>>>     The generic 'migrate_set_parameters' command handle all types of param.
>>>>>>>>>>     
>>>>>>>>>>     Only the QMP commands were documented in the deprecations page, but the
>>>>>>>>>>     rationale for deprecating applies equally to HMP, and the replacements
>>>>>>>>>>     exist. Furthermore the HMP commands are just shims to the QMP commands,
>>>>>>>>>>     so removing the latter breaks the former unless they get re-implemented.
>>>>>>>>>>     
>>>>>>>>>>     Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
>>>>>>>>>>     Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
>>>>>>>>>
>>>>>>>>> That doesn't make a whole lot of sense as a bisect result.
>>>>>>>>> How reliable is that bisect end point ? Have you bisected
>>>>>>>>> to that point more than once ?
>>>>>>>>
>>>>>>>> I did run through the bisect itself only once, so I'll double check that.
>>>>>>>> The results seem to be reproducible almost to the second though, a savevm that took 35 seconds before the commit takes 2m 48 seconds after.
>>>>>>>>
>>>>>>>> For this test I am using libvirt v6.0.0.
>>>>>
>>>>> I've just noticed this.  That version of libvirt is 2 years old and
>>>>> doesn't have full support for migrate_set_parameters.
>>>>>
>>>>>
>>>>>> 2022-03-07 10:47:20.145+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-19"}^M
>>>>>>  len=93 ret=93 errno=0
>>>>>> 2022-03-07 10:47:20.146+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"id": "libvirt-19", "error": {"class": "CommandNotFound", "desc": "The command migrate_set_speed has not been found"}}
>>>>>> 2022-03-07 10:47:20.147+0000: 134391: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'migrate_set_speed': The command migrate_set_speed has not been found
>>>>>
>>>>> We see the migrate_set_speed failing and libvirt obviously ignores that
>>>>> failure.
>>>>>
>>>>> In current libvirt migrate_set_speed is not used as it properly
>>>>> handles migrate_set_parameters AFAICT.
>>>>>
>>>>> I think you just need to upgrade libvirt if you want to use this
>>>>> newer QEMU version
>>>>>
>>>>> Regards,
>>>>> Daniel
>>>>>
>>>>
>>>> Got it, this explains it, sorry for the noise on this.
>>>>
>>>> I'll continue to investigate the general issue of low throughput with virsh save / qemu savevm .
>>>
>>> BTW, consider measuring with the --bypass-cache flag to virsh save.
>>> This causes libvirt to use a I/O helper that uses O_DIRECT when
>>> saving the image. This should give more predictable results by
>>> avoiding the influence of host I/O cache which can be in a differnt
>>> state of usage each time you measure.  It was also intended that
>>> by avoiding hitting cache, saving the memory image of a large VM
>>> will not push other useful stuff out of host I/O  cache which can
>>> negatively impact other running VMs.
>>>
>>> Also it is possible to configure compression on the libvirt side
>>> which may be useful if you have spare CPU cycles, but your storage
>>> is slow. See 'save_image_format' in the /etc/libvirt/qemu.conf
>>>
>>> With regards,
>>> Daniel
>>>
>>
>> Hi Daniel, thanks for these good info,
>>
>> regarding slow storage, for these tests I am saving to /dev/null to avoid having to take storage into account
>> (and still getting low bandwidth unfortunately) so I guess compression is out of the question.
> 
> What type of speeds do you get if you try a migrate to a netcat socket?

much faster apparently, 30 sec savevm vs 7 seconds for migration to a netcat socket sent to /dev/null.

nc -l -U /tmp/savevm.socket

virsh suspend centos7
Domain centos7 suspended

virsh qemu-monitor-command --cmd '{ "execute": "migrate", "arguments": { "uri": "unix:///tmp/savevm.socket" } }' centos7

virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
{"return":{"blocked":false,"status":"completed","setup-time":118,"downtime":257,"total-time":7524,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":1057530,"page-size":4096,"remaining":0,"mbps":24215.572437483122,"transferred":22417172290,"duplicate":2407520,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22351847424,"normal":5456994}},"id":"libvirt-438"}

virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
{"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":8,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-439"}


I did also a run with multifd-channels:1 instead of 8, if it matters:


virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
{"return":{"blocked":false,"status":"completed","setup-time":119,"downtime":260,"total-time":8601,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":908820,"page-size":4096,"remaining":0,"mbps":21141.861157274227,"transferred":22415264188,"duplicate":2407986,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22349938688,"normal":5456528}},"id":"libvirt-453"}

virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
{"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":1,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-454"}


Still we are in the 20 Gbps range, or around 2560 MiB/s, way faster than savevm which does around 600 MiB/s when the wind is in its favor..

Thanks,

Claudio

Re: bad qemu savevm to /dev/null performance (600 MiB/s max) (Was: Re: starting to look at qemu savevm performance, a first regression detected)

[Dr. David Alan Gilbert]

* Claudio Fontana (cfontana@suse.de) wrote:
> On 3/7/22 1:28 PM, Dr. David Alan Gilbert wrote:
> > * Claudio Fontana (cfontana@suse.de) wrote:
> >> On 3/7/22 1:20 PM, Daniel P. Berrangé wrote:
> >>> On Mon, Mar 07, 2022 at 01:09:55PM +0100, Claudio Fontana wrote:
> >>>> On 3/7/22 1:00 PM, Daniel P. Berrangé wrote:
> >>>>> On Mon, Mar 07, 2022 at 12:19:22PM +0100, Claudio Fontana wrote:
> >>>>>> On 3/7/22 10:51 AM, Daniel P. Berrangé wrote:
> >>>>>>> On Mon, Mar 07, 2022 at 10:44:56AM +0100, Claudio Fontana wrote:
> >>>>>>>> Hello Daniel,
> >>>>>>>>
> >>>>>>>> On 3/7/22 10:27 AM, Daniel P. Berrangé wrote:
> >>>>>>>>> On Sat, Mar 05, 2022 at 02:19:39PM +0100, Claudio Fontana wrote:
> >>>>>>>>>>
> >>>>>>>>>> Hello all,
> >>>>>>>>>>
> >>>>>>>>>> I have been looking at some reports of bad qemu savevm performance in large VMs (around 20+ Gb),
> >>>>>>>>>> when used in libvirt commands like:
> >>>>>>>>>>
> >>>>>>>>>>
> >>>>>>>>>> virsh save domain /dev/null
> >>>>>>>>>>
> >>>>>>>>>>
> >>>>>>>>>>
> >>>>>>>>>> I have written a simple test to run in a Linux centos7-minimal-2009 guest, which allocates and touches 20G mem.
> >>>>>>>>>>
> >>>>>>>>>> With any qemu version since around 2020, I am not seeing more than 580 Mb/Sec even in the most ideal of situations.
> >>>>>>>>>>
> >>>>>>>>>> This drops to around 122 Mb/sec after commit: cbde7be900d2a2279cbc4becb91d1ddd6a014def .
> >>>>>>>>>>
> >>>>>>>>>> Here is the bisection for this particular drop in throughput:
> >>>>>>>>>>
> >>>>>>>>>> commit cbde7be900d2a2279cbc4becb91d1ddd6a014def (HEAD, refs/bisect/bad)
> >>>>>>>>>> Author: Daniel P. Berrangé <berrange@redhat.com>
> >>>>>>>>>> Date:   Fri Feb 19 18:40:12 2021 +0000
> >>>>>>>>>>
> >>>>>>>>>>     migrate: remove QMP/HMP commands for speed, downtime and cache size
> >>>>>>>>>>     
> >>>>>>>>>>     The generic 'migrate_set_parameters' command handle all types of param.
> >>>>>>>>>>     
> >>>>>>>>>>     Only the QMP commands were documented in the deprecations page, but the
> >>>>>>>>>>     rationale for deprecating applies equally to HMP, and the replacements
> >>>>>>>>>>     exist. Furthermore the HMP commands are just shims to the QMP commands,
> >>>>>>>>>>     so removing the latter breaks the former unless they get re-implemented.
> >>>>>>>>>>     
> >>>>>>>>>>     Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
> >>>>>>>>>>     Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
> >>>>>>>>>
> >>>>>>>>> That doesn't make a whole lot of sense as a bisect result.
> >>>>>>>>> How reliable is that bisect end point ? Have you bisected
> >>>>>>>>> to that point more than once ?
> >>>>>>>>
> >>>>>>>> I did run through the bisect itself only once, so I'll double check that.
> >>>>>>>> The results seem to be reproducible almost to the second though, a savevm that took 35 seconds before the commit takes 2m 48 seconds after.
> >>>>>>>>
> >>>>>>>> For this test I am using libvirt v6.0.0.
> >>>>>
> >>>>> I've just noticed this.  That version of libvirt is 2 years old and
> >>>>> doesn't have full support for migrate_set_parameters.
> >>>>>
> >>>>>
> >>>>>> 2022-03-07 10:47:20.145+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-19"}^M
> >>>>>>  len=93 ret=93 errno=0
> >>>>>> 2022-03-07 10:47:20.146+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"id": "libvirt-19", "error": {"class": "CommandNotFound", "desc": "The command migrate_set_speed has not been found"}}
> >>>>>> 2022-03-07 10:47:20.147+0000: 134391: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'migrate_set_speed': The command migrate_set_speed has not been found
> >>>>>
> >>>>> We see the migrate_set_speed failing and libvirt obviously ignores that
> >>>>> failure.
> >>>>>
> >>>>> In current libvirt migrate_set_speed is not used as it properly
> >>>>> handles migrate_set_parameters AFAICT.
> >>>>>
> >>>>> I think you just need to upgrade libvirt if you want to use this
> >>>>> newer QEMU version
> >>>>>
> >>>>> Regards,
> >>>>> Daniel
> >>>>>
> >>>>
> >>>> Got it, this explains it, sorry for the noise on this.
> >>>>
> >>>> I'll continue to investigate the general issue of low throughput with virsh save / qemu savevm .
> >>>
> >>> BTW, consider measuring with the --bypass-cache flag to virsh save.
> >>> This causes libvirt to use a I/O helper that uses O_DIRECT when
> >>> saving the image. This should give more predictable results by
> >>> avoiding the influence of host I/O cache which can be in a differnt
> >>> state of usage each time you measure.  It was also intended that
> >>> by avoiding hitting cache, saving the memory image of a large VM
> >>> will not push other useful stuff out of host I/O  cache which can
> >>> negatively impact other running VMs.
> >>>
> >>> Also it is possible to configure compression on the libvirt side
> >>> which may be useful if you have spare CPU cycles, but your storage
> >>> is slow. See 'save_image_format' in the /etc/libvirt/qemu.conf
> >>>
> >>> With regards,
> >>> Daniel
> >>>
> >>
> >> Hi Daniel, thanks for these good info,
> >>
> >> regarding slow storage, for these tests I am saving to /dev/null to avoid having to take storage into account
> >> (and still getting low bandwidth unfortunately) so I guess compression is out of the question.
> > 
> > What type of speeds do you get if you try a migrate to a netcat socket?
> 
> much faster apparently, 30 sec savevm vs 7 seconds for migration to a netcat socket sent to /dev/null.
> 
> nc -l -U /tmp/savevm.socket
> 
> virsh suspend centos7
> Domain centos7 suspended
> 
> virsh qemu-monitor-command --cmd '{ "execute": "migrate", "arguments": { "uri": "unix:///tmp/savevm.socket" } }' centos7
> 
> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
> {"return":{"blocked":false,"status":"completed","setup-time":118,"downtime":257,"total-time":7524,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":1057530,"page-size":4096,"remaining":0,"mbps":24215.572437483122,"transferred":22417172290,"duplicate":2407520,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22351847424,"normal":5456994}},"id":"libvirt-438"}
> 
> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
> {"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":8,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-439"}
> 
> 
> I did also a run with multifd-channels:1 instead of 8, if it matters:

I suspect you haven't actually got multifd enabled ( check
query-migrate-capabilities ?).
> 
> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
> {"return":{"blocked":false,"status":"completed","setup-time":119,"downtime":260,"total-time":8601,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":908820,"page-size":4096,"remaining":0,"mbps":21141.861157274227,"transferred":22415264188,"duplicate":2407986,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22349938688,"normal":5456528}},"id":"libvirt-453"}
> 
> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
> {"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":1,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-454"}
> 
> 
> Still we are in the 20 Gbps range, or around 2560 MiB/s, way faster than savevm which does around 600 MiB/s when the wind is in its favor..

Yeh that's what I'd hope for off a decent CPU; hmm there's not that much
savevm specific is there?

Dave

> Thanks,
> 
> Claudio
> 
-- 
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: bad qemu savevm to /dev/null performance (600 MiB/s max) (Was: Re: starting to look at qemu savevm performance, a first regression detected)

[Daniel P. Berrangé]

On Wed, Mar 09, 2022 at 11:43:48AM +0000, Dr. David Alan Gilbert wrote:
> * Claudio Fontana (cfontana@suse.de) wrote:
> > On 3/7/22 1:28 PM, Dr. David Alan Gilbert wrote:
> > > * Claudio Fontana (cfontana@suse.de) wrote:
> > >> On 3/7/22 1:20 PM, Daniel P. Berrangé wrote:
> > >>> On Mon, Mar 07, 2022 at 01:09:55PM +0100, Claudio Fontana wrote:
> > >>>> Got it, this explains it, sorry for the noise on this.
> > >>>>
> > >>>> I'll continue to investigate the general issue of low throughput with virsh save / qemu savevm .
> > >>>
> > >>> BTW, consider measuring with the --bypass-cache flag to virsh save.
> > >>> This causes libvirt to use a I/O helper that uses O_DIRECT when
> > >>> saving the image. This should give more predictable results by
> > >>> avoiding the influence of host I/O cache which can be in a differnt
> > >>> state of usage each time you measure.  It was also intended that
> > >>> by avoiding hitting cache, saving the memory image of a large VM
> > >>> will not push other useful stuff out of host I/O  cache which can
> > >>> negatively impact other running VMs.
> > >>>
> > >>> Also it is possible to configure compression on the libvirt side
> > >>> which may be useful if you have spare CPU cycles, but your storage
> > >>> is slow. See 'save_image_format' in the /etc/libvirt/qemu.conf
> > >>>
> > >>> With regards,
> > >>> Daniel
> > >>>
> > >>
> > >> Hi Daniel, thanks for these good info,
> > >>
> > >> regarding slow storage, for these tests I am saving to /dev/null to avoid having to take storage into account
> > >> (and still getting low bandwidth unfortunately) so I guess compression is out of the question.
> > > 
> > > What type of speeds do you get if you try a migrate to a netcat socket?
> > 
> > much faster apparently, 30 sec savevm vs 7 seconds for migration to a netcat socket sent to /dev/null.
> > 
> > nc -l -U /tmp/savevm.socket
> > 
> > virsh suspend centos7
> > Domain centos7 suspended
> > 
> > virsh qemu-monitor-command --cmd '{ "execute": "migrate", "arguments": { "uri": "unix:///tmp/savevm.socket" } }' centos7
> > 
> > virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
> > {"return":{"blocked":false,"status":"completed","setup-time":118,"downtime":257,"total-time":7524,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":1057530,"page-size":4096,"remaining":0,"mbps":24215.572437483122,"transferred":22417172290,"duplicate":2407520,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22351847424,"normal":5456994}},"id":"libvirt-438"}
> > 
> > virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
> > {"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":8,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-439"}
> > 
> > 
> > I did also a run with multifd-channels:1 instead of 8, if it matters:
> 
> I suspect you haven't actually got multifd enabled ( check
> query-migrate-capabilities ?).
> > 
> > virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
> > {"return":{"blocked":false,"status":"completed","setup-time":119,"downtime":260,"total-time":8601,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":908820,"page-size":4096,"remaining":0,"mbps":21141.861157274227,"transferred":22415264188,"duplicate":2407986,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22349938688,"normal":5456528}},"id":"libvirt-453"}
> > 
> > virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
> > {"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":1,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-454"}
> > 
> > 
> > Still we are in the 20 Gbps range, or around 2560 MiB/s, way faster than savevm which does around 600 MiB/s when the wind is in its favor..
> 
> Yeh that's what I'd hope for off a decent CPU; hmm there's not that much
> savevm specific is there?

BTW, quick clarification here.

IIUC, Claudio says the test is 'virsh save $VMNAME /some/file'. This
is *not* running 'savevm' at the QEMU level. So it is a bit misleading
refering to it as savevm in the thread here.

'virsh save' is simply wired up to the normal QEMU 'migrate' commands,
with libvirt giving QEMU a pre-opened FD, which libvirt processes the
other end of to write out to disk.

IOW, the performance delta is possibly on libvirt's side rather
than QEMU's.

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 :|

Re: bad qemu savevm to /dev/null performance (600 MiB/s max) (Was: Re: starting to look at qemu savevm performance, a first regression detected)

[Claudio Fontana]

On 3/9/22 12:43 PM, Dr. David Alan Gilbert wrote:
> * Claudio Fontana (cfontana@suse.de) wrote:
>> On 3/7/22 1:28 PM, Dr. David Alan Gilbert wrote:
>>> * Claudio Fontana (cfontana@suse.de) wrote:
>>>> On 3/7/22 1:20 PM, Daniel P. Berrangé wrote:
>>>>> On Mon, Mar 07, 2022 at 01:09:55PM +0100, Claudio Fontana wrote:
>>>>>> On 3/7/22 1:00 PM, Daniel P. Berrangé wrote:
>>>>>>> On Mon, Mar 07, 2022 at 12:19:22PM +0100, Claudio Fontana wrote:
>>>>>>>> On 3/7/22 10:51 AM, Daniel P. Berrangé wrote:
>>>>>>>>> On Mon, Mar 07, 2022 at 10:44:56AM +0100, Claudio Fontana wrote:
>>>>>>>>>> Hello Daniel,
>>>>>>>>>>
>>>>>>>>>> On 3/7/22 10:27 AM, Daniel P. Berrangé wrote:
>>>>>>>>>>> On Sat, Mar 05, 2022 at 02:19:39PM +0100, Claudio Fontana wrote:
>>>>>>>>>>>>
>>>>>>>>>>>> Hello all,
>>>>>>>>>>>>
>>>>>>>>>>>> I have been looking at some reports of bad qemu savevm performance in large VMs (around 20+ Gb),
>>>>>>>>>>>> when used in libvirt commands like:
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> virsh save domain /dev/null
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> I have written a simple test to run in a Linux centos7-minimal-2009 guest, which allocates and touches 20G mem.
>>>>>>>>>>>>
>>>>>>>>>>>> With any qemu version since around 2020, I am not seeing more than 580 Mb/Sec even in the most ideal of situations.
>>>>>>>>>>>>
>>>>>>>>>>>> This drops to around 122 Mb/sec after commit: cbde7be900d2a2279cbc4becb91d1ddd6a014def .
>>>>>>>>>>>>
>>>>>>>>>>>> Here is the bisection for this particular drop in throughput:
>>>>>>>>>>>>
>>>>>>>>>>>> commit cbde7be900d2a2279cbc4becb91d1ddd6a014def (HEAD, refs/bisect/bad)
>>>>>>>>>>>> Author: Daniel P. Berrangé <berrange@redhat.com>
>>>>>>>>>>>> Date:   Fri Feb 19 18:40:12 2021 +0000
>>>>>>>>>>>>
>>>>>>>>>>>>     migrate: remove QMP/HMP commands for speed, downtime and cache size
>>>>>>>>>>>>     
>>>>>>>>>>>>     The generic 'migrate_set_parameters' command handle all types of param.
>>>>>>>>>>>>     
>>>>>>>>>>>>     Only the QMP commands were documented in the deprecations page, but the
>>>>>>>>>>>>     rationale for deprecating applies equally to HMP, and the replacements
>>>>>>>>>>>>     exist. Furthermore the HMP commands are just shims to the QMP commands,
>>>>>>>>>>>>     so removing the latter breaks the former unless they get re-implemented.
>>>>>>>>>>>>     
>>>>>>>>>>>>     Reviewed-by: Dr. David Alan Gilbert <dgilbert@redhat.com>
>>>>>>>>>>>>     Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
>>>>>>>>>>>
>>>>>>>>>>> That doesn't make a whole lot of sense as a bisect result.
>>>>>>>>>>> How reliable is that bisect end point ? Have you bisected
>>>>>>>>>>> to that point more than once ?
>>>>>>>>>>
>>>>>>>>>> I did run through the bisect itself only once, so I'll double check that.
>>>>>>>>>> The results seem to be reproducible almost to the second though, a savevm that took 35 seconds before the commit takes 2m 48 seconds after.
>>>>>>>>>>
>>>>>>>>>> For this test I am using libvirt v6.0.0.
>>>>>>>
>>>>>>> I've just noticed this.  That version of libvirt is 2 years old and
>>>>>>> doesn't have full support for migrate_set_parameters.
>>>>>>>
>>>>>>>
>>>>>>>> 2022-03-07 10:47:20.145+0000: 134386: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7fa4380028a0 buf={"execute":"migrate_set_speed","arguments":{"value":9223372036853727232},"id":"libvirt-19"}^M
>>>>>>>>  len=93 ret=93 errno=0
>>>>>>>> 2022-03-07 10:47:20.146+0000: 134386: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7fa4380028a0 reply={"id": "libvirt-19", "error": {"class": "CommandNotFound", "desc": "The command migrate_set_speed has not been found"}}
>>>>>>>> 2022-03-07 10:47:20.147+0000: 134391: error : qemuMonitorJSONCheckError:412 : internal error: unable to execute QEMU command 'migrate_set_speed': The command migrate_set_speed has not been found
>>>>>>>
>>>>>>> We see the migrate_set_speed failing and libvirt obviously ignores that
>>>>>>> failure.
>>>>>>>
>>>>>>> In current libvirt migrate_set_speed is not used as it properly
>>>>>>> handles migrate_set_parameters AFAICT.
>>>>>>>
>>>>>>> I think you just need to upgrade libvirt if you want to use this
>>>>>>> newer QEMU version
>>>>>>>
>>>>>>> Regards,
>>>>>>> Daniel
>>>>>>>
>>>>>>
>>>>>> Got it, this explains it, sorry for the noise on this.
>>>>>>
>>>>>> I'll continue to investigate the general issue of low throughput with virsh save / qemu savevm .
>>>>>
>>>>> BTW, consider measuring with the --bypass-cache flag to virsh save.
>>>>> This causes libvirt to use a I/O helper that uses O_DIRECT when
>>>>> saving the image. This should give more predictable results by
>>>>> avoiding the influence of host I/O cache which can be in a differnt
>>>>> state of usage each time you measure.  It was also intended that
>>>>> by avoiding hitting cache, saving the memory image of a large VM
>>>>> will not push other useful stuff out of host I/O  cache which can
>>>>> negatively impact other running VMs.
>>>>>
>>>>> Also it is possible to configure compression on the libvirt side
>>>>> which may be useful if you have spare CPU cycles, but your storage
>>>>> is slow. See 'save_image_format' in the /etc/libvirt/qemu.conf
>>>>>
>>>>> With regards,
>>>>> Daniel
>>>>>
>>>>
>>>> Hi Daniel, thanks for these good info,
>>>>
>>>> regarding slow storage, for these tests I am saving to /dev/null to avoid having to take storage into account
>>>> (and still getting low bandwidth unfortunately) so I guess compression is out of the question.
>>>
>>> What type of speeds do you get if you try a migrate to a netcat socket?
>>
>> much faster apparently, 30 sec savevm vs 7 seconds for migration to a netcat socket sent to /dev/null.
>>
>> nc -l -U /tmp/savevm.socket
>>
>> virsh suspend centos7
>> Domain centos7 suspended
>>
>> virsh qemu-monitor-command --cmd '{ "execute": "migrate", "arguments": { "uri": "unix:///tmp/savevm.socket" } }' centos7
>>
>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
>> {"return":{"blocked":false,"status":"completed","setup-time":118,"downtime":257,"total-time":7524,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":1057530,"page-size":4096,"remaining":0,"mbps":24215.572437483122,"transferred":22417172290,"duplicate":2407520,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22351847424,"normal":5456994}},"id":"libvirt-438"}
>>
>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
>> {"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":8,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-439"}
>>
>>
>> I did also a run with multifd-channels:1 instead of 8, if it matters:
> 
> I suspect you haven't actually got multifd enabled ( check
> query-migrate-capabilities ?).
>>
>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
>> {"return":{"blocked":false,"status":"completed","setup-time":119,"downtime":260,"total-time":8601,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":908820,"page-size":4096,"remaining":0,"mbps":21141.861157274227,"transferred":22415264188,"duplicate":2407986,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22349938688,"normal":5456528}},"id":"libvirt-453"}
>>
>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
>> {"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":1,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-454"}
>>
>>
>> Still we are in the 20 Gbps range, or around 2560 MiB/s, way faster than savevm which does around 600 MiB/s when the wind is in its favor..
> qemu-1646827174
> Yeh that's what I'd hope for off a decent CPU; hmm there's not that much
> savevm specific is there?


Hmm not sure. I have a hunch, is the difference just more threads being used to transfer the data?

Is the migration path creating threads, while savevm doesn't? Hmm...

Thanks,

Claudio

Re: bad qemu savevm to /dev/null performance (600 MiB/s max) (Was: Re: starting to look at qemu savevm performance, a first regression detected)

[Claudio Fontana]

On 3/9/22 12:51 PM, Daniel P. Berrangé wrote:
> On Wed, Mar 09, 2022 at 11:43:48AM +0000, Dr. David Alan Gilbert wrote:
>> * Claudio Fontana (cfontana@suse.de) wrote:
>>> On 3/7/22 1:28 PM, Dr. David Alan Gilbert wrote:
>>>> * Claudio Fontana (cfontana@suse.de) wrote:
>>>>> On 3/7/22 1:20 PM, Daniel P. Berrangé wrote:
>>>>>> On Mon, Mar 07, 2022 at 01:09:55PM +0100, Claudio Fontana wrote:
>>>>>>> Got it, this explains it, sorry for the noise on this.
>>>>>>>
>>>>>>> I'll continue to investigate the general issue of low throughput with virsh save / qemu savevm .
>>>>>>
>>>>>> BTW, consider measuring with the --bypass-cache flag to virsh save.
>>>>>> This causes libvirt to use a I/O helper that uses O_DIRECT when
>>>>>> saving the image. This should give more predictable results by
>>>>>> avoiding the influence of host I/O cache which can be in a differnt
>>>>>> state of usage each time you measure.  It was also intended that
>>>>>> by avoiding hitting cache, saving the memory image of a large VM
>>>>>> will not push other useful stuff out of host I/O  cache which can
>>>>>> negatively impact other running VMs.
>>>>>>
>>>>>> Also it is possible to configure compression on the libvirt side
>>>>>> which may be useful if you have spare CPU cycles, but your storage
>>>>>> is slow. See 'save_image_format' in the /etc/libvirt/qemu.conf
>>>>>>
>>>>>> With regards,
>>>>>> Daniel
>>>>>>
>>>>>
>>>>> Hi Daniel, thanks for these good info,
>>>>>
>>>>> regarding slow storage, for these tests I am saving to /dev/null to avoid having to take storage into account
>>>>> (and still getting low bandwidth unfortunately) so I guess compression is out of the question.
>>>>
>>>> What type of speeds do you get if you try a migrate to a netcat socket?
>>>
>>> much faster apparently, 30 sec savevm vs 7 seconds for migration to a netcat socket sent to /dev/null.
>>>
>>> nc -l -U /tmp/savevm.socket
>>>
>>> virsh suspend centos7
>>> Domain centos7 suspended
>>>
>>> virsh qemu-monitor-command --cmd '{ "execute": "migrate", "arguments": { "uri": "unix:///tmp/savevm.socket" } }' centos7
>>>
>>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
>>> {"return":{"blocked":false,"status":"completed","setup-time":118,"downtime":257,"total-time":7524,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":1057530,"page-size":4096,"remaining":0,"mbps":24215.572437483122,"transferred":22417172290,"duplicate":2407520,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22351847424,"normal":5456994}},"id":"libvirt-438"}
>>>
>>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
>>> {"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":8,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-439"}
>>>
>>>
>>> I did also a run with multifd-channels:1 instead of 8, if it matters:
>>
>> I suspect you haven't actually got multifd enabled ( check
>> query-migrate-capabilities ?).
>>>
>>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
>>> {"return":{"blocked":false,"status":"completed","setup-time":119,"downtime":260,"total-time":8601,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":908820,"page-size":4096,"remaining":0,"mbps":21141.861157274227,"transferred":22415264188,"duplicate":2407986,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22349938688,"normal":5456528}},"id":"libvirt-453"}
>>>
>>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
>>> {"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":1,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-454"}
>>>
>>>
>>> Still we are in the 20 Gbps range, or around 2560 MiB/s, way faster than savevm which does around 600 MiB/s when the wind is in its favor..
>>
>> Yeh that's what I'd hope for off a decent CPU; hmm there's not that much
>> savevm specific is there?
> 
> BTW, quick clarification here.
> 
> IIUC, Claudio says the test is 'virsh save $VMNAME /some/file'. This
> is *not* running 'savevm' at the QEMU level. So it is a bit misleading
> refering to it as savevm in the thread here.


Thanks, this is a helpful clarification, I was wrongly assuming those were linked.
Indeed the use case is virsh save.

> 
> 'virsh save' is simply wired up to the normal QEMU 'migrate' commands,
> with libvirt giving QEMU a pre-opened FD, which libvirt processes the
> other end of to write out to disk.
> 
> IOW, the performance delta is possibly on libvirt's side rather
> than QEMU's.

Interesting, also Ccing Jim on this, I'll continue to do more experiments.

> 
> Regards,
> Daniel
> 

Re: bad virsh save /dev/null performance (600 MiB/s max)

[Claudio Fontana]

On 3/9/22 3:22 PM, Claudio Fontana wrote:
> On 3/9/22 12:51 PM, Daniel P. Berrangé wrote:
>> On Wed, Mar 09, 2022 at 11:43:48AM +0000, Dr. David Alan Gilbert wrote:
>>> * Claudio Fontana (cfontana@suse.de) wrote:
>>>> On 3/7/22 1:28 PM, Dr. David Alan Gilbert wrote:
>>>>> * Claudio Fontana (cfontana@suse.de) wrote:
>>>>>> On 3/7/22 1:20 PM, Daniel P. Berrangé wrote:
>>>>>>> On Mon, Mar 07, 2022 at 01:09:55PM +0100, Claudio Fontana wrote:
>>>>>>>> Got it, this explains it, sorry for the noise on this.
>>>>>>>>
>>>>>>>> I'll continue to investigate the general issue of low throughput with virsh save / qemu savevm .
>>>>>>>
>>>>>>> BTW, consider measuring with the --bypass-cache flag to virsh save.
>>>>>>> This causes libvirt to use a I/O helper that uses O_DIRECT when
>>>>>>> saving the image. This should give more predictable results by
>>>>>>> avoiding the influence of host I/O cache which can be in a differnt
>>>>>>> state of usage each time you measure.  It was also intended that
>>>>>>> by avoiding hitting cache, saving the memory image of a large VM
>>>>>>> will not push other useful stuff out of host I/O  cache which can
>>>>>>> negatively impact other running VMs.
>>>>>>>
>>>>>>> Also it is possible to configure compression on the libvirt side
>>>>>>> which may be useful if you have spare CPU cycles, but your storage
>>>>>>> is slow. See 'save_image_format' in the /etc/libvirt/qemu.conf
>>>>>>>
>>>>>>> With regards,
>>>>>>> Daniel
>>>>>>>
>>>>>>
>>>>>> Hi Daniel, thanks for these good info,
>>>>>>
>>>>>> regarding slow storage, for these tests I am saving to /dev/null to avoid having to take storage into account
>>>>>> (and still getting low bandwidth unfortunately) so I guess compression is out of the question.
>>>>>
>>>>> What type of speeds do you get if you try a migrate to a netcat socket?
>>>>
>>>> much faster apparently, 30 sec savevm vs 7 seconds for migration to a netcat socket sent to /dev/null.
>>>>
>>>> nc -l -U /tmp/savevm.socket
>>>>
>>>> virsh suspend centos7
>>>> Domain centos7 suspended
>>>>
>>>> virsh qemu-monitor-command --cmd '{ "execute": "migrate", "arguments": { "uri": "unix:///tmp/savevm.socket" } }' centos7
>>>>
>>>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
>>>> {"return":{"blocked":false,"status":"completed","setup-time":118,"downtime":257,"total-time":7524,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":1057530,"page-size":4096,"remaining":0,"mbps":24215.572437483122,"transferred":22417172290,"duplicate":2407520,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22351847424,"normal":5456994}},"id":"libvirt-438"}
>>>>
>>>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
>>>> {"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":8,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-439"}
>>>>
>>>>
>>>> I did also a run with multifd-channels:1 instead of 8, if it matters:
>>>
>>> I suspect you haven't actually got multifd enabled ( check
>>> query-migrate-capabilities ?).
>>>>
>>>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate" }' centos7
>>>> {"return":{"blocked":false,"status":"completed","setup-time":119,"downtime":260,"total-time":8601,"ram":{"total":32213049344,"postcopy-requests":0,"dirty-sync-count":3,"multifd-bytes":0,"pages-per-second":908820,"page-size":4096,"remaining":0,"mbps":21141.861157274227,"transferred":22415264188,"duplicate":2407986,"dirty-pages-rate":0,"skipped":0,"normal-bytes":22349938688,"normal":5456528}},"id":"libvirt-453"}
>>>>
>>>> virt97:/mnt # virsh qemu-monitor-command --cmd '{ "execute": "query-migrate-parameters" }' centos7
>>>> {"return":{"cpu-throttle-tailslow":false,"xbzrle-cache-size":67108864,"cpu-throttle-initial":20,"announce-max":550,"decompress-threads":2,"compress-threads":8,"compress-level":0,"multifd-channels":1,"multifd-zstd-level":1,"announce-initial":50,"block-incremental":false,"compress-wait-thread":true,"downtime-limit":300,"tls-authz":"","multifd-compression":"none","announce-rounds":5,"announce-step":100,"tls-creds":"","multifd-zlib-level":1,"max-cpu-throttle":99,"max-postcopy-bandwidth":0,"tls-hostname":"","throttle-trigger-threshold":50,"max-bandwidth":9223372036853727232,"x-checkpoint-delay":20000,"cpu-throttle-increment":10},"id":"libvirt-454"}
>>>>
>>>>
>>>> Still we are in the 20 Gbps range, or around 2560 MiB/s, way faster than savevm which does around 600 MiB/s when the wind is in its favor..
>>>
>>> Yeh that's what I'd hope for off a decent CPU; hmm there's not that much
>>> savevm specific is there?
>>
>> BTW, quick clarification here.
>>
>> IIUC, Claudio says the test is 'virsh save $VMNAME /some/file'. This
>> is *not* running 'savevm' at the QEMU level. So it is a bit misleading
>> refering to it as savevm in the thread here.
> 
> 
> Thanks, this is a helpful clarification, I was wrongly assuming those were linked.
> Indeed the use case is virsh save.
> 
>>
>> 'virsh save' is simply wired up to the normal QEMU 'migrate' commands,
>> with libvirt giving QEMU a pre-opened FD, which libvirt processes the
>> other end of to write out to disk.
>>
>> IOW, the performance delta is possibly on libvirt's side rather
>> than QEMU's.
> 
> Interesting, also Ccing Jim on this, I'll continue to do more experiments.
> 


One difference I could see looking at the qmp commands issued by libvirt in the "virsh save" case,
is "detach:true" in the migration command (which seems to have no effect in qemu),


and maybe more interestingly this stuff about the "fd":


2022-03-09 17:29:34.247+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
 fd=34
2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
 len=73 ret=73 errno=0
2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:457 : QEMU_MONITOR_IO_SEND_FD: mon=0x7faa9003ebf0 fd=34 ret=73 errno=0
2022-03-09 17:29:34.248+0000: 20387: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7faa9003ebf0 reply={"return": {}, "id": "libvirt-390"}
2022-03-09 17:29:34.249+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
 fd=-1
2022-03-09 17:29:34.249+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
 len=113 ret=113 errno=0


in qemu I am currently looking at the code in migration/socket.c vs the code in migration/fd.c , wonder if the difference would stem from there..

Thanks,

CLaudio

Re: bad virsh save /dev/null performance (600 MiB/s max)

[Daniel P. Berrangé]

On Wed, Mar 09, 2022 at 07:27:12PM +0100, Claudio Fontana wrote:
> 
> One difference I could see looking at the qmp commands issued by libvirt in the "virsh save" case,
> is "detach:true" in the migration command (which seems to have no effect in qemu),

That is a bug in libvirt - it should not be setting that in QMP.

To quote the QAPI spec for 'migrate'

  # @detach: this argument exists only for compatibility reasons and
  #          is ignored by QEMU


> 
> 
> and maybe more interestingly this stuff about the "fd":
> 
> 
> 2022-03-09 17:29:34.247+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
>  fd=34
> 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
>  len=73 ret=73 errno=0
> 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:457 : QEMU_MONITOR_IO_SEND_FD: mon=0x7faa9003ebf0 fd=34 ret=73 errno=0
> 2022-03-09 17:29:34.248+0000: 20387: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7faa9003ebf0 reply={"return": {}, "id": "libvirt-390"}
> 2022-03-09 17:29:34.249+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
>  fd=-1
> 2022-03-09 17:29:34.249+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
>  len=113 ret=113 errno=0
> 
> 
> in qemu I am currently looking at the code in migration/socket.c
> vs the code in migration/fd.c , wonder if the difference would
> stem from there..

When saving to a file, libvirt passes in a pre-opened FD for
QEU to use. IIRC this should always be a pipe FD connected to
libvirt's iohelper program, sometimes indirectly via a compression
program.

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 :|

Re: bad virsh save /dev/null performance (600 MiB/s max)

[Dr. David Alan Gilbert]

* Daniel P. Berrangé (berrange@redhat.com) wrote:
> On Wed, Mar 09, 2022 at 07:27:12PM +0100, Claudio Fontana wrote:
> > 
> > One difference I could see looking at the qmp commands issued by libvirt in the "virsh save" case,
> > is "detach:true" in the migration command (which seems to have no effect in qemu),
> 
> That is a bug in libvirt - it should not be setting that in QMP.
> 
> To quote the QAPI spec for 'migrate'
> 
>   # @detach: this argument exists only for compatibility reasons and
>   #          is ignored by QEMU
> 
> 
> > 
> > 
> > and maybe more interestingly this stuff about the "fd":
> > 
> > 
> > 2022-03-09 17:29:34.247+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
> >  fd=34
> > 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
> >  len=73 ret=73 errno=0
> > 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:457 : QEMU_MONITOR_IO_SEND_FD: mon=0x7faa9003ebf0 fd=34 ret=73 errno=0
> > 2022-03-09 17:29:34.248+0000: 20387: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7faa9003ebf0 reply={"return": {}, "id": "libvirt-390"}
> > 2022-03-09 17:29:34.249+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
> >  fd=-1
> > 2022-03-09 17:29:34.249+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
> >  len=113 ret=113 errno=0
> > 
> > 
> > in qemu I am currently looking at the code in migration/socket.c
> > vs the code in migration/fd.c , wonder if the difference would
> > stem from there..
> 
> When saving to a file, libvirt passes in a pre-opened FD for
> QEU to use. IIRC this should always be a pipe FD connected to
> libvirt's iohelper program, sometimes indirectly via a compression
> program.

In which case, what is a simple 'top' showing on the system?

Dave

> 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 :|
> 
-- 
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: bad virsh save /dev/null performance (600 MiB/s max)

[Daniel P. Berrangé]

On Wed, Mar 09, 2022 at 06:37:42PM +0000, Daniel P. Berrangé wrote:
> On Wed, Mar 09, 2022 at 07:27:12PM +0100, Claudio Fontana wrote:
> > 
> > One difference I could see looking at the qmp commands issued by libvirt in the "virsh save" case,
> > is "detach:true" in the migration command (which seems to have no effect in qemu),
> 
> That is a bug in libvirt - it should not be setting that in QMP.
> 
> To quote the QAPI spec for 'migrate'
> 
>   # @detach: this argument exists only for compatibility reasons and
>   #          is ignored by QEMU
> 
> 
> > 
> > 
> > and maybe more interestingly this stuff about the "fd":
> > 
> > 
> > 2022-03-09 17:29:34.247+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
> >  fd=34
> > 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
> >  len=73 ret=73 errno=0
> > 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:457 : QEMU_MONITOR_IO_SEND_FD: mon=0x7faa9003ebf0 fd=34 ret=73 errno=0
> > 2022-03-09 17:29:34.248+0000: 20387: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7faa9003ebf0 reply={"return": {}, "id": "libvirt-390"}
> > 2022-03-09 17:29:34.249+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
> >  fd=-1
> > 2022-03-09 17:29:34.249+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
> >  len=113 ret=113 errno=0
> > 
> > 
> > in qemu I am currently looking at the code in migration/socket.c
> > vs the code in migration/fd.c , wonder if the difference would
> > stem from there..
> 
> When saving to a file, libvirt passes in a pre-opened FD for
> QEU to use. IIRC this should always be a pipe FD connected to
> libvirt's iohelper program, sometimes indirectly via a compression
> program.

It occurs to me that pipes and sockets likely use very different
buffer sizes, with sockets larger IIUC, and buffer sizes can impact
throughput. Could be worth exploring a change to libvirt code to
use socketpair() instead of pipe() to see if it impacts performance
in any meaningful way, or playing with fcntl(F_SETPIPE_SZ)

With 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 :|

Re: bad virsh save /dev/null performance (600 MiB/s max)

[Claudio Fontana]

On 3/9/22 7:39 PM, Dr. David Alan Gilbert wrote:
> * Daniel P. Berrangé (berrange@redhat.com) wrote:
>> On Wed, Mar 09, 2022 at 07:27:12PM +0100, Claudio Fontana wrote:
>>>
>>> One difference I could see looking at the qmp commands issued by libvirt in the "virsh save" case,
>>> is "detach:true" in the migration command (which seems to have no effect in qemu),
>>
>> That is a bug in libvirt - it should not be setting that in QMP.
>>
>> To quote the QAPI spec for 'migrate'
>>
>>   # @detach: this argument exists only for compatibility reasons and
>>   #          is ignored by QEMU
>>
>>
>>>
>>>
>>> and maybe more interestingly this stuff about the "fd":
>>>
>>>
>>> 2022-03-09 17:29:34.247+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
>>>  fd=34
>>> 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
>>>  len=73 ret=73 errno=0
>>> 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:457 : QEMU_MONITOR_IO_SEND_FD: mon=0x7faa9003ebf0 fd=34 ret=73 errno=0
>>> 2022-03-09 17:29:34.248+0000: 20387: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7faa9003ebf0 reply={"return": {}, "id": "libvirt-390"}
>>> 2022-03-09 17:29:34.249+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
>>>  fd=-1
>>> 2022-03-09 17:29:34.249+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
>>>  len=113 ret=113 errno=0
>>>
>>>
>>> in qemu I am currently looking at the code in migration/socket.c
>>> vs the code in migration/fd.c , wonder if the difference would
>>> stem from there..
>>
>> When saving to a file, libvirt passes in a pre-opened FD for
>> QEU to use. IIRC this should always be a pipe FD connected to
>> libvirt's iohelper program, sometimes indirectly via a compression
>> program.
> 
> In which case, what is a simple 'top' showing on the system?

libvirt_iohelper is the top cpu consumer at 60-something%,
qemu-system-x86_64 is at 30-40%.

C.

Re: bad virsh save /dev/null performance (600 MiB/s max)

[Dr. David Alan Gilbert]

* Claudio Fontana (cfontana@suse.de) wrote:
> On 3/9/22 7:39 PM, Dr. David Alan Gilbert wrote:
> > * Daniel P. Berrangé (berrange@redhat.com) wrote:
> >> On Wed, Mar 09, 2022 at 07:27:12PM +0100, Claudio Fontana wrote:
> >>>
> >>> One difference I could see looking at the qmp commands issued by libvirt in the "virsh save" case,
> >>> is "detach:true" in the migration command (which seems to have no effect in qemu),
> >>
> >> That is a bug in libvirt - it should not be setting that in QMP.
> >>
> >> To quote the QAPI spec for 'migrate'
> >>
> >>   # @detach: this argument exists only for compatibility reasons and
> >>   #          is ignored by QEMU
> >>
> >>
> >>>
> >>>
> >>> and maybe more interestingly this stuff about the "fd":
> >>>
> >>>
> >>> 2022-03-09 17:29:34.247+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
> >>>  fd=34
> >>> 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
> >>>  len=73 ret=73 errno=0
> >>> 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:457 : QEMU_MONITOR_IO_SEND_FD: mon=0x7faa9003ebf0 fd=34 ret=73 errno=0
> >>> 2022-03-09 17:29:34.248+0000: 20387: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7faa9003ebf0 reply={"return": {}, "id": "libvirt-390"}
> >>> 2022-03-09 17:29:34.249+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
> >>>  fd=-1
> >>> 2022-03-09 17:29:34.249+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
> >>>  len=113 ret=113 errno=0
> >>>
> >>>
> >>> in qemu I am currently looking at the code in migration/socket.c
> >>> vs the code in migration/fd.c , wonder if the difference would
> >>> stem from there..
> >>
> >> When saving to a file, libvirt passes in a pre-opened FD for
> >> QEU to use. IIRC this should always be a pipe FD connected to
> >> libvirt's iohelper program, sometimes indirectly via a compression
> >> program.
> > 
> > In which case, what is a simple 'top' showing on the system?
> 
> libvirt_iohelper is the top cpu consumer at 60-something%,
> qemu-system-x86_64 is at 30-40%.

Right, with plain migration qemu just writes directly to the fd
instead of bubbling through the iohelper.
You could probably optimise that, but there's probably one or two
extra copies in the way.

Dave

> C.
> 
-- 
Dr. David Alan Gilbert / dgilbert@redhat.com / Manchester, UK

Re: bad virsh save /dev/null performance (600 MiB/s max)

[Claudio Fontana]

On 3/9/22 7:46 PM, Daniel P. Berrangé wrote:
> On Wed, Mar 09, 2022 at 06:37:42PM +0000, Daniel P. Berrangé wrote:
>> On Wed, Mar 09, 2022 at 07:27:12PM +0100, Claudio Fontana wrote:
>>>
>>> One difference I could see looking at the qmp commands issued by libvirt in the "virsh save" case,
>>> is "detach:true" in the migration command (which seems to have no effect in qemu),
>>
>> That is a bug in libvirt - it should not be setting that in QMP.
>>
>> To quote the QAPI spec for 'migrate'
>>
>>   # @detach: this argument exists only for compatibility reasons and
>>   #          is ignored by QEMU
>>
>>
>>>
>>>
>>> and maybe more interestingly this stuff about the "fd":
>>>
>>>
>>> 2022-03-09 17:29:34.247+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
>>>  fd=34
>>> 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"getfd","arguments":{"fdname":"migrate"},"id":"libvirt-390"}^M
>>>  len=73 ret=73 errno=0
>>> 2022-03-09 17:29:34.247+0000: 20387: info : qemuMonitorIOWrite:457 : QEMU_MONITOR_IO_SEND_FD: mon=0x7faa9003ebf0 fd=34 ret=73 errno=0
>>> 2022-03-09 17:29:34.248+0000: 20387: info : qemuMonitorJSONIOProcessLine:240 : QEMU_MONITOR_RECV_REPLY: mon=0x7faa9003ebf0 reply={"return": {}, "id": "libvirt-390"}
>>> 2022-03-09 17:29:34.249+0000: 20390: info : qemuMonitorSend:995 : QEMU_MONITOR_SEND_MSG: mon=0x7faa9003ebf0 msg={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
>>>  fd=-1
>>> 2022-03-09 17:29:34.249+0000: 20387: info : qemuMonitorIOWrite:452 : QEMU_MONITOR_IO_WRITE: mon=0x7faa9003ebf0 buf={"execute":"migrate","arguments":{"detach":true,"blk":false,"inc":false,"uri":"fd:migrate"},"id":"libvirt-391"}^M
>>>  len=113 ret=113 errno=0
>>>
>>>
>>> in qemu I am currently looking at the code in migration/socket.c
>>> vs the code in migration/fd.c , wonder if the difference would
>>> stem from there..
>>
>> When saving to a file, libvirt passes in a pre-opened FD for
>> QEU to use. IIRC this should always be a pipe FD connected to
>> libvirt's iohelper program, sometimes indirectly via a compression
>> program.
> 
> It occurs to me that pipes and sockets likely use very different
> buffer sizes, with sockets larger IIUC, and buffer sizes can impact
> throughput. Could be worth exploring a change to libvirt code to
> use socketpair() instead of pipe() to see if it impacts performance
> in any meaningful way, or playing with fcntl(F_SETPIPE_SZ)
> 
> With regards,
> Daniel
> 

Hello Daniel,

the experiment with F_SETPIPE_SZ was successful, transfer speeds are dramatically increased. Still digging but this is a huge benefit.

Thanks,

Claudio