Skip to content

Commit 67fe213

Browse files
committed
Added threading test
tests/test_sys_trace.py test_callback_preservation() test_callback_wrapping() test_wrapping_line_event_disabling_callback() Minor stylistic updates test_wrapping_thread_local_callbacks() New test for wrapping around thread-local tracing functions in a multithreaded environment
1 parent 28c4d5e commit 67fe213

File tree

1 file changed

+90
-20
lines changed

1 file changed

+90
-20
lines changed

tests/test_sys_trace.py

Lines changed: 90 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -10,20 +10,22 @@
1010
- However, there effects are isolated since each test is run in a
1111
separate Python subprocess.
1212
"""
13-
import contextlib
13+
import concurrent.futures
1414
import functools
1515
import inspect
1616
import linecache
1717
import os
1818
import subprocess
1919
import sys
20+
import time
2021
import tempfile
2122
import textwrap
23+
import threading
2224
import pytest
2325
from ast import literal_eval
2426
from io import StringIO
2527
from types import FrameType
26-
from typing import Any, Callable, Generator, List, Optional, Literal, Union
28+
from typing import Any, Callable, List, Literal, Union
2729
from line_profiler import LineProfiler
2830

2931

@@ -226,7 +228,7 @@ class MyException(Exception):
226228
pass
227229

228230

229-
# Test: callbacks preserved before/after using the profiler
231+
# Tests
230232

231233

232234
def _test_helper_callback_preservation(
@@ -235,7 +237,7 @@ def _test_helper_callback_preservation(
235237
assert sys.gettrace() is callback, f'can\'t set trace to {callback!r}'
236238
profile = LineProfiler(wrap_trace=False)
237239
profile.enable_by_count()
238-
assert sys.gettrace() is profile, f'can\'t set trace to the profiler'
240+
assert sys.gettrace() is profile, 'can\'t set trace to the profiler'
239241
profile.disable_by_count()
240242
assert sys.gettrace() is callback, f'trace not restored to {callback!r}'
241243
sys.settrace(None)
@@ -251,9 +253,6 @@ def test_callback_preservation():
251253
_test_helper_callback_preservation(lambda frame, event, arg: None)
252254

253255

254-
# Test: profiler can wrap around an existing callback and use it
255-
256-
257256
@pytest.mark.parametrize(
258257
('label', 'use_profiler', 'wrap_trace'),
259258
[('base case', False, False),
@@ -279,9 +278,9 @@ def test_callback_wrapping(
279278
foo_like = foo
280279
trace_preserved = True
281280
if trace_preserved:
282-
exp_output = [f'foo: spam = {spam}' for spam in range(1, 6)]
281+
exp_logs = [f'foo: spam = {spam}' for spam in range(1, 6)]
283282
else:
284-
exp_output = []
283+
exp_logs = []
285284

286285
assert sys.gettrace() is my_callback, 'can\'t set custom trace'
287286
my_callback.emit_debug = True
@@ -293,7 +292,7 @@ def test_callback_wrapping(
293292
# Check that the existing trace function has been called where
294293
# appropriate
295294
print(f'Logs: {logs!r}')
296-
assert logs == exp_output, f'expected logs = {exp_output!r}, got {logs!r}'
295+
assert logs == exp_logs, f'expected logs = {exp_logs!r}, got {logs!r}'
297296

298297
# Check that the profiling is as expected: 5 hits on the
299298
# incrementation line
@@ -308,10 +307,6 @@ def test_callback_wrapping(
308307
assert nhits == 5, f'expected 5 profiler hits, got {nhits!r}'
309308

310309

311-
# Test: if the wrapped existing callback unsets itself, the profiler's
312-
# callback stops calling it, but profiling continues
313-
314-
315310
@pytest.mark.parametrize(
316311
('label', 'use_profiler', 'enable_count'),
317312
[('base case', False, 0),
@@ -396,10 +391,6 @@ def test_wrapping_throwing_callback(
396391
f'profiler hits, got {nhits!r}')
397392

398393

399-
# Test: if the wrapped existing callback set `frame.f_trace_lines`, the
400-
# profiler's callback catches and reverts that
401-
402-
403394
@pytest.mark.parametrize(('label', 'use_profiler'),
404395
[('base case', False), ('profiled', True)])
405396
@isolate_test_in_subproc
@@ -432,8 +423,8 @@ def test_wrapping_line_event_disabling_callback(label: str,
432423
# Check that the trace function has been called exactly once on the
433424
# line event, and once on the return event
434425
print(f'Logs: {logs!r}')
435-
exp_output = [f'foo: spam = 1', 'Returning from `foo()`']
436-
assert logs == exp_output, f'expected logs = {exp_output!r}, got {logs!r}'
426+
exp_logs = ['foo: spam = 1', 'Returning from `foo()`']
427+
assert logs == exp_logs, f'expected logs = {exp_logs!r}, got {logs!r}'
437428

438429
# Check that the profiling is as expected: 5 hits on the
439430
# incrementation line
@@ -446,3 +437,82 @@ def test_wrapping_line_event_disabling_callback(label: str,
446437
line, = (line for line in out.splitlines() if '+=' in line)
447438
nhits = int(line.split()[1])
448439
assert nhits == 5, f'expected 5 profiler hits, got {nhits!r}'
440+
441+
442+
def _test_helper_wrapping_thread_local_callbacks(
443+
profile: Union[LineProfiler, None], sleep: float = .0625) -> str:
444+
logs = []
445+
if threading.current_thread() == threading.main_thread():
446+
thread_label = 'main'
447+
func = foo
448+
my_callback = get_incr_logger(logs, func)
449+
exp_logs = [f'foo: spam = {spam}' for spam in range(1, 6)]
450+
else:
451+
thread_label = 'side'
452+
func = bar
453+
my_callback = get_return_logger(logs)
454+
exp_logs = ['Returning from `bar()`']
455+
if profile is None:
456+
func_like = func
457+
else:
458+
func_like = profile(func)
459+
print(f'Thread: {threading.get_ident()} ({thread_label})')
460+
461+
# Check result
462+
sys.settrace(my_callback)
463+
assert sys.gettrace() is my_callback, 'can\'t set custom trace'
464+
my_callback.emit_debug = True
465+
x = func_like(5)
466+
my_callback.emit_debug = False
467+
assert x == 15, f'expected `{func.__name__}(5) = 15`, got {x!r}'
468+
assert sys.gettrace() is my_callback, 'trace not restored afterwards'
469+
470+
# Check logs
471+
print(f'Logs ({thread_label} thread): {logs!r}')
472+
assert logs == exp_logs, f'expected logs = {exp_logs!r}, got {logs!r}'
473+
time.sleep(sleep)
474+
return '\n'.join(logs)
475+
476+
477+
@pytest.mark.parametrize(('label', 'use_profiler'),
478+
[('base case', False), ('profiled', True)])
479+
@isolate_test_in_subproc
480+
def test_wrapping_thread_local_callbacks(label: str,
481+
use_profiler: bool) -> None:
482+
"""
483+
Test in a subprocess that the profiler properly handles thread-local
484+
`sys` trace callbacks.
485+
"""
486+
profile = LineProfiler(wrap_trace=True) if use_profiler else None
487+
expected_results = {
488+
# From the main thread
489+
'\n'.join(f'foo: spam = {spam}' for spam in range(1, 6)),
490+
# From the other thread
491+
'Returning from `bar()`',
492+
}
493+
494+
# Run tasks (and so some basic checks)
495+
results = set()
496+
with concurrent.futures.ThreadPoolExecutor(max_workers=1) as executor:
497+
tasks = []
498+
tasks.append(executor.submit( # This is run on a side thread
499+
_test_helper_wrapping_thread_local_callbacks, profile))
500+
# This is run on the main thread
501+
results.add(_test_helper_wrapping_thread_local_callbacks(profile))
502+
results.update(future.result()
503+
for future in concurrent.futures.as_completed(tasks))
504+
assert results == expected_results, (f'expected {expected_results!r}, '
505+
f'got {results!r}')
506+
507+
# Check profiling
508+
if profile is None:
509+
return
510+
with StringIO() as sio:
511+
profile.print_stats(stream=sio, summarize=True)
512+
out = sio.getvalue()
513+
print(out)
514+
for var in 'spam', 'ham':
515+
line, = (line for line in out.splitlines()
516+
if line.endswith('+= ' + var))
517+
nhits = int(line.split()[1])
518+
assert nhits == 5, f'expected 5 profiler hits, got {nhits!r}'

0 commit comments

Comments
 (0)