2022-10-06 13:33:45 +02:00
# SPDX-FileCopyrightText: Red Hat, Inc.
# SPDX-License-Identifier: GPL-2.0-or-later
2020-04-24 00:51:35 +03:00
import pytest
2020-05-10 09:40:03 +03:00
from ovirt_imageio . _internal import stats
2020-04-24 00:51:35 +03:00
2020-08-31 15:51:28 +02:00
class FakeTime :
2020-04-24 00:51:35 +03:00
def __init__ ( self ) :
self . value = 0
def __call__ ( self ) :
return self . value
# Ccorrect usage
2020-04-25 21:00:25 +03:00
def test_empty ( ) :
2020-04-24 00:51:35 +03:00
c = stats . Clock ( )
stats: Extensible format
Change the stats format to extensible format. Instead of:
[connection=9.805853/1, dispatch=7.476260/135, operation=7.384645/134,
read=2.674123/133, write=3.923540/133, flush=0.658042/1]
Use:
[connection 1 ops, 9.805853 s] [dispatch 135 ops, 7.476260 s]
[operation 134 ops, 7.384645 s] [read 133 ops, 2.674123 s]
[write 133 ops, 3.923540 s] [flush 1 ops, 0.658042 s]
The new format allows adding more fields.
Change-Id: If1b92ea14b4286143753533b285a3818677adf95
Signed-off-by: Nir Soffer <nsoffer@redhat.com>
2020-04-24 02:26:50 +03:00
assert str ( c ) == " "
2020-04-24 00:51:35 +03:00
2020-04-26 17:18:40 +03:00
def test_stop_returns_elapsed_time ( ) :
fake_time = FakeTime ( )
c = stats . Clock ( fake_time )
2020-04-24 00:51:35 +03:00
c . start ( " read " )
fake_time . value + = 1
assert c . stop ( " read " ) == 1
c . start ( " read " )
fake_time . value + = 2
assert c . stop ( " read " ) == 2
2020-04-26 17:18:40 +03:00
def test_measure ( ) :
fake_time = FakeTime ( )
c = stats . Clock ( fake_time )
2020-04-24 00:51:35 +03:00
c . start ( " total " )
c . start ( " read " )
fake_time . value + = 1
c . stop ( " read " )
c . start ( " write " )
fake_time . value + = 1
c . stop ( " write " )
c . start ( " sync " )
fake_time . value + = 1
c . stop ( " sync " )
c . stop ( " total " )
assert str ( c ) == (
stats: Extensible format
Change the stats format to extensible format. Instead of:
[connection=9.805853/1, dispatch=7.476260/135, operation=7.384645/134,
read=2.674123/133, write=3.923540/133, flush=0.658042/1]
Use:
[connection 1 ops, 9.805853 s] [dispatch 135 ops, 7.476260 s]
[operation 134 ops, 7.384645 s] [read 133 ops, 2.674123 s]
[write 133 ops, 3.923540 s] [flush 1 ops, 0.658042 s]
The new format allows adding more fields.
Change-Id: If1b92ea14b4286143753533b285a3818677adf95
Signed-off-by: Nir Soffer <nsoffer@redhat.com>
2020-04-24 02:26:50 +03:00
" [total 1 ops, 3.000000 s] "
" [read 1 ops, 1.000000 s] "
" [write 1 ops, 1.000000 s] "
" [sync 1 ops, 1.000000 s] "
)
2020-04-24 00:51:35 +03:00
2020-04-26 17:18:40 +03:00
def test_measure_multiple ( ) :
fake_time = FakeTime ( )
c = stats . Clock ( fake_time )
2020-04-24 00:51:35 +03:00
c . start ( " total " )
c . start ( " read " )
fake_time . value + = 1
c . stop ( " read " )
c . start ( " write " )
fake_time . value + = 1
c . stop ( " write " )
c . start ( " read " )
fake_time . value + = 1
c . stop ( " read " )
c . start ( " write " )
fake_time . value + = 1
c . stop ( " write " )
c . start ( " sync " )
fake_time . value + = 1
c . stop ( " sync " )
c . stop ( " total " )
assert str ( c ) == (
stats: Extensible format
Change the stats format to extensible format. Instead of:
[connection=9.805853/1, dispatch=7.476260/135, operation=7.384645/134,
read=2.674123/133, write=3.923540/133, flush=0.658042/1]
Use:
[connection 1 ops, 9.805853 s] [dispatch 135 ops, 7.476260 s]
[operation 134 ops, 7.384645 s] [read 133 ops, 2.674123 s]
[write 133 ops, 3.923540 s] [flush 1 ops, 0.658042 s]
The new format allows adding more fields.
Change-Id: If1b92ea14b4286143753533b285a3818677adf95
Signed-off-by: Nir Soffer <nsoffer@redhat.com>
2020-04-24 02:26:50 +03:00
" [total 1 ops, 5.000000 s] "
" [read 2 ops, 2.000000 s] "
" [write 2 ops, 2.000000 s] "
" [sync 1 ops, 1.000000 s] "
)
2020-04-24 00:51:35 +03:00
2020-04-26 17:18:40 +03:00
def test_running ( ) :
fake_time = FakeTime ( )
c = stats . Clock ( fake_time )
2020-04-24 00:51:35 +03:00
c . start ( " total " )
fake_time . value + = 3
c . start ( " read " )
fake_time . value + = 4
c . stop ( " read " )
2020-04-26 02:42:50 +03:00
# Since total was not stopped, the operation is not counted.
assert str ( c ) == " [total 0 ops, 7.000000 s] [read 1 ops, 4.000000 s] "
2020-04-24 00:51:35 +03:00
2020-04-26 17:18:40 +03:00
def test_bytes ( ) :
fake_time = FakeTime ( )
c = stats . Clock ( fake_time )
stats: Support recording number of bytes
Support collecting number of bytes per every operation. This is more
tricky then expected, since we know the number of bytes only when I/O
completes, so we cannot pass it to start() or run().
To solve this, Clock.start() and Clock.run() return a Stats instance,
and the caller need to update the number of bytes manually.
Clock.__repr__ shows now the total number of bytes and total rate
for this operation formatted in human friendly manner.
NullClock use special NullStat instance that drop the bytes values, so
code does not need to care if stats collections is enabled.
The typical use case is:
with clock.run("name") as stats:
n = backend.write(buf)
stats.bytes += n
When the caller cannot use Clock.run(), it should keep the stats
instance and update it before calling stop.
stats = clock.start("name")
...
stats.bytes += 4096
clock.stop("name")
Here is output from the benchmark, showing the overhead of measuring
50,000 requests:
[connection 1 ops, 0.366829 s] [request 50000 ops, 0.334896 s]
[read 50000 ops, 0.030955 s, 97.66 GiB, 3.08 TiB/s]
[write 50000 ops, 0.031029 s, 97.66 GiB, 3.07 TiB/s]
Change-Id: I7dc223ec077284cacae1ceebb343b044b198cc3f
Signed-off-by: Nir Soffer <nsoffer@redhat.com>
2020-04-25 21:25:49 +03:00
c . start ( " total " )
# Using start()/stop().
s = c . start ( " read " )
s . bytes + = 512 * 1024 * * 2
fake_time . value + = 1
c . stop ( " read " )
s = c . start ( " write " )
s . bytes + = 200 * 1024 * * 2
fake_time . value + = 1
c . stop ( " write " )
# Using run().
with c . run ( " read " ) as s :
s . bytes + = 512 * 1024 * * 2
fake_time . value + = 1
with c . run ( " write " ) as s :
s . bytes + = 200 * 1024 * * 2
fake_time . value + = 1
with c . run ( " sync " ) :
fake_time . value + = 1
c . stop ( " total " )
assert str ( c ) == (
" [total 1 ops, 5.000000 s] "
" [read 2 ops, 2.000000 s, 1.00 GiB, 512.00 MiB/s] "
" [write 2 ops, 2.000000 s, 400.00 MiB, 200.00 MiB/s] "
" [sync 1 ops, 1.000000 s] "
)
def test_null_clock ( ) :
c = stats . NullClock ( )
# This clock records nothing...
with c . run ( " total " ) :
with c . run ( " read " ) as s :
s . bytes + = 4096
# bytes value is dropped...
assert s . bytes == 0
with c . run ( " sync " ) :
pass
# And always return empty string.
assert str ( c ) == " "
2020-04-26 17:18:40 +03:00
def test_error_before_stop ( ) :
fake_time = FakeTime ( )
c = stats . Clock ( fake_time )
2020-04-26 02:42:50 +03:00
c . start ( " read " )
fake_time . value + = 1
# User code fails here, before we increase bytes and call stop().
# Since read was not stopped the operation is not counted...
assert str ( c ) == " [read 0 ops, 1.000000 s] "
# And we cannot start this operation again.
with pytest . raises ( RuntimeError ) :
c . start ( " read " )
# We can abort the operation to continue to use this clock.
fake_time . value + = 1
c . abort ( " read " )
assert str ( c ) == " [read 0 ops, 2.000000 s] "
2020-04-26 17:18:40 +03:00
def test_error_in_run ( ) :
fake_time = FakeTime ( )
c = stats . Clock ( fake_time )
2020-04-26 02:42:50 +03:00
with pytest . raises ( RuntimeError ) :
with c . run ( " read " ) as s :
fake_time . value + = 1
raise RuntimeError ( " fake error " )
s . bytes + = 512 * 1024 * * 2
# First read failed, so bytes is not set and the operation is not counted.
assert str ( c ) == " [read 0 ops, 1.000000 s] "
# However clock was stopped, so next read can succeed.
with c . run ( " read " ) as s :
fake_time . value + = 1
s . bytes + = 512 * 1024 * * 2
# Bytes value is set now so we report total and rate values.
assert str ( c ) == " [read 1 ops, 2.000000 s, 512.00 MiB, 256.00 MiB/s] "
2020-04-24 00:51:35 +03:00
# Inccorrect usage
2020-04-25 21:00:25 +03:00
def test_start_twice ( ) :
2020-04-24 00:51:35 +03:00
c = stats . Clock ( )
c . start ( " started " )
with pytest . raises ( RuntimeError ) :
c . start ( " started " )
2020-04-25 21:00:25 +03:00
def test_stop_twice ( ) :
2020-04-24 00:51:35 +03:00
c = stats . Clock ( )
c . start ( " stopped " )
c . stop ( " stopped " )
with pytest . raises ( RuntimeError ) :
c . stop ( " stopped " )
2020-04-25 21:00:25 +03:00
def test_stop_missing ( ) :
2020-04-24 00:51:35 +03:00
c = stats . Clock ( )
with pytest . raises ( RuntimeError ) :
c . stop ( " missing " )
2020-04-26 17:18:40 +03:00
def test_run ( ) :
fake_time = FakeTime ( )
c = stats . Clock ( fake_time )
2020-04-24 00:51:35 +03:00
with c . run ( " total " ) :
with c . run ( " a " ) :
fake_time . value + = 4
with c . run ( " b " ) :
fake_time . value + = 3
stats: Extensible format
Change the stats format to extensible format. Instead of:
[connection=9.805853/1, dispatch=7.476260/135, operation=7.384645/134,
read=2.674123/133, write=3.923540/133, flush=0.658042/1]
Use:
[connection 1 ops, 9.805853 s] [dispatch 135 ops, 7.476260 s]
[operation 134 ops, 7.384645 s] [read 133 ops, 2.674123 s]
[write 133 ops, 3.923540 s] [flush 1 ops, 0.658042 s]
The new format allows adding more fields.
Change-Id: If1b92ea14b4286143753533b285a3818677adf95
Signed-off-by: Nir Soffer <nsoffer@redhat.com>
2020-04-24 02:26:50 +03:00
assert str ( c ) == (
" [total 1 ops, 7.000000 s] "
" [a 1 ops, 4.000000 s] "
" [b 1 ops, 3.000000 s] "
)
2020-04-24 00:51:35 +03:00
2020-04-25 21:00:25 +03:00
def test_run_recursive ( ) :
2020-04-24 00:51:35 +03:00
c = stats . Clock ( )
with c . run ( " started " ) :
with pytest . raises ( RuntimeError ) :
with c . run ( " started " ) :
pass
@pytest.mark.benchmark
tests: Benchmark both real and null clock
Add parameters so we test both the real clock and the null clock.
Here is an example (reformatted) output from the test:
$ tox -e bench test/stats_test.py -- -vs
test/stats_test.py::test_benchmark[clock]
[total 1 ops, 0.353321 s] [connection 1 ops, 0.353318 s] [request
50000 ops, 0.323798 s] [read 50000 ops, 0.030133 s, 97.66 GiB, 3.16
TiB/s] [write 50000 ops, 0.030439 s, 97.66 GiB, 3.13 TiB/s]
test/stats_test.py::test_benchmark[null-clock]
[total 1 ops, 0.229809 s]
Change-Id: Ibb46a8cf561b8ca2b86c71929509c5b1e463d252
Signed-off-by: Nir Soffer <nsoffer@redhat.com>
2020-04-26 02:31:00 +03:00
@pytest.mark.parametrize ( " clock " , [
pytest . param ( stats . Clock ( ) , id = " clock " ) ,
pytest . param ( stats . NullClock ( ) , id = " null-clock " ) ,
] )
def test_benchmark ( clock ) :
test = stats . Clock ( )
with test . run ( " total " ) :
clock . start ( " connection " )
# We have seen 66,000 requests per single upload with virt-v2v.
for i in range ( 50000 ) :
clock . start ( " request " )
with clock . run ( " read " ) as s :
s . bytes + = 2 * 1024 * * 2
with clock . run ( " write " ) as s :
s . bytes + = 2 * 1024 * * 2
clock . stop ( " request " )
clock . stop ( " connection " )
print ( " {} {} " . format ( test , clock ) )