def test_time_func_default(self):
"""Make sure that the default time_func=None"""
sw = StopWatch(time_func=None)
with sw.timer('root'):
pass
agg_report = sw.get_last_aggregated_report()
tr_data = agg_report.root_timer_data
assert tr_data.name == 'root'
assert tr_data.end_time >= tr_data.start_time
def test_time_func_default(self):
"""Make sure that the default time_func=None"""
sw = StopWatch(time_func=None)
with sw.timer('root'):
pass
agg_report = sw.get_last_aggregated_report()
tr_data = agg_report.root_timer_data
assert tr_data.name == 'root'
assert tr_data.end_time >= tr_data.start_time
def test_multiple_root_spans(self):
"""Test multiple root spans timed in one instance of the StopWatch object."""
sw = StopWatch()
with sw.timer('root'):
with sw.timer('child'):
pass
agg_values = sw.get_last_aggregated_report().aggregated_values
assert len(agg_values) == 2
assert all([span in agg_values for span in ('root', 'root#child')])
with sw.timer('root'):
with sw.timer('different_child'):
pass
agg_values = sw.get_last_aggregated_report().aggregated_values
assert len(agg_values) == 2
assert all([span in agg_values for span in ('root', 'root#different_child')])
def test_sampling_timer(self):
for i in range(100):
sw = StopWatch()
with sw.timer('root', start_time=20, end_time=120):
with sw.sampling_timer('child', p=0.5, start_time=40, end_time=100):
pass
agg_report = sw.get_last_aggregated_report()
assert len(agg_report.aggregated_values) in (1, 2)
if len(agg_report.aggregated_values) == 2:
assert agg_report.aggregated_values['root#child'] == [60000.0, 1, None]
def test_stopwatch_cancel(self):
"""Test that spans can be correctly cancelled and not reported."""
sw = StopWatch()
sw.start('root')
sw.start('child')
sw.cancel('child')
sw.end('root')
agg_values = sw.get_last_aggregated_report().aggregated_values
assert len(agg_values) == 1
assert 'root' in agg_values
def test_stopwatch_cancel_context_manager(self):
"""Test that spans can be cancelled while inside a span context."""
sw = StopWatch()
with sw.timer('root'):
with sw.timer('child'):
sw.cancel('child')
with sw.timer('grand'):
pass
agg_values = sw.get_last_aggregated_report().aggregated_values
assert len(agg_values) == 2
assert all([span in agg_values for span in ('root', 'root#grand')])
def test_override_exports(self):
export_tracing = Mock()
export_timers = Mock()
sw = StopWatch(
export_tracing_func=export_tracing,
export_aggregated_timers_func=export_timers,
)
add_timers(sw)
agg_report = sw.get_last_aggregated_report()
traces = sw.get_last_trace_report()
export_timers.assert_called_once_with(aggregated_report=agg_report)
export_tracing.assert_called_once_with(reported_traces=traces)
assert agg_report.aggregated_values == {
'root': [900000.0, 1, None],
'root#child1': [240000.0, 2, MyBuckets.BUCKET_A],
'root#child1#grand_children1': [20000.0, 1, None],
'root#child1#grand_children2': [80000.0, 2, None],
'root#child1#grand_children3': [10000.0, 1, None],
'root#child2': [560000.0, 1, MyBuckets.BUCKET_B],
'root#child2#grand_children1': [260000.0, 1, None],
'root#child2#grand_children3': [10000.0, 1, None],
}
assert agg_report.root_timer_data.start_time == 20.0
assert agg_report.root_timer_data.end_time == 920.0
assert agg_report.root_timer_data.name == 'root'
assert agg_report.root_timer_data.trace_annotations == [
TraceAnnotation('Cooltag', '1', 50),
TraceAnnotation('Slowtag', '1', 920),
]
# Traces are listed in the same order that scopes close
assert [(trace.name, trace.log_name, trace.start_time,
trace.end_time, trace.parent_span_id) for trace in traces] == [
('grand_children1', 'root#child1#grand_children1', 60, 80, traces[2].span_id),
('grand_children2', 'root#child1#grand_children2', 100, 120, traces[2].span_id),
('child1', 'root#child1', 40, 140, traces[9].span_id),
('grand_children3', 'root#child1#grand_children3', 180, 190, traces[5].span_id),
('grand_children2', 'root#child1#grand_children2', 220, 280, traces[5].span_id),
('child1', 'root#child1', 160, 300, traces[9].span_id),
('grand_children3', 'root#child2#grand_children3', 380, 390, traces[8].span_id),
('grand_children1', 'root#child2#grand_children1', 520, 780, traces[8].span_id),
('child2', 'root#child2', 320, 880, traces[9].span_id),
('root', 'root', 20, 920, None),
]
assert all(trace.trace_annotations == [] for trace in traces[:9])
assert traces[9].trace_annotations == [
TraceAnnotation('Cooltag', '1', 50),
TraceAnnotation('Slowtag', '1', 920),
]
def test_override_exports(self):
export_tracing = Mock()
export_timers = Mock()
sw = StopWatch(
export_tracing_func=export_tracing,
export_aggregated_timers_func=export_timers,
)
add_timers(sw)
agg_report = sw.get_last_aggregated_report()
traces = sw.get_last_trace_report()
export_timers.assert_called_once_with(aggregated_report=agg_report)
export_tracing.assert_called_once_with(reported_traces=traces)
assert agg_report.aggregated_values == {
'root': [900000.0, 1, None],
'root#child1': [240000.0, 2, MyBuckets.BUCKET_A],
'root#child1#grand_children1': [20000.0, 1, None],
'root#child1#grand_children2': [80000.0, 2, None],
'root#child1#grand_children3': [10000.0, 1, None],
'root#child2': [560000.0, 1, MyBuckets.BUCKET_B],
'root#child2#grand_children1': [260000.0, 1, None],
'root#child2#grand_children3': [10000.0, 1, None],
}
assert agg_report.root_timer_data.start_time == 20.0
assert agg_report.root_timer_data.end_time == 920.0
assert agg_report.root_timer_data.name == 'root'
assert agg_report.root_timer_data.trace_annotations == [
TraceAnnotation('Cooltag', '1', 50),
TraceAnnotation('Slowtag', '1', 920),
]
# Traces are listed in the same order that scopes close
assert [(trace.name, trace.log_name, trace.start_time,
trace.end_time, trace.parent_span_id) for trace in traces] == [
('grand_children1', 'root#child1#grand_children1', 60, 80, traces[2].span_id),
('grand_children2', 'root#child1#grand_children2', 100, 120, traces[2].span_id),
('child1', 'root#child1', 40, 140, traces[9].span_id),
('grand_children3', 'root#child1#grand_children3', 180, 190, traces[5].span_id),
('grand_children2', 'root#child1#grand_children2', 220, 280, traces[5].span_id),
('child1', 'root#child1', 160, 300, traces[9].span_id),
('grand_children3', 'root#child2#grand_children3', 380, 390, traces[8].span_id),
('grand_children1', 'root#child2#grand_children1', 520, 780, traces[8].span_id),
('child2', 'root#child2', 320, 880, traces[9].span_id),
('root', 'root', 20, 920, None),
]
assert all(trace.trace_annotations == [] for trace in traces[:9])
assert traces[9].trace_annotations == [
TraceAnnotation('Cooltag', '1', 50),
TraceAnnotation('Slowtag', '1', 920),
]
def test_override_exports(self):
export_tracing = Mock()
export_timers = Mock()
sw = StopWatch(
export_tracing_func=export_tracing,
export_aggregated_timers_func=export_timers,
)
add_timers(sw)
agg_report = sw.get_last_aggregated_report()
traces = sw.get_last_trace_report()
assert export_timers.call_args[1]['reported_values'] == agg_report[0]
assert export_timers.call_args[1]['tags'] == agg_report[1]
export_tracing.assert_called_once_with(reported_traces=traces)
export_timers.assert_called_once_with(
reported_values={
'root': [900000.0, 1, None],
'root#child1': [240000.0, 2, MyBuckets.BUCKET_A],
'root#child1#grand_children1': [20000.0, 1, None],
'root#child1#grand_children2': [80000.0, 2, None],
'root#child1#grand_children3': [10000.0, 1, None],
'root#child2': [560000.0, 1, MyBuckets.BUCKET_B],
'root#child2#grand_children1': [260000.0, 1, None],
'root#child2#grand_children3': [10000.0, 1, None],
},
tags=set(["Cooltag", "Slowtag"]),
total_time_ms=900000.0,
root_span_name="root",
)
# Traces are listed in the same order that scopes close
assert [(trace.name, trace.log_name, trace.start_time,
trace.end_time, trace.parent_span_id) for trace in traces] == [
('grand_children1', 'root#child1#grand_children1', 60, 80, traces[2].span_id),
('grand_children2', 'root#child1#grand_children2', 100, 120, traces[2].span_id),
('child1', 'root#child1', 40, 140, traces[9].span_id),
('grand_children3', 'root#child1#grand_children3', 180, 190, traces[5].span_id),
('grand_children2', 'root#child1#grand_children2', 220, 280, traces[5].span_id),
('child1', 'root#child1', 160, 300, traces[9].span_id),
('grand_children3', 'root#child2#grand_children3', 380, 390, traces[8].span_id),
('grand_children1', 'root#child2#grand_children1', 520, 780, traces[8].span_id),
('child2', 'root#child2', 320, 880, traces[9].span_id),
('root', 'root', 20, 920, None),
]
assert all(trace.trace_annotations == [] for trace in traces[:9])
assert traces[9].trace_annotations == [
KeyValueAnnotation('Cooltag', '1'),
KeyValueAnnotation('Slowtag', '1'),
]
def test_scope_in_loop(self):
sw = StopWatch()
with sw.timer('root', start_time=20, end_time=120):
for t in range(30, 100, 10):
with sw.timer('child', start_time=t, end_time=t + 5):
pass
agg_report = sw.get_last_aggregated_report()
assert agg_report.aggregated_values == {
'root': [100000.0, 1, None],
'root#child': [35000.0, 7, None],
}
assert agg_report.root_timer_data.start_time == 20.0
assert agg_report.root_timer_data.end_time == 120.0
assert agg_report.root_timer_data.name == 'root'
def test_scope_in_loop(self):
sw = StopWatch()
with sw.timer('root', start_time=20, end_time=120):
for t in range(30, 100, 10):
with sw.timer('child', start_time=t, end_time=t + 5):
pass
agg_report = sw.get_last_aggregated_report()
assert agg_report.aggregated_values == {
'root': [100000.0, 1, None],
'root#child': [35000.0, 7, None],
}
assert agg_report.root_timer_data.start_time == 20.0
assert agg_report.root_timer_data.end_time == 120.0
assert agg_report.root_timer_data.name == 'root'
def test_time_func(self):
"""Test override of the time_func"""
time_mock = Mock(side_effect=[50, 70])
sw = StopWatch(time_func=time_mock)
# Should call our timer func once on entry and once on exit
with sw.timer('root'):
pass
agg_report = sw.get_last_aggregated_report()
assert agg_report.aggregated_values == {
'root': [20000.0, 1, None],
}
assert agg_report.root_timer_data.start_time == 50.0
assert agg_report.root_timer_data.end_time == 70.0
assert agg_report.root_timer_data.name == 'root'
def test_time_func(self):
"""Test override of the time_func"""
time_mock = Mock(side_effect=[50, 70])
sw = StopWatch(time_func=time_mock)
# Should call our timer func once on entry and once on exit
with sw.timer('root'):
pass
agg_report = sw.get_last_aggregated_report()
assert agg_report.aggregated_values == {
'root': [20000.0, 1, None],
}
assert agg_report.root_timer_data.start_time == 50.0
assert agg_report.root_timer_data.end_time == 70.0
assert agg_report.root_timer_data.name == 'root'
def test_format_report(self):
sw = StopWatch()
add_timers(sw)
agg_report = sw.get_last_aggregated_report()
formatted_report = format_report(agg_report)
assert formatted_report == \
"************************\n" \
"*** StopWatch Report ***\n" \
"************************\n" \
"root 900000.000 (100%)\n" \
" BUCKET_A child1 2 240000.000 (27%)\n" \
" grand_children1 1 20000.000 (2%)\n" \
" grand_children2 2 80000.000 (9%)\n" \
" grand_children3 1 10000.000 (1%)\n" \
" BUCKET_B child2 1 560000.000 (62%)\n" \
" grand_children1 1 260000.000 (29%)\n" \
" grand_children3 1 10000.000 (1%)\n" \
"Tags: Cooltag, Slowtag"
def test_format_report(self):
sw = StopWatch()
add_timers(sw)
agg_report = sw.get_last_aggregated_report()
formatted_report = format_report(agg_report)
assert formatted_report == \
"root 900000.000ms (100%)\n" \
" BUCKET_A child1 2 240000.000ms (27%)\n" \
" grand_children1 1 20000.000ms (2%)\n" \
" grand_children2 2 80000.000ms (9%)\n" \
" grand_children3 1 10000.000ms (1%)\n" \
" BUCKET_B child2 1 560000.000ms (62%)\n" \
" grand_children1 1 260000.000ms (29%)\n" \
" grand_children3 1 10000.000ms (1%)\n" \
"Annotations: Cooltag, Slowtag"
formatted_report2 = sw.format_last_report()
assert formatted_report == formatted_report2
def test_stopwatch_cancel_multiple_root_spans(self):
"""Test that spans can be cancelled inside a span context, with multiple
of the same root span created. Ensure that they behave in an expected way.
"""
sw = StopWatch()
with sw.timer('root'):
with sw.timer('child'):
sw.cancel('child')
pass
with sw.timer('root'):
with sw.timer('child'):
pass
agg_values = sw.get_last_aggregated_report().aggregated_values
assert len(agg_values) == 2
assert all([span in agg_values for span in ('root', 'root#child')])
# Ensure that we are not leaking cancelled span data
assert not sw._cancelled_spans
