diff mbox series

[v4,09/23] job: call job_enter from job_pause

Message ID 20210116214705.822267-10-vsementsov@virtuozzo.com
State New
Headers show
Series backup performance: block_status + async | expand

Commit Message

Vladimir Sementsov-Ogievskiy Jan. 16, 2021, 9:46 p.m. UTC
If main job coroutine called job_yield (while some background process
is in progress), we should give it a chance to call job_pause_point().
It will be used in backup, when moved on async block-copy.

Note, that job_user_pause is not enough: we want to handle
child_job_drained_begin() as well, which call job_pause().

Still, if job is already in job_do_yield() in job_pause_point() we
should not enter it.

iotest 109 output is modified: on stop we do bdrv_drain_all() which now
triggers job pause immediately (and pause after ready is standby).

Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
---
 job.c                      |  3 +++
 tests/qemu-iotests/109.out | 24 ++++++++++++++++++++++++
 2 files changed, 27 insertions(+)

Comments

Max Reitz Jan. 18, 2021, 1:45 p.m. UTC | #1
On 16.01.21 22:46, Vladimir Sementsov-Ogievskiy wrote:
> If main job coroutine called job_yield (while some background process
> is in progress), we should give it a chance to call job_pause_point().
> It will be used in backup, when moved on async block-copy.
> 
> Note, that job_user_pause is not enough: we want to handle
> child_job_drained_begin() as well, which call job_pause().

OK.

> Still, if job is already in job_do_yield() in job_pause_point() we
> should not enter it.

Agreed.

> iotest 109 output is modified: on stop we do bdrv_drain_all() which now
> triggers job pause immediately (and pause after ready is standby).

Sounds like a good thing.

> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>   job.c                      |  3 +++
>   tests/qemu-iotests/109.out | 24 ++++++++++++++++++++++++
>   2 files changed, 27 insertions(+)
> 
> diff --git a/job.c b/job.c
> index 8fecf38960..3aaaebafe2 100644
> --- a/job.c
> +++ b/job.c
> @@ -553,6 +553,9 @@ static bool job_timer_not_pending(Job *job)
>   void job_pause(Job *job)
>   {
>       job->pause_count++;
> +    if (!job->paused) {
> +        job_enter(job);
> +    }
>   }

I see job_pause is also called from block_job_error_action() – should we 
reenter the job there, too?

(It looks to me like e.g. mirror would basically just continue to run, 
then, until it needs to yield because of some other issue.  I don’t know 
whether that’s a problem, because I suppose we don’t guarantee to stop 
immediately on an error, though I suspect users would expect us to do 
that as early as possible (i.e., not to launch new requests).

[Quite some time later]

I’ve now tested a mirror job that stops due to a target error, and it 
actually does not make any progress; or at least it doesn’t report any. 
  So it looks like my concern is unjustified.  I don’t know why it’s 
unjustified, though, so perhaps you can explain it before I give my R-b O:))

Max
Max Reitz Jan. 18, 2021, 2:20 p.m. UTC | #2
On 18.01.21 14:45, Max Reitz wrote:
> On 16.01.21 22:46, Vladimir Sementsov-Ogievskiy wrote:
>> If main job coroutine called job_yield (while some background process
>> is in progress), we should give it a chance to call job_pause_point().
>> It will be used in backup, when moved on async block-copy.
>>
>> Note, that job_user_pause is not enough: we want to handle
>> child_job_drained_begin() as well, which call job_pause().
> 
> OK.
> 
>> Still, if job is already in job_do_yield() in job_pause_point() we
>> should not enter it.
> 
> Agreed.
> 
>> iotest 109 output is modified: on stop we do bdrv_drain_all() which now
>> triggers job pause immediately (and pause after ready is standby).
> 
> Sounds like a good thing.
> 
>> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
>> ---
>>   job.c                      |  3 +++
>>   tests/qemu-iotests/109.out | 24 ++++++++++++++++++++++++
>>   2 files changed, 27 insertions(+)
>>
>> diff --git a/job.c b/job.c
>> index 8fecf38960..3aaaebafe2 100644
>> --- a/job.c
>> +++ b/job.c
>> @@ -553,6 +553,9 @@ static bool job_timer_not_pending(Job *job)
>>   void job_pause(Job *job)
>>   {
>>       job->pause_count++;
>> +    if (!job->paused) {
>> +        job_enter(job);
>> +    }
>>   }
> 
> I see job_pause is also called from block_job_error_action() – should we 
> reenter the job there, too?
> 
> (It looks to me like e.g. mirror would basically just continue to run, 
> then, until it needs to yield because of some other issue.  I don’t know 
> whether that’s a problem, because I suppose we don’t guarantee to stop 
> immediately on an error, though I suspect users would expect us to do 
> that as early as possible (i.e., not to launch new requests).
> 
> [Quite some time later]
> 
> I’ve now tested a mirror job that stops due to a target error, and it 
> actually does not make any progress; or at least it doesn’t report any. 
>   So it looks like my concern is unjustified.  I don’t know why it’s 
> unjustified, though, so perhaps you can explain it before I give my R-b 
> O:))

Oh, I guess because job_enter_cond() doesn’t enter if the job is busy 
already.  That would make a lot of sense, so I’m going to assume that’s 
what’s preventing the job_enter() to do anything if the job is already 
running (which it has to be to invoke block_job_error_action()).

Reviewed-by: Max Reitz <mreitz@redhat.com>
Max Reitz April 7, 2021, 11:19 a.m. UTC | #3
On 16.01.21 22:46, Vladimir Sementsov-Ogievskiy wrote:
> If main job coroutine called job_yield (while some background process
> is in progress), we should give it a chance to call job_pause_point().
> It will be used in backup, when moved on async block-copy.
> 
> Note, that job_user_pause is not enough: we want to handle
> child_job_drained_begin() as well, which call job_pause().
> 
> Still, if job is already in job_do_yield() in job_pause_point() we
> should not enter it.
> 
> iotest 109 output is modified: on stop we do bdrv_drain_all() which now
> triggers job pause immediately (and pause after ready is standby).
> 
> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
> ---
>   job.c                      |  3 +++
>   tests/qemu-iotests/109.out | 24 ++++++++++++++++++++++++
>   2 files changed, 27 insertions(+)

While looking into

https://lists.gnu.org/archive/html/qemu-block/2021-04/msg00035.html

I noticed this:

$ ./qemu-img create -f raw src.img 1G
$ ./qemu-img create -f raw dst.img 1G

$ (echo '
     {"execute":"qmp_capabilities"}
     {"execute":"blockdev-mirror",
      "arguments":{"job-id":"mirror",
                   "device":"source",
                   "target":"target",
                   "sync":"full",
                   "filter-node-name":"mirror-top"}}
'; sleep 3; echo '
     {"execute":"human-monitor-command",
      "arguments":{"command-line":
                   "qemu-io mirror-top \"write 0 1G\""}}') \
| x86_64-softmmu/qemu-system-x86_64 \
     -qmp stdio \
     -blockdev file,node-name=source,filename=src.img \
     -blockdev file,node-name=target,filename=dst.img \
     -object iothread,id=iothr0 \
     -device virtio-blk,drive=source,iothread=iothr0

Before this commit, qemu-io returned an error that there is a permission 
conflict with virtio-blk.  After this commit, there is an abort (“qemu: 
qemu_mutex_unlock_impl: Operation not permitted”):

#0  0x00007f8445a4eef5 in raise () at /usr/lib/libc.so.6
#1  0x00007f8445a38862 in abort () at /usr/lib/libc.so.6
#2  0x000055fbb14a36bf in error_exit
     (err=<optimized out>, msg=msg@entry=0x55fbb1634790 <__func__.27> 
"qemu_mutex_unlock_impl")
     at ../util/qemu-thread-posix.c:37
#3  0x000055fbb14a3bc3 in qemu_mutex_unlock_impl
     (mutex=mutex@entry=0x55fbb25ab6e0, file=file@entry=0x55fbb1636957 
"../util/async.c", line=line@entry=650)
     at ../util/qemu-thread-posix.c:109
#4  0x000055fbb14b2e75 in aio_context_release 
(ctx=ctx@entry=0x55fbb25ab680) at ../util/async.c:650
#5  0x000055fbb13d2029 in bdrv_do_drained_begin
     (bs=bs@entry=0x55fbb3a87000, recursive=recursive@entry=false, 
parent=parent@entry=0x0, 
ignore_bds_parents=ignore_bds_parents@entry=false, poll=poll@entry=true) 
at ../block/io.c:441
#6  0x000055fbb13d2192 in bdrv_do_drained_begin
     (poll=true, ignore_bds_parents=false, parent=0x0, recursive=false, 
bs=0x55fbb3a87000) at ../block/io.c:448
#7  0x000055fbb13c71a7 in blk_drain (blk=0x55fbb26c5a00) at 
../block/block-backend.c:1718
#8  0x000055fbb13c8bbd in blk_unref (blk=0x55fbb26c5a00) at 
../block/block-backend.c:498
#9  blk_unref (blk=0x55fbb26c5a00) at ../block/block-backend.c:491
#10 0x000055fbb1024863 in hmp_qemu_io (mon=0x7fffaf3fc7d0, 
qdict=<optimized out>)
     at ../block/monitor/block-hmp-cmds.c:628

Can you make anything out of this?

Max
Vladimir Sementsov-Ogievskiy April 7, 2021, 11:38 a.m. UTC | #4
07.04.2021 14:19, Max Reitz wrote:
> On 16.01.21 22:46, Vladimir Sementsov-Ogievskiy wrote:
>> If main job coroutine called job_yield (while some background process
>> is in progress), we should give it a chance to call job_pause_point().
>> It will be used in backup, when moved on async block-copy.
>>
>> Note, that job_user_pause is not enough: we want to handle
>> child_job_drained_begin() as well, which call job_pause().
>>
>> Still, if job is already in job_do_yield() in job_pause_point() we
>> should not enter it.
>>
>> iotest 109 output is modified: on stop we do bdrv_drain_all() which now
>> triggers job pause immediately (and pause after ready is standby).
>>
>> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
>> ---
>>   job.c                      |  3 +++
>>   tests/qemu-iotests/109.out | 24 ++++++++++++++++++++++++
>>   2 files changed, 27 insertions(+)
> 
> While looking into
> 
> https://lists.gnu.org/archive/html/qemu-block/2021-04/msg00035.html
> 
> I noticed this:
> 
> $ ./qemu-img create -f raw src.img 1G
> $ ./qemu-img create -f raw dst.img 1G
> 
> $ (echo '
>     {"execute":"qmp_capabilities"}
>     {"execute":"blockdev-mirror",
>      "arguments":{"job-id":"mirror",
>                   "device":"source",
>                   "target":"target",
>                   "sync":"full",
>                   "filter-node-name":"mirror-top"}}
> '; sleep 3; echo '
>     {"execute":"human-monitor-command",
>      "arguments":{"command-line":
>                   "qemu-io mirror-top \"write 0 1G\""}}') \
> | x86_64-softmmu/qemu-system-x86_64 \
>     -qmp stdio \
>     -blockdev file,node-name=source,filename=src.img \
>     -blockdev file,node-name=target,filename=dst.img \
>     -object iothread,id=iothr0 \
>     -device virtio-blk,drive=source,iothread=iothr0
> 
> Before this commit, qemu-io returned an error that there is a permission conflict with virtio-blk.  After this commit, there is an abort (“qemu: qemu_mutex_unlock_impl: Operation not permitted”):
> 
> #0  0x00007f8445a4eef5 in raise () at /usr/lib/libc.so.6
> #1  0x00007f8445a38862 in abort () at /usr/lib/libc.so.6
> #2  0x000055fbb14a36bf in error_exit
>     (err=<optimized out>, msg=msg@entry=0x55fbb1634790 <__func__.27> "qemu_mutex_unlock_impl")
>     at ../util/qemu-thread-posix.c:37
> #3  0x000055fbb14a3bc3 in qemu_mutex_unlock_impl
>     (mutex=mutex@entry=0x55fbb25ab6e0, file=file@entry=0x55fbb1636957 "../util/async.c", line=line@entry=650)
>     at ../util/qemu-thread-posix.c:109
> #4  0x000055fbb14b2e75 in aio_context_release (ctx=ctx@entry=0x55fbb25ab680) at ../util/async.c:650
> #5  0x000055fbb13d2029 in bdrv_do_drained_begin
>     (bs=bs@entry=0x55fbb3a87000, recursive=recursive@entry=false, parent=parent@entry=0x0, ignore_bds_parents=ignore_bds_parents@entry=false, poll=poll@entry=true) at ../block/io.c:441
> #6  0x000055fbb13d2192 in bdrv_do_drained_begin
>     (poll=true, ignore_bds_parents=false, parent=0x0, recursive=false, bs=0x55fbb3a87000) at ../block/io.c:448
> #7  0x000055fbb13c71a7 in blk_drain (blk=0x55fbb26c5a00) at ../block/block-backend.c:1718
> #8  0x000055fbb13c8bbd in blk_unref (blk=0x55fbb26c5a00) at ../block/block-backend.c:498
> #9  blk_unref (blk=0x55fbb26c5a00) at ../block/block-backend.c:491
> #10 0x000055fbb1024863 in hmp_qemu_io (mon=0x7fffaf3fc7d0, qdict=<optimized out>)
>     at ../block/monitor/block-hmp-cmds.c:628
> 
> Can you make anything out of this?
> 

Hmm.. Interesting.

man pthread_mutex_unlock
...
      EPERM  The  mutex type is PTHREAD_MUTEX_ERRORCHECK or PTHREAD_MUTEX_RECURSIVE, or the mutex is a
               robust mutex, and the current thread does not own the mutex.

So, thread doesn't own the mutex.. We have an iothread here.

AIO_WAIT_WHILE() documents that ctx must be acquired exactly once by caller.. But I don't see, where is it acquired in the call stack?

The other question, is why permission conflict is lost with the commit. Strange. I ss that hmp_qemu_io creates blk with perm=0 and shread=BLK_PERM_ALL.. How could it conflict even before the considered commit?
Vladimir Sementsov-Ogievskiy April 21, 2021, 8:31 a.m. UTC | #5
07.04.2021 14:38, Vladimir Sementsov-Ogievskiy wrote:
> 07.04.2021 14:19, Max Reitz wrote:
>> On 16.01.21 22:46, Vladimir Sementsov-Ogievskiy wrote:
>>> If main job coroutine called job_yield (while some background process
>>> is in progress), we should give it a chance to call job_pause_point().
>>> It will be used in backup, when moved on async block-copy.
>>>
>>> Note, that job_user_pause is not enough: we want to handle
>>> child_job_drained_begin() as well, which call job_pause().
>>>
>>> Still, if job is already in job_do_yield() in job_pause_point() we
>>> should not enter it.
>>>
>>> iotest 109 output is modified: on stop we do bdrv_drain_all() which now
>>> triggers job pause immediately (and pause after ready is standby).
>>>
>>> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com>
>>> ---
>>>   job.c                      |  3 +++
>>>   tests/qemu-iotests/109.out | 24 ++++++++++++++++++++++++
>>>   2 files changed, 27 insertions(+)
>>
>> While looking into
>>
>> https://lists.gnu.org/archive/html/qemu-block/2021-04/msg00035.html
>>
>> I noticed this:
>>
>> $ ./qemu-img create -f raw src.img 1G
>> $ ./qemu-img create -f raw dst.img 1G
>>
>> $ (echo '
>>     {"execute":"qmp_capabilities"}
>>     {"execute":"blockdev-mirror",
>>      "arguments":{"job-id":"mirror",
>>                   "device":"source",
>>                   "target":"target",
>>                   "sync":"full",
>>                   "filter-node-name":"mirror-top"}}
>> '; sleep 3; echo '
>>     {"execute":"human-monitor-command",
>>      "arguments":{"command-line":
>>                   "qemu-io mirror-top \"write 0 1G\""}}') \
>> | x86_64-softmmu/qemu-system-x86_64 \
>>     -qmp stdio \
>>     -blockdev file,node-name=source,filename=src.img \
>>     -blockdev file,node-name=target,filename=dst.img \
>>     -object iothread,id=iothr0 \
>>     -device virtio-blk,drive=source,iothread=iothr0
>>
>> Before this commit, qemu-io returned an error that there is a permission conflict with virtio-blk.  After this commit, there is an abort (“qemu: qemu_mutex_unlock_impl: Operation not permitted”):
>>
>> #0  0x00007f8445a4eef5 in raise () at /usr/lib/libc.so.6
>> #1  0x00007f8445a38862 in abort () at /usr/lib/libc.so.6
>> #2  0x000055fbb14a36bf in error_exit
>>     (err=<optimized out>, msg=msg@entry=0x55fbb1634790 <__func__.27> "qemu_mutex_unlock_impl")
>>     at ../util/qemu-thread-posix.c:37
>> #3  0x000055fbb14a3bc3 in qemu_mutex_unlock_impl
>>     (mutex=mutex@entry=0x55fbb25ab6e0, file=file@entry=0x55fbb1636957 "../util/async.c", line=line@entry=650)
>>     at ../util/qemu-thread-posix.c:109
>> #4  0x000055fbb14b2e75 in aio_context_release (ctx=ctx@entry=0x55fbb25ab680) at ../util/async.c:650
>> #5  0x000055fbb13d2029 in bdrv_do_drained_begin
>>     (bs=bs@entry=0x55fbb3a87000, recursive=recursive@entry=false, parent=parent@entry=0x0, ignore_bds_parents=ignore_bds_parents@entry=false, poll=poll@entry=true) at ../block/io.c:441
>> #6  0x000055fbb13d2192 in bdrv_do_drained_begin
>>     (poll=true, ignore_bds_parents=false, parent=0x0, recursive=false, bs=0x55fbb3a87000) at ../block/io.c:448
>> #7  0x000055fbb13c71a7 in blk_drain (blk=0x55fbb26c5a00) at ../block/block-backend.c:1718
>> #8  0x000055fbb13c8bbd in blk_unref (blk=0x55fbb26c5a00) at ../block/block-backend.c:498
>> #9  blk_unref (blk=0x55fbb26c5a00) at ../block/block-backend.c:491
>> #10 0x000055fbb1024863 in hmp_qemu_io (mon=0x7fffaf3fc7d0, qdict=<optimized out>)
>>     at ../block/monitor/block-hmp-cmds.c:628
>>
>> Can you make anything out of this?
>>
> 
> Hmm.. Interesting.
> 
> man pthread_mutex_unlock
> ...
>      EPERM  The  mutex type is PTHREAD_MUTEX_ERRORCHECK or PTHREAD_MUTEX_RECURSIVE, or the mutex is a
>               robust mutex, and the current thread does not own the mutex.
> 
> So, thread doesn't own the mutex.. We have an iothread here.
> 
> AIO_WAIT_WHILE() documents that ctx must be acquired exactly once by caller.. But I don't see, where is it acquired in the call stack?
> 
> The other question, is why permission conflict is lost with the commit. Strange. I ss that hmp_qemu_io creates blk with perm=0 and shread=BLK_PERM_ALL.. How could it conflict even before the considered commit?
> 


Sorry, I've answered and forgot about this thread. Now, looking through my series I find this again. Seems that problem is really in lacking aio-context locking around blk_unref(). I'll send patch now.
diff mbox series

Patch

diff --git a/job.c b/job.c
index 8fecf38960..3aaaebafe2 100644
--- a/job.c
+++ b/job.c
@@ -553,6 +553,9 @@  static bool job_timer_not_pending(Job *job)
 void job_pause(Job *job)
 {
     job->pause_count++;
+    if (!job->paused) {
+        job_enter(job);
+    }
 }
 
 void job_resume(Job *job)
diff --git a/tests/qemu-iotests/109.out b/tests/qemu-iotests/109.out
index 6e73406cdb..8f839b4b7f 100644
--- a/tests/qemu-iotests/109.out
+++ b/tests/qemu-iotests/109.out
@@ -42,6 +42,8 @@  read 512/512 bytes at offset 0
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 1024, "offset": 1024, "speed": 0, "type": "mirror"}}
@@ -91,6 +93,8 @@  read 512/512 bytes at offset 0
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 197120, "offset": 197120, "speed": 0, "type": "mirror"}}
@@ -140,6 +144,8 @@  read 512/512 bytes at offset 0
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 327680, "offset": 327680, "speed": 0, "type": "mirror"}}
@@ -189,6 +195,8 @@  read 512/512 bytes at offset 0
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 1024, "offset": 1024, "speed": 0, "type": "mirror"}}
@@ -238,6 +246,8 @@  read 512/512 bytes at offset 0
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 65536, "offset": 65536, "speed": 0, "type": "mirror"}}
@@ -287,6 +297,8 @@  read 512/512 bytes at offset 0
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 2560, "offset": 2560, "speed": 0, "type": "mirror"}}
@@ -335,6 +347,8 @@  read 512/512 bytes at offset 0
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 2560, "offset": 2560, "speed": 0, "type": "mirror"}}
@@ -383,6 +397,8 @@  read 512/512 bytes at offset 0
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 31457280, "offset": 31457280, "speed": 0, "type": "mirror"}}
@@ -431,6 +447,8 @@  read 512/512 bytes at offset 0
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 327680, "offset": 327680, "speed": 0, "type": "mirror"}}
@@ -479,6 +497,8 @@  read 512/512 bytes at offset 0
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 2048, "offset": 2048, "speed": 0, "type": "mirror"}}
@@ -507,6 +527,8 @@  WARNING: Image format was not specified for 'TEST_DIR/t.raw' and probing guessed
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 512, "offset": 512, "speed": 0, "type": "mirror"}}
@@ -528,6 +550,8 @@  Images are identical.
 {"execute":"quit"}
 {"return": {}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "SHUTDOWN", "data": {"guest": false, "reason": "host-qmp-quit"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "standby", "id": "src"}}
+{"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "ready", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "waiting", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "JOB_STATUS_CHANGE", "data": {"status": "pending", "id": "src"}}
 {"timestamp": {"seconds":  TIMESTAMP, "microseconds":  TIMESTAMP}, "event": "BLOCK_JOB_COMPLETED", "data": {"device": "src", "len": 512, "offset": 512, "speed": 0, "type": "mirror"}}