Skip to content

Commit d061234

Browse files
committed
feat(fitness): add timing instrumentation to fitness checks
Implements timing instrumentation for fitness checks as requested in review feedback. Timing information provides visibility into check execution performance. Changes: - Add time.perf_counter() measurements for individual checks - Log individual check timing in debug output (e.g., '(42.5ms)') - Log total fitness check execution time in final info message - Use 2-decimal precision for millisecond formatting - Add 5 comprehensive tests for timing functionality: * test_logs_individual_check_timing: Verify individual timings logged * test_logs_total_check_timing: Verify total time in summary * test_timing_is_reasonable: Ensure timings are positive and realistic * test_timing_with_multiple_checks: Verify all checks have timing logged * test_timing_format_consistency: Ensure format follows (X.XXms) pattern
1 parent d9ad5d0 commit d061234

2 files changed

Lines changed: 129 additions & 5 deletions

File tree

runpod/serverless/modules/rp_fitness.py

Lines changed: 12 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@
1010

1111
import inspect
1212
import sys
13+
import time
1314
import traceback
1415
from typing import Callable, List
1516

@@ -149,19 +150,20 @@ async def run_fitness_checks() -> None:
149150
3. Log start of fitness check phase
150151
4. For each registered check:
151152
- Auto-detect sync vs async using inspect.iscoroutinefunction()
152-
- Execute check (await if async, call if sync)
153-
- Log success or failure with check name
153+
- Execute check with timing instrumentation (await if async, call if sync)
154+
- Log success or failure with check name and execution time
154155
5. On any exception:
155156
- Log detailed error with check name, exception type, and message
156157
- Log traceback at DEBUG level
157158
- Call sys.exit(1) immediately (fail-fast)
158159
6. On successful completion of all checks:
159-
- Log completion message
160+
- Log completion message with total execution time
160161
161162
Note:
162163
Checks run in registration order (list preserves order).
163164
Sequential execution (not parallel) ensures clear error reporting
164165
and handles checks with dependencies correctly.
166+
Timing uses high-precision perf_counter for accurate measurements.
165167
166168
Raises:
167169
SystemExit: Calls sys.exit(1) if any check fails.
@@ -179,19 +181,23 @@ async def run_fitness_checks() -> None:
179181

180182
log.info(f"Running {len(_fitness_checks)} fitness check(s)...")
181183

184+
total_start_time = time.perf_counter()
185+
182186
for check_func in _fitness_checks:
183187
check_name = check_func.__name__
184188

185189
try:
186190
log.debug(f"Executing fitness check: {check_name}")
191+
check_start_time = time.perf_counter()
187192

188193
# Auto-detect async vs sync using inspect
189194
if inspect.iscoroutinefunction(check_func):
190195
await check_func()
191196
else:
192197
check_func()
193198

194-
log.debug(f"Fitness check passed: {check_name}")
199+
check_elapsed_ms = (time.perf_counter() - check_start_time) * 1000
200+
log.debug(f"Fitness check passed: {check_name} ({check_elapsed_ms:.2f}ms)")
195201

196202
except Exception as exc:
197203
# Log detailed error information
@@ -209,4 +215,5 @@ async def run_fitness_checks() -> None:
209215
log.error("Worker is unhealthy, exiting.")
210216
sys.exit(1)
211217

212-
log.info("All fitness checks passed.")
218+
total_elapsed_ms = (time.perf_counter() - total_start_time) * 1000
219+
log.info(f"All fitness checks passed. ({total_elapsed_ms:.2f}ms)")

tests/test_serverless/test_modules/test_fitness/test_registration.py

Lines changed: 117 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -452,3 +452,120 @@ def check_three():
452452

453453
# Only first check should have run
454454
assert results == ["one"]
455+
456+
457+
# ============================================================================
458+
# Timing Instrumentation Tests
459+
# ============================================================================
460+
461+
class TestFitnessCheckTiming:
462+
"""Tests for fitness check timing instrumentation."""
463+
464+
@pytest.mark.asyncio
465+
@patch("runpod.serverless.modules.rp_fitness.log")
466+
async def test_logs_individual_check_timing(self, mock_log):
467+
"""Test that individual check timings are logged."""
468+
@register_fitness_check
469+
def check():
470+
pass
471+
472+
await run_fitness_checks()
473+
474+
# Verify timing is logged in debug output for the check
475+
debug_calls = [str(call) for call in mock_log.debug.call_args_list]
476+
# Should contain timing info like "(X.XXms)"
477+
assert any("ms)" in call for call in debug_calls)
478+
479+
@pytest.mark.asyncio
480+
@patch("runpod.serverless.modules.rp_fitness.log")
481+
async def test_logs_total_check_timing(self, mock_log):
482+
"""Test that total execution time is logged."""
483+
@register_fitness_check
484+
def check():
485+
pass
486+
487+
await run_fitness_checks()
488+
489+
# Verify total timing is logged in final info message
490+
info_calls = [str(call) for call in mock_log.info.call_args_list]
491+
# Final message should be "All fitness checks passed. (X.XXms)"
492+
assert any(
493+
"All fitness checks passed" in call and "ms)" in call
494+
for call in info_calls
495+
)
496+
497+
@pytest.mark.asyncio
498+
async def test_timing_is_reasonable(self):
499+
"""Test that check timing is reasonable (not negative, < 100ms for no-op)."""
500+
timings = []
501+
502+
@register_fitness_check
503+
def check():
504+
pass
505+
506+
with patch("runpod.serverless.modules.rp_fitness.log") as mock_log:
507+
await run_fitness_checks()
508+
509+
# Extract timing from debug logs
510+
debug_calls = mock_log.debug.call_args_list
511+
for call in debug_calls:
512+
call_str = str(call)
513+
# Look for format like "passed: check_name (X.XXms)"
514+
if "passed:" in call_str and "ms)" in call_str:
515+
# Extract the timing value
516+
import re
517+
match = re.search(r"\((\d+\.\d+)ms\)", call_str)
518+
if match:
519+
timing_ms = float(match.group(1))
520+
timings.append(timing_ms)
521+
522+
# Should have at least one timing
523+
assert len(timings) > 0
524+
# Timings should be positive and reasonable
525+
for timing in timings:
526+
assert timing >= 0
527+
assert timing < 100 # No-op should be < 100ms
528+
529+
@pytest.mark.asyncio
530+
@patch("runpod.serverless.modules.rp_fitness.log")
531+
async def test_timing_with_multiple_checks(self, mock_log):
532+
"""Test that timing is logged for multiple checks."""
533+
@register_fitness_check
534+
def check_one():
535+
pass
536+
537+
@register_fitness_check
538+
def check_two():
539+
pass
540+
541+
await run_fitness_checks()
542+
543+
# Should log timing for both checks
544+
debug_calls = [str(call) for call in mock_log.debug.call_args_list]
545+
timing_logs = [call for call in debug_calls if "ms)" in call]
546+
# Should have at least 2 timing logs (one for each check)
547+
assert len(timing_logs) >= 2
548+
549+
@pytest.mark.asyncio
550+
@patch("runpod.serverless.modules.rp_fitness.log")
551+
async def test_timing_format_consistency(self, mock_log):
552+
"""Test that timing format is consistent (X.XXms)."""
553+
import re
554+
555+
@register_fitness_check
556+
def check():
557+
pass
558+
559+
await run_fitness_checks()
560+
561+
# Check all timing messages follow the format pattern
562+
all_calls = (
563+
[str(call) for call in mock_log.debug.call_args_list]
564+
+ [str(call) for call in mock_log.info.call_args_list]
565+
)
566+
timing_calls = [call for call in all_calls if "ms)" in call]
567+
568+
# All timing entries should match format (X.XXms)
569+
pattern = r"\(\d+\.\d{2}ms\)"
570+
for call in timing_calls:
571+
assert re.search(pattern, call), f"Timing format mismatch in: {call}"

0 commit comments

Comments
 (0)