Re: [PATCH v2 14/22] qemu-iotests/199: better catch postcopy time

[Andrey Shinkevich <andrey.shinkevich@virtuozzo.com>]

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>
-- 
With the best regards,
Andrey Shinkevich