Message ID | 20200217150246.29180-15-vsementsov@virtuozzo.com |
---|---|
State | New |
Headers | show |
Series | Fix error handling during bitmap postcopy | expand |
On 17/02/2020 18:02, Vladimir Sementsov-Ogievskiy wrote: > The test aims to test _postcopy_ migration, and wants to do some write > operations during postcopy time. > > Test considers migrate status=complete event on source as start of > postcopy. This is completely wrong, completion is completion of the > whole migration process. Let's instead consider destination start as > start of postcopy, and use RESUME event for it. > > Next, as migration finish, let's use migration status=complete event on > target, as such method is closer to what libvirt or another user will > do, than tracking number of dirty-bitmaps. > > Finally, add a possibility to dump events for debug. And if > set debug to True, we see, that actual postcopy period is very small > relatively to the whole test duration time (~0.2 seconds to >40 seconds > for me). This means, that test is very inefficient in what it supposed > to do. Let's improve it in following commits. > > Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> > --- > tests/qemu-iotests/199 | 72 +++++++++++++++++++++++++++++++++--------- > 1 file changed, 57 insertions(+), 15 deletions(-) > > diff --git a/tests/qemu-iotests/199 b/tests/qemu-iotests/199 > index dda918450a..6599fc6fb4 100755 > --- a/tests/qemu-iotests/199 > +++ b/tests/qemu-iotests/199 > @@ -20,17 +20,43 @@ > > import os > import iotests > -import time > from iotests import qemu_img > > +debug = False > + > disk_a = os.path.join(iotests.test_dir, 'disk_a') > disk_b = os.path.join(iotests.test_dir, 'disk_b') > size = '256G' > fifo = os.path.join(iotests.test_dir, 'mig_fifo') > > > +def event_seconds(event): > + return event['timestamp']['seconds'] + \ > + event['timestamp']['microseconds'] / 1000000.0 > + > + > +def event_dist(e1, e2): > + return event_seconds(e2) - event_seconds(e1) > + > + > class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): > def tearDown(self): It's common to put the definition of setUp() ahead > + if debug: > + self.vm_a_events += self.vm_a.get_qmp_events() > + self.vm_b_events += self.vm_b.get_qmp_events() > + for e in self.vm_a_events: > + e['vm'] = 'SRC' > + for e in self.vm_b_events: > + e['vm'] = 'DST' > + events = (self.vm_a_events + self.vm_b_events) > + events = [(e['timestamp']['seconds'], > + e['timestamp']['microseconds'], > + e['vm'], > + e['event'], > + e.get('data', '')) for e in events] > + for e in sorted(events): > + print('{}.{:06} {} {} {}'.format(*e)) > + > self.vm_a.shutdown() > self.vm_b.shutdown() > os.remove(disk_a) > @@ -47,6 +73,10 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): > self.vm_a.launch() > self.vm_b.launch() > > + # collect received events for debug > + self.vm_a_events = [] > + self.vm_b_events = [] > + > def test_postcopy(self): > write_size = 0x40000000 > granularity = 512 > @@ -77,15 +107,13 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): > self.vm_a.hmp_qemu_io('drive0', 'write %d %d' % (s, chunk)) > s += 0x10000 > > - bitmaps_cap = {'capability': 'dirty-bitmaps', 'state': True} > - events_cap = {'capability': 'events', 'state': True} > + caps = [{'capability': 'dirty-bitmaps', 'state': True}, The name "capabilities" would be an appropriate identifier. > + {'capability': 'events', 'state': True}] > > - result = self.vm_a.qmp('migrate-set-capabilities', > - capabilities=[bitmaps_cap, events_cap]) > + result = self.vm_a.qmp('migrate-set-capabilities', capabilities=caps) > self.assert_qmp(result, 'return', {}) > > - result = self.vm_b.qmp('migrate-set-capabilities', > - capabilities=[bitmaps_cap]) > + result = self.vm_b.qmp('migrate-set-capabilities', capabilities=caps) > self.assert_qmp(result, 'return', {}) > > result = self.vm_a.qmp('migrate', uri='exec:cat>' + fifo) > @@ -94,24 +122,38 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): > result = self.vm_a.qmp('migrate-start-postcopy') > self.assert_qmp(result, 'return', {}) > > - while True: > - event = self.vm_a.event_wait('MIGRATION') > - if event['data']['status'] == 'completed': > - break > + e_resume = self.vm_b.event_wait('RESUME') "event_resume" gives a faster understanding > + self.vm_b_events.append(e_resume) > > s = 0x8000 > while s < write_size: > self.vm_b.hmp_qemu_io('drive0', 'write %d %d' % (s, chunk)) > s += 0x10000 > > + match = {'data': {'status': 'completed'}} > + e_complete = self.vm_b.event_wait('MIGRATION', match=match) "event_complete" also > + self.vm_b_events.append(e_complete) > + > + # take queued event, should already been happened > + e_stop = self.vm_a.event_wait('STOP') "event_stop" > + self.vm_a_events.append(e_stop) > + > + downtime = event_dist(e_stop, e_resume) > + postcopy_time = event_dist(e_resume, e_complete) > + > + # TODO: assert downtime * 10 < postcopy_time I got the results below in debug mode: downtime: 6.194924831390381 postcopy_time: 0.1592559814453125 1582102669.764919 SRC MIGRATION {'status': 'setup'} 1582102669.766179 SRC MIGRATION_PASS {'pass': 1} 1582102669.766234 SRC MIGRATION {'status': 'active'} 1582102669.768058 DST MIGRATION {'status': 'active'} 1582102669.801422 SRC MIGRATION {'status': 'postcopy-active'} 1582102669.801510 SRC STOP 1582102675.990041 DST MIGRATION {'status': 'postcopy-active'} 1582102675.996435 DST RESUME 1582102676.111313 SRC MIGRATION {'status': 'completed'} 1582102676.155691 DST MIGRATION {'status': 'completed'} > + if debug: with no usage in the following patches, you can put the whole block of relative code above under the "if debug: section > + print('downtime:', downtime) > + print('postcopy_time:', postcopy_time) > + > + # Assert that bitmap migration is finished (check that successor bitmap > + # is removed) > result = self.vm_b.qmp('query-block') > - while len(result['return'][0]['dirty-bitmaps']) > 1: > - time.sleep(2) > - result = self.vm_b.qmp('query-block') > + assert len(result['return'][0]['dirty-bitmaps']) == 1 > > + # Check content of migrated (and updated by new writes) bitmap > result = self.vm_b.qmp('x-debug-block-dirty-bitmap-sha256', > node='drive0', name='bitmap') > - > self.assert_qmp(result, 'return/sha256', sha256) > > > Reviewed-by: Andrey Shinkevich <andrey.shinkevich@virtuozzo.com>
19.02.2020 16:16, Andrey Shinkevich wrote: > On 17/02/2020 18:02, Vladimir Sementsov-Ogievskiy wrote: >> The test aims to test _postcopy_ migration, and wants to do some write >> operations during postcopy time. >> >> Test considers migrate status=complete event on source as start of >> postcopy. This is completely wrong, completion is completion of the >> whole migration process. Let's instead consider destination start as >> start of postcopy, and use RESUME event for it. >> >> Next, as migration finish, let's use migration status=complete event on >> target, as such method is closer to what libvirt or another user will >> do, than tracking number of dirty-bitmaps. >> >> Finally, add a possibility to dump events for debug. And if >> set debug to True, we see, that actual postcopy period is very small >> relatively to the whole test duration time (~0.2 seconds to >40 seconds >> for me). This means, that test is very inefficient in what it supposed >> to do. Let's improve it in following commits. >> >> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> >> --- >> tests/qemu-iotests/199 | 72 +++++++++++++++++++++++++++++++++--------- >> 1 file changed, 57 insertions(+), 15 deletions(-) >> >> diff --git a/tests/qemu-iotests/199 b/tests/qemu-iotests/199 >> index dda918450a..6599fc6fb4 100755 >> --- a/tests/qemu-iotests/199 >> +++ b/tests/qemu-iotests/199 >> @@ -20,17 +20,43 @@ >> import os >> import iotests >> -import time >> from iotests import qemu_img >> +debug = False >> + >> disk_a = os.path.join(iotests.test_dir, 'disk_a') >> disk_b = os.path.join(iotests.test_dir, 'disk_b') >> size = '256G' >> fifo = os.path.join(iotests.test_dir, 'mig_fifo') >> +def event_seconds(event): >> + return event['timestamp']['seconds'] + \ >> + event['timestamp']['microseconds'] / 1000000.0 >> + >> + >> +def event_dist(e1, e2): >> + return event_seconds(e2) - event_seconds(e1) >> + >> + >> class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): >> def tearDown(self): > It's common to put the definition of setUp() ahead > >> + if debug: >> + self.vm_a_events += self.vm_a.get_qmp_events() >> + self.vm_b_events += self.vm_b.get_qmp_events() >> + for e in self.vm_a_events: >> + e['vm'] = 'SRC' >> + for e in self.vm_b_events: >> + e['vm'] = 'DST' >> + events = (self.vm_a_events + self.vm_b_events) >> + events = [(e['timestamp']['seconds'], >> + e['timestamp']['microseconds'], >> + e['vm'], >> + e['event'], >> + e.get('data', '')) for e in events] >> + for e in sorted(events): >> + print('{}.{:06} {} {} {}'.format(*e)) >> + >> self.vm_a.shutdown() >> self.vm_b.shutdown() >> os.remove(disk_a) >> @@ -47,6 +73,10 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): >> self.vm_a.launch() >> self.vm_b.launch() >> + # collect received events for debug >> + self.vm_a_events = [] >> + self.vm_b_events = [] >> + >> def test_postcopy(self): >> write_size = 0x40000000 >> granularity = 512 >> @@ -77,15 +107,13 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): >> self.vm_a.hmp_qemu_io('drive0', 'write %d %d' % (s, chunk)) >> s += 0x10000 >> - bitmaps_cap = {'capability': 'dirty-bitmaps', 'state': True} >> - events_cap = {'capability': 'events', 'state': True} >> + caps = [{'capability': 'dirty-bitmaps', 'state': True}, > The name "capabilities" would be an appropriate identifier. > >> + {'capability': 'events', 'state': True}] >> - result = self.vm_a.qmp('migrate-set-capabilities', >> - capabilities=[bitmaps_cap, events_cap]) >> + result = self.vm_a.qmp('migrate-set-capabilities', capabilities=caps) >> self.assert_qmp(result, 'return', {}) >> - result = self.vm_b.qmp('migrate-set-capabilities', >> - capabilities=[bitmaps_cap]) >> + result = self.vm_b.qmp('migrate-set-capabilities', capabilities=caps) >> self.assert_qmp(result, 'return', {}) >> result = self.vm_a.qmp('migrate', uri='exec:cat>' + fifo) >> @@ -94,24 +122,38 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): >> result = self.vm_a.qmp('migrate-start-postcopy') >> self.assert_qmp(result, 'return', {}) >> - while True: >> - event = self.vm_a.event_wait('MIGRATION') >> - if event['data']['status'] == 'completed': >> - break >> + e_resume = self.vm_b.event_wait('RESUME') > "event_resume" gives a faster understanding > >> + self.vm_b_events.append(e_resume) >> s = 0x8000 >> while s < write_size: >> self.vm_b.hmp_qemu_io('drive0', 'write %d %d' % (s, chunk)) >> s += 0x10000 >> + match = {'data': {'status': 'completed'}} >> + e_complete = self.vm_b.event_wait('MIGRATION', match=match) > "event_complete" also > >> + self.vm_b_events.append(e_complete) >> + >> + # take queued event, should already been happened >> + e_stop = self.vm_a.event_wait('STOP') > "event_stop" > >> + self.vm_a_events.append(e_stop) >> + >> + downtime = event_dist(e_stop, e_resume) >> + postcopy_time = event_dist(e_resume, e_complete) >> + >> + # TODO: assert downtime * 10 < postcopy_time > > I got the results below in debug mode: That's why it's a TODO > > downtime: 6.194924831390381 > postcopy_time: 0.1592559814453125 > 1582102669.764919 SRC MIGRATION {'status': 'setup'} > 1582102669.766179 SRC MIGRATION_PASS {'pass': 1} > 1582102669.766234 SRC MIGRATION {'status': 'active'} > 1582102669.768058 DST MIGRATION {'status': 'active'} > 1582102669.801422 SRC MIGRATION {'status': 'postcopy-active'} > 1582102669.801510 SRC STOP > 1582102675.990041 DST MIGRATION {'status': 'postcopy-active'} > 1582102675.996435 DST RESUME > 1582102676.111313 SRC MIGRATION {'status': 'completed'} > 1582102676.155691 DST MIGRATION {'status': 'completed'} > >> + if debug: > with no usage in the following patches, you can put the whole block of relative code above under the "if debug: section TODO will be uncommented soon > >> + print('downtime:', downtime) >> + print('postcopy_time:', postcopy_time) >> + >> + # Assert that bitmap migration is finished (check that successor bitmap >> + # is removed) >> result = self.vm_b.qmp('query-block') >> - while len(result['return'][0]['dirty-bitmaps']) > 1: >> - time.sleep(2) >> - result = self.vm_b.qmp('query-block') >> + assert len(result['return'][0]['dirty-bitmaps']) == 1 >> + # Check content of migrated (and updated by new writes) bitmap >> result = self.vm_b.qmp('x-debug-block-dirty-bitmap-sha256', >> node='drive0', name='bitmap') >> - >> self.assert_qmp(result, 'return/sha256', sha256) >> > > Reviewed-by: Andrey Shinkevich <andrey.shinkevich@virtuozzo.com>
19.02.2020 16:16, Andrey Shinkevich wrote: > On 17/02/2020 18:02, Vladimir Sementsov-Ogievskiy wrote: >> The test aims to test _postcopy_ migration, and wants to do some write >> operations during postcopy time. >> >> Test considers migrate status=complete event on source as start of >> postcopy. This is completely wrong, completion is completion of the >> whole migration process. Let's instead consider destination start as >> start of postcopy, and use RESUME event for it. >> >> Next, as migration finish, let's use migration status=complete event on >> target, as such method is closer to what libvirt or another user will >> do, than tracking number of dirty-bitmaps. >> >> Finally, add a possibility to dump events for debug. And if >> set debug to True, we see, that actual postcopy period is very small >> relatively to the whole test duration time (~0.2 seconds to >40 seconds >> for me). This means, that test is very inefficient in what it supposed >> to do. Let's improve it in following commits. >> >> Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> >> --- >> tests/qemu-iotests/199 | 72 +++++++++++++++++++++++++++++++++--------- >> 1 file changed, 57 insertions(+), 15 deletions(-) >> >> diff --git a/tests/qemu-iotests/199 b/tests/qemu-iotests/199 >> index dda918450a..6599fc6fb4 100755 >> --- a/tests/qemu-iotests/199 >> +++ b/tests/qemu-iotests/199 >> @@ -20,17 +20,43 @@ >> import os >> import iotests >> -import time >> from iotests import qemu_img >> +debug = False >> + >> disk_a = os.path.join(iotests.test_dir, 'disk_a') >> disk_b = os.path.join(iotests.test_dir, 'disk_b') >> size = '256G' >> fifo = os.path.join(iotests.test_dir, 'mig_fifo') >> +def event_seconds(event): >> + return event['timestamp']['seconds'] + \ >> + event['timestamp']['microseconds'] / 1000000.0 >> + >> + >> +def event_dist(e1, e2): >> + return event_seconds(e2) - event_seconds(e1) >> + >> + >> class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): >> def tearDown(self): > It's common to put the definition of setUp() ahead Preexisting, I don't want to update it in this patch > >> + if debug: >> + self.vm_a_events += self.vm_a.get_qmp_events() >> + self.vm_b_events += self.vm_b.get_qmp_events() >> + for e in self.vm_a_events: >> + e['vm'] = 'SRC' >> + for e in self.vm_b_events: >> + e['vm'] = 'DST' >> + events = (self.vm_a_events + self.vm_b_events) >> + events = [(e['timestamp']['seconds'], >> + e['timestamp']['microseconds'], >> + e['vm'], >> + e['event'], >> + e.get('data', '')) for e in events] >> + for e in sorted(events): >> + print('{}.{:06} {} {} {}'.format(*e)) >> + >> self.vm_a.shutdown() >> self.vm_b.shutdown() >> os.remove(disk_a) >> @@ -47,6 +73,10 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): >> self.vm_a.launch() >> self.vm_b.launch() >> + # collect received events for debug >> + self.vm_a_events = [] >> + self.vm_b_events = [] >> + >> def test_postcopy(self): >> write_size = 0x40000000 >> granularity = 512 >> @@ -77,15 +107,13 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): >> self.vm_a.hmp_qemu_io('drive0', 'write %d %d' % (s, chunk)) >> s += 0x10000 >> - bitmaps_cap = {'capability': 'dirty-bitmaps', 'state': True} >> - events_cap = {'capability': 'events', 'state': True} >> + caps = [{'capability': 'dirty-bitmaps', 'state': True}, > The name "capabilities" would be an appropriate identifier. This will result in following lines growing and not fit into one line. I'll leave "caps". Also, they are called "caps" in iotest 169 and in migration.c. And here in the context always used together with full word ('capability': or capabilities=). > >> + {'capability': 'events', 'state': True}] >> - result = self.vm_a.qmp('migrate-set-capabilities', >> - capabilities=[bitmaps_cap, events_cap]) >> + result = self.vm_a.qmp('migrate-set-capabilities', capabilities=caps) >> self.assert_qmp(result, 'return', {}) >> - result = self.vm_b.qmp('migrate-set-capabilities', >> - capabilities=[bitmaps_cap]) >> + result = self.vm_b.qmp('migrate-set-capabilities', capabilities=caps) >> self.assert_qmp(result, 'return', {}) >> result = self.vm_a.qmp('migrate', uri='exec:cat>' + fifo) >> @@ -94,24 +122,38 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): >> result = self.vm_a.qmp('migrate-start-postcopy') >> self.assert_qmp(result, 'return', {}) >> - while True: >> - event = self.vm_a.event_wait('MIGRATION') >> - if event['data']['status'] == 'completed': >> - break >> + e_resume = self.vm_b.event_wait('RESUME') > "event_resume" gives a faster understanding OK, no problem > >> + self.vm_b_events.append(e_resume) >> s = 0x8000 >> while s < write_size: >> self.vm_b.hmp_qemu_io('drive0', 'write %d %d' % (s, chunk)) >> s += 0x10000 >> + match = {'data': {'status': 'completed'}} >> + e_complete = self.vm_b.event_wait('MIGRATION', match=match) > "event_complete" also OK > >> + self.vm_b_events.append(e_complete) >> + >> + # take queued event, should already been happened >> + e_stop = self.vm_a.event_wait('STOP') > "event_stop" OK > >> + self.vm_a_events.append(e_stop) >> + >> + downtime = event_dist(e_stop, e_resume) >> + postcopy_time = event_dist(e_resume, e_complete) >> + >> + # TODO: assert downtime * 10 < postcopy_time > > I got the results below in debug mode: > > downtime: 6.194924831390381 > postcopy_time: 0.1592559814453125 > 1582102669.764919 SRC MIGRATION {'status': 'setup'} > 1582102669.766179 SRC MIGRATION_PASS {'pass': 1} > 1582102669.766234 SRC MIGRATION {'status': 'active'} > 1582102669.768058 DST MIGRATION {'status': 'active'} > 1582102669.801422 SRC MIGRATION {'status': 'postcopy-active'} > 1582102669.801510 SRC STOP > 1582102675.990041 DST MIGRATION {'status': 'postcopy-active'} > 1582102675.996435 DST RESUME > 1582102676.111313 SRC MIGRATION {'status': 'completed'} > 1582102676.155691 DST MIGRATION {'status': 'completed'} > >> + if debug: > with no usage in the following patches, you can put the whole block of relative code above under the "if debug: section > >> + print('downtime:', downtime) >> + print('postcopy_time:', postcopy_time) >> + >> + # Assert that bitmap migration is finished (check that successor bitmap >> + # is removed) >> result = self.vm_b.qmp('query-block') >> - while len(result['return'][0]['dirty-bitmaps']) > 1: >> - time.sleep(2) >> - result = self.vm_b.qmp('query-block') >> + assert len(result['return'][0]['dirty-bitmaps']) == 1 >> + # Check content of migrated (and updated by new writes) bitmap >> result = self.vm_b.qmp('x-debug-block-dirty-bitmap-sha256', >> node='drive0', name='bitmap') >> - >> self.assert_qmp(result, 'return/sha256', sha256) >> > > Reviewed-by: Andrey Shinkevich <andrey.shinkevich@virtuozzo.com> Thanks!
diff --git a/tests/qemu-iotests/199 b/tests/qemu-iotests/199 index dda918450a..6599fc6fb4 100755 --- a/tests/qemu-iotests/199 +++ b/tests/qemu-iotests/199 @@ -20,17 +20,43 @@ import os import iotests -import time from iotests import qemu_img +debug = False + disk_a = os.path.join(iotests.test_dir, 'disk_a') disk_b = os.path.join(iotests.test_dir, 'disk_b') size = '256G' fifo = os.path.join(iotests.test_dir, 'mig_fifo') +def event_seconds(event): + return event['timestamp']['seconds'] + \ + event['timestamp']['microseconds'] / 1000000.0 + + +def event_dist(e1, e2): + return event_seconds(e2) - event_seconds(e1) + + class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): def tearDown(self): + if debug: + self.vm_a_events += self.vm_a.get_qmp_events() + self.vm_b_events += self.vm_b.get_qmp_events() + for e in self.vm_a_events: + e['vm'] = 'SRC' + for e in self.vm_b_events: + e['vm'] = 'DST' + events = (self.vm_a_events + self.vm_b_events) + events = [(e['timestamp']['seconds'], + e['timestamp']['microseconds'], + e['vm'], + e['event'], + e.get('data', '')) for e in events] + for e in sorted(events): + print('{}.{:06} {} {} {}'.format(*e)) + self.vm_a.shutdown() self.vm_b.shutdown() os.remove(disk_a) @@ -47,6 +73,10 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): self.vm_a.launch() self.vm_b.launch() + # collect received events for debug + self.vm_a_events = [] + self.vm_b_events = [] + def test_postcopy(self): write_size = 0x40000000 granularity = 512 @@ -77,15 +107,13 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): self.vm_a.hmp_qemu_io('drive0', 'write %d %d' % (s, chunk)) s += 0x10000 - bitmaps_cap = {'capability': 'dirty-bitmaps', 'state': True} - events_cap = {'capability': 'events', 'state': True} + caps = [{'capability': 'dirty-bitmaps', 'state': True}, + {'capability': 'events', 'state': True}] - result = self.vm_a.qmp('migrate-set-capabilities', - capabilities=[bitmaps_cap, events_cap]) + result = self.vm_a.qmp('migrate-set-capabilities', capabilities=caps) self.assert_qmp(result, 'return', {}) - result = self.vm_b.qmp('migrate-set-capabilities', - capabilities=[bitmaps_cap]) + result = self.vm_b.qmp('migrate-set-capabilities', capabilities=caps) self.assert_qmp(result, 'return', {}) result = self.vm_a.qmp('migrate', uri='exec:cat>' + fifo) @@ -94,24 +122,38 @@ class TestDirtyBitmapPostcopyMigration(iotests.QMPTestCase): result = self.vm_a.qmp('migrate-start-postcopy') self.assert_qmp(result, 'return', {}) - while True: - event = self.vm_a.event_wait('MIGRATION') - if event['data']['status'] == 'completed': - break + e_resume = self.vm_b.event_wait('RESUME') + self.vm_b_events.append(e_resume) s = 0x8000 while s < write_size: self.vm_b.hmp_qemu_io('drive0', 'write %d %d' % (s, chunk)) s += 0x10000 + match = {'data': {'status': 'completed'}} + e_complete = self.vm_b.event_wait('MIGRATION', match=match) + self.vm_b_events.append(e_complete) + + # take queued event, should already been happened + e_stop = self.vm_a.event_wait('STOP') + self.vm_a_events.append(e_stop) + + downtime = event_dist(e_stop, e_resume) + postcopy_time = event_dist(e_resume, e_complete) + + # TODO: assert downtime * 10 < postcopy_time + if debug: + print('downtime:', downtime) + print('postcopy_time:', postcopy_time) + + # Assert that bitmap migration is finished (check that successor bitmap + # is removed) result = self.vm_b.qmp('query-block') - while len(result['return'][0]['dirty-bitmaps']) > 1: - time.sleep(2) - result = self.vm_b.qmp('query-block') + assert len(result['return'][0]['dirty-bitmaps']) == 1 + # Check content of migrated (and updated by new writes) bitmap result = self.vm_b.qmp('x-debug-block-dirty-bitmap-sha256', node='drive0', name='bitmap') - self.assert_qmp(result, 'return/sha256', sha256)
The test aims to test _postcopy_ migration, and wants to do some write operations during postcopy time. Test considers migrate status=complete event on source as start of postcopy. This is completely wrong, completion is completion of the whole migration process. Let's instead consider destination start as start of postcopy, and use RESUME event for it. Next, as migration finish, let's use migration status=complete event on target, as such method is closer to what libvirt or another user will do, than tracking number of dirty-bitmaps. Finally, add a possibility to dump events for debug. And if set debug to True, we see, that actual postcopy period is very small relatively to the whole test duration time (~0.2 seconds to >40 seconds for me). This means, that test is very inefficient in what it supposed to do. Let's improve it in following commits. Signed-off-by: Vladimir Sementsov-Ogievskiy <vsementsov@virtuozzo.com> --- tests/qemu-iotests/199 | 72 +++++++++++++++++++++++++++++++++--------- 1 file changed, 57 insertions(+), 15 deletions(-)