Hot path: debug-only type checks, lazy logging, direct component creation

[andre-merzky]

Depends on #91 (based on feature/nosleep); retargeted to main once #91 is merged.

Summary

After #91 removed the scheduler's sleeps and per-pass scans, task throughput is bound by per-task overhead outside the scheduler. Profiled at 8,192 concurrent workflows (NoopExecutionBackend), about 45% of the time went to typeguard checks on task_callbacks, the rest largely to log formatting, telemetry arguments built with telemetry off, and a @wraps closure built for every task call. With init_default_logger() configured, every DEBUG call also built a full LogRecord, because the logger level was NOTSET and filtering happened only at the handlers.

Changes:

• Debug mode for runtime type checks. task_callbacks is type-checked only when RADICAL_ASYNCFLOW_DEBUG is set to 1/true/yes/on; if that variable is unset, RADICAL_DEBUG decides. Read at import. __init__ stays type-checked (once per engine). The test suite enables debug mode in tests/conftest.py, so CI keeps the checks.
• Logging. Per-task log calls use lazy %s arguments, or an isEnabledFor(DEBUG) guard where an argument list is built. The per-task state line (<uid> is in <state> state) and the per-batch Submitting <n> tasks/blocks line move from INFO to DEBUG.
• init_default_logger sets the logger level to the lowest level of its handlers instead of NOTSET, so records no handler emits are dropped before they are built.
• Telemetry. Call sites in registration, dependency resolution and the run loop build event arguments only when telemetry is enabled.
• Component creation. A decorated call creates its component via _create_component instead of building and calling a @wraps wrapper per call; the async check runs once per decorated function (inspect.iscoroutinefunction).
• Docs. docs/best_practice.md documents debug mode and replaces the RADICAL_LOG_LVL hint, which asyncflow never reads. CHANGELOG lists the INFO→DEBUG moves and the logger level change.

Behaviour changes

• Per-task state and submission messages appear at DEBUG, not INFO.
• init_default_logger with the root logger: records of other libraries below the configured level are dropped unless the library sets a level on its own logger. With logger_name, records at the configured level are now emitted (they were filtered by the root logger's level) and propagate to root handlers.
• Type errors in task_callbacks arguments raise TypeCheckError only in debug mode.
• On Python 3.9, inspect.iscoroutinefunction(AsyncMock()) is False, so decorating an AsyncMock raises "must be async" there (3.10+ unaffected; no test does this).

Performance

Laptop, one pinned core, NoopExecutionBackend unless noted, environment without RADICAL_DEBUG; K = long-running tasks parked in running. Throughput: median of 10 runs; latency: median of 5. Markers compare to #91 head (this PR's base): 🟢 > 5% better, 🔴 > 5% worse, ⚪ within ±5%. Release 0.5.1 for reference.

Throughput on the 01-workflows.py workload (tasks/s), no logging configured:

Workflows, K	0.5.1	#91 head	This PR	This PR, debug mode
1,024, K=0	17,124	20,702	🟢 36,373 (+76%)	🟢 24,410 (+18%)
2,048, K=0	19,224	20,972	🟢 38,070 (+82%)	🟢 25,220 (+20%)
4,096, K=0	18,700	19,901	🟢 35,372 (+78%)	🟢 23,632 (+19%)
8,192, K=0	17,823	18,354	🟢 31,374 (+71%)	🟢 21,740 (+18%)
1,024, K=10k	14,280	17,650	🟢 24,961 (+41%)	🟢 19,452 (+10%)
2,048, K=10k	16,580	18,556	🟢 30,086 (+62%)	🟢 21,618 (+17%)
4,096, K=10k	16,626	17,502	🟢 28,192 (+61%)	🟢 20,324 (+16%)
8,192, K=10k	16,279	16,984	🟢 27,672 (+63%)	🟢 19,886 (+17%)

Throughput with init_default_logger(logging.INFO) (as in the ROSE examples and DT scripts):

Workflows, K	0.5.1	#91 head	This PR	This PR, debug mode
1,024, K=0	8,855	9,674	🟢 36,214 (+274%)	🟢 24,038 (+148%)
2,048, K=0	9,496	9,708	🟢 38,684 (+298%)	🟢 25,234 (+160%)
4,096, K=0	9,311	9,496	🟢 35,757 (+277%)	🟢 23,478 (+147%)
8,192, K=0	9,050	9,140	🟢 31,454 (+244%)	🟢 21,696 (+137%)
1,024, K=10k	8,304	8,894	🟢 25,162 (+183%)	🟢 19,546 (+120%)
2,048, K=10k	8,850	9,076	🟢 29,688 (+227%)	🟢 21,214 (+134%)
4,096, K=10k	8,688	8,826	🟢 28,361 (+221%)	🟢 20,450 (+132%)
8,192, K=10k	8,586	8,702	🟢 27,754 (+219%)	🟢 20,011 (+130%)

Latency, no logging configured (in parentheses: with init_default_logger(logging.INFO)):

Measure	0.5.1	#91 head	This PR	This PR, debug mode
Round-trip, LocalExecutionBackend (ms)	12.01 (12.44)	0.40 (0.62)	🟢 0.33 (🟢 0.32)	🟢 0.36 (🟢 0.37)
50 ms task → dependent, LocalExecutionBackend (s)	1.035 (1.036)	0.052 (0.053)	⚪ 0.052 (⚪ 0.052)	⚪ 0.052 (⚪ 0.053)
Sequential task, K=0 (µs, wall = CPU)	10,878 (11,198)	125 (233)	🟢 79 (🟢 79)	🟢 110 (🟢 108)
Sequential task, K=1,000 (µs)	11,593 (12,022)	137 (256)	🟢 91 (🟢 90)	🟢 122 (🟢 120)
Sequential task, K=10k (µs)	17,295 (17,565)	157 (255)	🟢 126 (🟢 125)	🟢 134 (🟢 136)

Idle CPU is unchanged from #91 head (poll_timeout 0.1 s: 0.0 / 1.2 / 7.3% of one core at K = 0 / 1,000 / 10k).

Tests

• tests/unit/test_debug_mode.py: variable parsing and precedence; task_callbacks raises TypeCheckError in debug mode; logger level follows the lowest handler level.
• tests/unit/test_task_registration_component.py: _create_component registers a function task; a decorated sync function is rejected at call time.
• Unit suite green with debug mode on (py3.10, py3.13: 124 passed, 2 skipped) and off (123 passed, 3 skipped); integration suite green; ruff clean on touched code.

Not in this PR

• The run loop's idle wait still creates two asyncio tasks per wait; replacing that saves about a third of the remaining per-task CPU in sequential workloads (measured on a prototype). Separate follow-up.

🤖 Generated with Claude Code