Re: [Qemu-devel] [RFC PATCH] tests/qemu-iotests: re-format output to for make check-block

[Vladimir Sementsov-Ogievskiy]

05.05.2019 18:54, Thomas Huth wrote:
> On 03/05/2019 18.15, Alex Bennée wrote:
>>
>> Thomas Huth <address@hidden> writes:
>>
>>> On 03/05/2019 16.39, Alex Bennée wrote:
>>>> This attempts to clean-up the output to better match the output of the
>>>> rest of the QEMU check system. This includes:
>>>>
>>>>    - formatting as "  TEST    iotest: nnn"
>>>>    - calculating time diff at the end
>>>>    - only dumping config on failure
>>>>
>>>> Signed-off-by: Alex Bennée <address@hidden>
>>>> ---
>>>>   tests/qemu-iotests/check | 71 +++++++++++++++++++---------------------
>>>>   1 file changed, 34 insertions(+), 37 deletions(-)
>>>
>>> Thanks for tackling this! The output now looks nicer indeed if you run
>>> "make check-qtest check-block -j8". However, if you add a "V=1" at the
>>> end of the command line, the outputs look quite different again...
>>>
>>> That's why I thought that having a TAP mode for the check script could
>>> be a good idea, too. Then we could pipe the output through the
>>> tap-driver.pl script, too, so we get uniform output for all tests...?
>>
>> That would probably be a cleaner approach. What would be even better is
>> somehow expanding the list of tests at make time so you could run your
>> tests in parallel.
> 
> I agree that this might be the ultimate solution ... but I'm not sure
> whether the iotests are really ready for being run in parallel yet, so
> it will likely take quite some while 'till we are at that point. With
> that in mind (and thus also not sure yet whether my TAP idea is really
> the right approach), your patch is certainly a good interim solution
> which we should try to get merged, too, when my "make check" series gets
> accepted?
> 
>> I did wonder how useful the timing stuff was to developers.
> 
> Yes, me too ... maybe the block layer folks can comment on that one...?
> 
>   Thomas
> 

Hi!

It was useful to not miss performance degradation (1) and
to understand that test hangs (2) (if you know that it should
finish in 1 second, but 10 seconds already passed, the test
most probably hangs)

Run tests with your patch:

first run:
# check -qcow2 -T
   TEST    iotest: 001 [20:00:30] -> [20:00:31]
   TEST    iotest: 002 [20:00:31] -> [20:00:33]
   TEST    iotest: 003 [20:00:33] -> [20:00:34]
   TEST    iotest: 004 [20:00:34] -> [20:00:35]
   TEST    iotest: 005 [20:00:35] -> [20:00:36]
   TEST    iotest: 007 [20:00:36] -> [20:00:39]


second run:
# check -qcow2 -T
   TEST    iotest: 001 [20:00:41] -> [20:00:43] 2s (last 1s)
   TEST    iotest: 002 [20:00:43] -> [20:00:44] 1s (last 2s)
   TEST    iotest: 003 [20:00:44] -> [20:00:46] 2s (last 1s)
   TEST    iotest: 004 [20:00:46] -> [20:00:46] 0s (last 1s)
   TEST    iotest: 005 [20:00:46] -> [20:00:47] 1s (last 1s)
   TEST    iotest: 007 [20:00:47] -> [20:00:50] 3s (last 3s)
   TEST    iotest: 008 [20:00:50] -> [20:00:51]
   TEST    iotest: 009 [20:00:51] -> [20:00:51]
   TEST    iotest: 010 [20:00:51] -> [20:00:51]


So, in first run delta was not calculated and on second - calculated.
Could you calculate delta in all cases, to make first run look like
# check -qcow2 -T
   TEST    iotest: 001 [20:00:30] -> [20:00:31] 1s
   TEST    iotest: 002 [20:00:31] -> [20:00:33] 2s
   TEST    iotest: 003 [20:00:33] -> [20:00:34] 1s
   TEST    iotest: 004 [20:00:34] -> [20:00:35] 1s
   TEST    iotest: 005 [20:00:35] -> [20:00:36] 1s
   TEST    iotest: 007 [20:00:36] -> [20:00:39] 3s


-- 
Best regards,
Vladimir