229 lines
4.3 KiB
Markdown
229 lines
4.3 KiB
Markdown
# Profiling Patterns
|
|
|
|
Detailed profiling patterns for use with
|
|
`piker.toolz.profile.Profiler`.
|
|
|
|
## Pattern: Function Entry/Exit
|
|
|
|
```python
|
|
async def my_function():
|
|
profiler = Profiler(
|
|
msg='my_function()',
|
|
disabled=False,
|
|
ms_threshold=0.0,
|
|
)
|
|
|
|
step1()
|
|
profiler('step1')
|
|
|
|
step2()
|
|
profiler('step2')
|
|
|
|
# auto-prints on exit
|
|
```
|
|
|
|
## Pattern: Loop Iterations
|
|
|
|
```python
|
|
# DON'T profile inside tight loops (overhead!)
|
|
for i in range(1000):
|
|
profiler(f'iteration {i}') # NO!
|
|
|
|
# DO profile around loops
|
|
profiler = Profiler(msg='processing 1000 items')
|
|
for i in range(1000):
|
|
process(item[i])
|
|
profiler('processed all items')
|
|
```
|
|
|
|
## Pattern: Conditional Profiling
|
|
|
|
```python
|
|
# only profile when investigating specific issue
|
|
DEBUG_REPOSITION = True
|
|
|
|
def reposition(self, array):
|
|
if DEBUG_REPOSITION:
|
|
profiler = Profiler(
|
|
msg='GapAnnotations.reposition()',
|
|
disabled=False,
|
|
)
|
|
|
|
# ... do work
|
|
|
|
if DEBUG_REPOSITION:
|
|
profiler('completed reposition')
|
|
```
|
|
|
|
## Pattern: Teardown/Cleanup Profiling
|
|
|
|
```python
|
|
try:
|
|
# ... main work
|
|
pass
|
|
finally:
|
|
profiler = Profiler(
|
|
msg='Annotation teardown',
|
|
disabled=False,
|
|
ms_threshold=0.0,
|
|
)
|
|
|
|
cleanup_resources()
|
|
profiler('resources cleaned')
|
|
|
|
close_connections()
|
|
profiler('connections closed')
|
|
```
|
|
|
|
## Pattern: Distributed IPC Profiling
|
|
|
|
### Server-side (chart actor)
|
|
|
|
```python
|
|
# piker/ui/_remote_ctl.py
|
|
@tractor.context
|
|
async def remote_annotate(ctx):
|
|
async with ctx.open_stream() as stream:
|
|
async for msg in stream:
|
|
profiler = Profiler(
|
|
msg=f'Batch annotate {n} gaps',
|
|
disabled=False,
|
|
ms_threshold=0.0,
|
|
)
|
|
|
|
result = await handle_request(msg)
|
|
profiler('request handled')
|
|
|
|
await stream.send(result)
|
|
profiler('result sent')
|
|
```
|
|
|
|
### Client-side (analysis script)
|
|
|
|
```python
|
|
# piker/tsp/_annotate.py
|
|
async def markup_gaps(...):
|
|
profiler = Profiler(
|
|
msg=f'markup_gaps() for {n} gaps',
|
|
disabled=False,
|
|
ms_threshold=0.0,
|
|
)
|
|
|
|
await actl.redraw()
|
|
profiler('initial redraw')
|
|
|
|
specs = build_specs(gaps)
|
|
profiler('built annotation specs')
|
|
|
|
# IPC round-trip!
|
|
result = await actl.add_batch(specs)
|
|
profiler('batch IPC call complete')
|
|
|
|
await actl.redraw()
|
|
profiler('final redraw')
|
|
```
|
|
|
|
## Common Use Cases
|
|
|
|
### IPC Request/Response Timing
|
|
|
|
```python
|
|
# Client side
|
|
profiler = Profiler(msg='Remote request')
|
|
result = await remote_call()
|
|
profiler('got response')
|
|
|
|
# Server side (in handler)
|
|
profiler = Profiler(msg='Handle request')
|
|
process_request()
|
|
profiler('request processed')
|
|
```
|
|
|
|
### Batch Operation Optimization
|
|
|
|
```python
|
|
profiler = Profiler(msg='Batch processing')
|
|
|
|
items = collect_all()
|
|
profiler(f'collected {len(items)} items')
|
|
|
|
results = numpy_batch_op(items)
|
|
profiler('numpy op complete')
|
|
|
|
output = {
|
|
k: v for k, v in zip(keys, results)
|
|
}
|
|
profiler('dict built')
|
|
```
|
|
|
|
### Startup/Initialization Timing
|
|
|
|
```python
|
|
async def __aenter__(self):
|
|
profiler = Profiler(msg='Service startup')
|
|
|
|
await connect_to_broker()
|
|
profiler('broker connected')
|
|
|
|
await load_config()
|
|
profiler('config loaded')
|
|
|
|
await start_feeds()
|
|
profiler('feeds started')
|
|
|
|
return self
|
|
```
|
|
|
|
## Debugging Performance Regressions
|
|
|
|
When profiler shows unexpected slowness:
|
|
|
|
### 1. Add finer-grained checkpoints
|
|
|
|
```python
|
|
# was:
|
|
result = big_function()
|
|
profiler('big_function done')
|
|
|
|
# now:
|
|
profiler = Profiler(
|
|
msg='big_function internals',
|
|
)
|
|
step1 = part_a()
|
|
profiler('part_a')
|
|
step2 = part_b()
|
|
profiler('part_b')
|
|
step3 = part_c()
|
|
profiler('part_c')
|
|
```
|
|
|
|
### 2. Check for hidden iterations
|
|
|
|
```python
|
|
# looks simple but might be slow!
|
|
result = array[array['time'] == timestamp]
|
|
profiler('array lookup')
|
|
|
|
# reveals O(n) scan per call
|
|
for ts in timestamps: # outer loop
|
|
row = array[array['time'] == ts] # O(n)!
|
|
```
|
|
|
|
### 3. Isolate IPC from computation
|
|
|
|
```python
|
|
# was: can't tell where time is spent
|
|
result = await remote_call(data)
|
|
profiler('remote call done')
|
|
|
|
# now: separate phases
|
|
payload = prepare_payload(data)
|
|
profiler('payload prepared')
|
|
|
|
result = await remote_call(payload)
|
|
profiler('IPC complete')
|
|
|
|
parsed = parse_result(result)
|
|
profiler('result parsed')
|
|
```
|