New timing logger, for use with the timing viz tool#870
New timing logger, for use with the timing viz tool#870
Conversation
WalkthroughAdds a timing utility and tests, instruments adapter and tool execution with timing wrappers, resets test Config between runs, and enables timing in the development server via an environment variable on import. Changes
Estimated code review effort🎯 3 (Moderate) | ⏱️ ~25 minutes
Suggested reviewers
Poem
Pre-merge checks and finishing touches❌ Failed checks (1 warning)
✅ Passed checks (2 passed)
✨ Finishing touches
🧪 Generate unit tests (beta)
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
📊 Coverage ReportOverall Coverage: 92% Diff: origin/main...HEAD
Summary
|
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 1
🧹 Nitpick comments (1)
libs/core/kiln_ai/adapters/model_adapters/litellm_adapter.py (1)
645-648: LGTM!The timing instrumentation is correctly placed around the tool execution, measuring only the
tool.run()call without including the name lookup overhead.Minor: The f-string on line 647 is redundant since
tool_nameis already a string. You could simplify to:- with time_operation("tool_run", f"{tool_name}"): + with time_operation("tool_run", tool_name):
📜 Review details
Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (5)
app/desktop/dev_server.py(1 hunks)libs/core/kiln_ai/adapters/model_adapters/base_adapter.py(2 hunks)libs/core/kiln_ai/adapters/model_adapters/litellm_adapter.py(2 hunks)libs/core/kiln_ai/utils/test_timing_logger.py(1 hunks)libs/core/kiln_ai/utils/timing_logger.py(1 hunks)
🧰 Additional context used
📓 Path-based instructions (5)
libs/core/**/*.py
📄 CodeRabbit inference engine (.cursor/rules/project.mdc)
Use Python 3.10+ for the core library (libs/core) and Python 3.13 for the desktop app
Use python 3.10+ for the core library (libs/core) and python 3.13 for the desktop app
Files:
libs/core/kiln_ai/adapters/model_adapters/litellm_adapter.pylibs/core/kiln_ai/adapters/model_adapters/base_adapter.pylibs/core/kiln_ai/utils/test_timing_logger.pylibs/core/kiln_ai/utils/timing_logger.py
**/*.py
📄 CodeRabbit inference engine (.cursor/rules/project.mdc)
**/*.py: Use asyncio for asynchronous operations in Python
Use Pydantic v2 (not v1) for data validation
Files:
libs/core/kiln_ai/adapters/model_adapters/litellm_adapter.pylibs/core/kiln_ai/adapters/model_adapters/base_adapter.pylibs/core/kiln_ai/utils/test_timing_logger.pylibs/core/kiln_ai/utils/timing_logger.pyapp/desktop/dev_server.py
libs/**/*.py
📄 CodeRabbit inference engine (AGENTS.md)
Use Pydantic v2 (not v1) for data validation and serialization
Files:
libs/core/kiln_ai/adapters/model_adapters/litellm_adapter.pylibs/core/kiln_ai/adapters/model_adapters/base_adapter.pylibs/core/kiln_ai/utils/test_timing_logger.pylibs/core/kiln_ai/utils/timing_logger.py
**/*test*.py
📄 CodeRabbit inference engine (.cursor/rules/project.mdc)
Use pytest for testing Python code
Use pytest for testing in python projects
Files:
libs/core/kiln_ai/utils/test_timing_logger.py
app/desktop/**/*.py
📄 CodeRabbit inference engine (AGENTS.md)
Use python 3.13 for the desktop app
Files:
app/desktop/dev_server.py
🧠 Learnings (1)
📓 Common learnings
Learnt from: scosman
Repo: Kiln-AI/Kiln PR: 733
File: app/web_ui/src/lib/stores/local_storage_store.ts:9-11
Timestamp: 2025-10-21T00:06:57.115Z
Learning: When scosman is refactoring code by moving it to a new location, he prefers to keep the moved code unchanged and not mix in functional improvements or bug fixes during the refactor.
🧬 Code graph analysis (3)
libs/core/kiln_ai/adapters/model_adapters/litellm_adapter.py (6)
libs/core/kiln_ai/utils/timing_logger.py (1)
time_operation(52-69)libs/core/kiln_ai/tools/base_tool.py (4)
name(62-64)name(94-95)run(45-49)run(112-116)libs/core/kiln_ai/tools/kiln_task_tool.py (2)
name(47-48)run(64-108)libs/core/kiln_ai/tools/mcp_server_tool.py (2)
name(25-26)run(44-65)libs/core/kiln_ai/adapters/model_adapters/test_litellm_adapter_tools.py (4)
name(769-770)name(810-811)run(783-788)run(824-832)libs/core/kiln_ai/tools/test_base_tools.py (1)
run(18-19)
libs/core/kiln_ai/adapters/model_adapters/base_adapter.py (3)
libs/core/kiln_ai/utils/timing_logger.py (1)
time_operation(52-69)libs/core/kiln_ai/datamodel/task_run.py (1)
TaskRun(76-260)libs/core/kiln_ai/adapters/run_output.py (1)
RunOutput(10-14)
libs/core/kiln_ai/utils/test_timing_logger.py (1)
app/desktop/studio_server/test_server.py (1)
side_effect(180-183)
🪛 GitHub Actions: Build and Test
libs/core/kiln_ai/utils/test_timing_logger.py
[error] 1-1: TestTimingLogger.test_timing_calculation failed with RuntimeError: generator raised StopIteration. Likely due to mock time.side_effect exhausting its values during timing calculation in the timing_logger module.
libs/core/kiln_ai/utils/timing_logger.py
[error] 46-46: TestTimingLogger.test_timing_calculation failed with StopIteration: mocked time.time() exhausted its side_effect during exit while logging a timing calculation.
⏰ Context from checks skipped due to timeout of 90000ms. You can increase the timeout in your CodeRabbit configuration to a maximum of 15 minutes (900000ms). (7)
- GitHub Check: Cursor Bugbot
- GitHub Check: Generate Coverage Report
- GitHub Check: Build Desktop Apps (ubuntu-22.04-arm)
- GitHub Check: Build Desktop Apps (macos-15-intel)
- GitHub Check: Build Desktop Apps (ubuntu-22.04)
- GitHub Check: Build Desktop Apps (macos-latest)
- GitHub Check: Build Desktop Apps (windows-latest)
🔇 Additional comments (8)
libs/core/kiln_ai/adapters/model_adapters/litellm_adapter.py (1)
49-49: LGTM!The import is correctly placed and necessary for the timing instrumentation added below.
app/desktop/dev_server.py (1)
18-18: LGTM!Correctly enables timing output for the development server. The placement at module level ensures timing is active throughout the dev server's execution, consistent with the other debug flag on line 17.
libs/core/kiln_ai/utils/test_timing_logger.py (1)
1-44: LGTM!The test coverage is comprehensive and well-structured:
- Basic functionality and log level verification
- Environment-driven enable/disable behavior
- Timestamp formatting
- Exception handling in timing context
- All three environment states (default, true, false)
The tests properly use
patch.dictto control the environment variable andcaplogto verify logging behavior.Also applies to: 59-124
libs/core/kiln_ai/adapters/model_adapters/base_adapter.py (2)
33-33: LGTM!Import is correctly placed and necessary for the timing instrumentation.
98-113: LGTM! Clean refactoring pattern for instrumentation.The refactoring follows a good pattern:
- Original method now wraps the timing instrumentation
- New
_coremethod contains the actual implementation logic- Original behavior is preserved
- Timing measures the complete task invocation from input to output
This approach keeps the instrumentation separate from the core logic, making it easy to maintain or remove if needed.
Based on learnings, scosman prefers to keep refactored code unchanged when moving it to a new location. This change aligns with that preference—the core logic is moved as-is to the new method, with only timing instrumentation added as a wrapper.
libs/core/kiln_ai/utils/timing_logger.py (3)
14-28: LGTM!The initialization and timestamp methods are straightforward:
- Stores operation metadata for logging
timestamp()uses ISO format for unambiguous timestampsstart_timeis typed as Optional and initialized to None
30-48: LGTM!The context manager implementation is correct:
__enter__records start time__exit__checks environment flag and conditionally logs- Duration calculation is straightforward
- Bracket sanitization prevents issues with log parsing by the visualization tool
- Logs at WARNING level to ensure visibility with default log settings
- Doesn't suppress exceptions (correct behavior)
Note: The timestamp reflects when the operation completed, not when it started. The visualization tool can calculate start time as
completion_time - durationif needed.
51-68: LGTM!The
time_operationcontext manager wrapper provides a clean, functional interface for timing code blocks. The example in the docstring clearly demonstrates usage.
![cursor[bot]](https://avatars.githubusercontent.com/in/1210556?s=60&v=4){kind=small}
There was a problem hiding this comment.
This is the final PR Bugbot will review for you during this billing cycle
Your free Bugbot reviews will reset on January 25
Details
You are on the Bugbot Free tier. On this plan, Bugbot will review limited PRs each billing cycle.
To receive Bugbot reviews on all of your PRs, visit the Cursor dashboard to activate Pro and start your 14-day free trial.
|
|
||
| os.environ["DEBUG_EVENT_LOOP"] = "true" | ||
|
|
||
| os.environ["KILN_SHOW_TIMING"] = "true" |
There was a problem hiding this comment.
Bug: Environment variable set after module import time initialization
The KILN_SHOW_TIMING environment variable is set on line 18, but the timing_logger module is already imported transitively through make_app on line 8. Since _show_timing in timing_logger.py is evaluated at module load time using os.getenv(), it will always be False when running the dev server. The environment variable needs to be set before the import chain that loads timing_logger.
Additional Locations (1)
There was a problem hiding this comment.
Actionable comments posted: 3
🧹 Nitpick comments (1)
libs/core/kiln_ai/utils/timing_logger.py (1)
38-49: Consider using INFO instead of WARNING level for timing logs.Timing information is typically logged at INFO or DEBUG level rather than WARNING. The WARNING level suggests something needs attention or is potentially problematic, which doesn't match the nature of performance timing data. Since timing is opt-in via environment variable, INFO would be more semantically appropriate.
Apply this diff if you agree:
- logger.warning( + logger.info( f"{self.timestamp()} timing_logger [{printable_operation}][{printable_name}][{duration:.2f}s]" )
📜 Review details
Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (2)
libs/core/kiln_ai/utils/test_timing_logger.py(1 hunks)libs/core/kiln_ai/utils/timing_logger.py(1 hunks)
🧰 Additional context used
📓 Path-based instructions (4)
libs/core/**/*.py
📄 CodeRabbit inference engine (.cursor/rules/project.mdc)
Use Python 3.10+ for the core library (libs/core) and Python 3.13 for the desktop app
Use python 3.10+ for the core library (libs/core) and python 3.13 for the desktop app
Files:
libs/core/kiln_ai/utils/timing_logger.pylibs/core/kiln_ai/utils/test_timing_logger.py
**/*.py
📄 CodeRabbit inference engine (.cursor/rules/project.mdc)
**/*.py: Use asyncio for asynchronous operations in Python
Use Pydantic v2 (not v1) for data validation
Files:
libs/core/kiln_ai/utils/timing_logger.pylibs/core/kiln_ai/utils/test_timing_logger.py
libs/**/*.py
📄 CodeRabbit inference engine (AGENTS.md)
Use Pydantic v2 (not v1) for data validation and serialization
Files:
libs/core/kiln_ai/utils/timing_logger.pylibs/core/kiln_ai/utils/test_timing_logger.py
**/*test*.py
📄 CodeRabbit inference engine (.cursor/rules/project.mdc)
Use pytest for testing Python code
Use pytest for testing in python projects
Files:
libs/core/kiln_ai/utils/test_timing_logger.py
🧠 Learnings (1)
📓 Common learnings
Learnt from: scosman
Repo: Kiln-AI/Kiln PR: 733
File: app/web_ui/src/lib/stores/local_storage_store.ts:9-11
Timestamp: 2025-10-21T00:06:57.115Z
Learning: When scosman is refactoring code by moving it to a new location, he prefers to keep the moved code unchanged and not mix in functional improvements or bug fixes during the refactor.
🧬 Code graph analysis (1)
libs/core/kiln_ai/utils/test_timing_logger.py (1)
libs/core/kiln_ai/utils/timing_logger.py (3)
TimingLogger(13-49)time_operation(53-70)timestamp(28-30)
⏰ Context from checks skipped due to timeout of 90000ms. You can increase the timeout in your CodeRabbit configuration to a maximum of 15 minutes (900000ms). (11)
- GitHub Check: Cursor Bugbot
- GitHub Check: Generate Coverage Report
- GitHub Check: Build Desktop Apps (macos-latest)
- GitHub Check: Build Desktop Apps (windows-latest)
- GitHub Check: Build Desktop Apps (ubuntu-22.04)
- GitHub Check: Build Desktop Apps (macos-15-intel)
- GitHub Check: Build Desktop Apps (ubuntu-22.04-arm)
- GitHub Check: Build, Typecheck, and Test Python (3.10)
- GitHub Check: Build, Typecheck, and Test Python (3.11)
- GitHub Check: Build, Typecheck, and Test Python (3.13)
- GitHub Check: Build, Typecheck, and Test Python (3.12)
🔇 Additional comments (7)
libs/core/kiln_ai/utils/timing_logger.py (1)
1-11: LGTM!The imports and module-level configuration are clean. The environment variable is correctly read at import time, and the test fixture properly manages the state for test isolation.
libs/core/kiln_ai/utils/test_timing_logger.py (6)
1-16: LGTM!The imports are appropriate, and the
reset_show_timingfixture properly ensures test isolation by saving and restoring the module-level_show_timingflag.
21-50: LGTM!The basic tests properly verify that timing logs are emitted when enabled, logged at WARNING level, and suppressed when disabled. The slight redundancy between
test_timing_logger_basic_usageandtest_timing_logger_logs_at_warning_levelis acceptable for test clarity.
52-65: LGTM!The timing calculation test is correctly implemented with three mock time values to account for
__enter__,__exit__, and the internal logging timestamp call. The previous issue with mock exhaustion has been properly addressed.
67-74: LGTM!The timestamp format test appropriately verifies ISO format output by checking for the 'T' separator and colons.
77-99: LGTM!The
time_operationcontext manager tests properly verify both basic usage and exception handling. The exception test is particularly valuable as it confirms that timing is logged even when the wrapped code raises an exception.
123-131: LGTM!The test correctly verifies that timing logs are emitted when
_show_timingis set toTrue.
| def test_timing_disabled_by_default(self, caplog): | ||
| """Test that timing is disabled when _show_timing is False.""" | ||
| timing_logger._show_timing = False | ||
| with caplog.at_level(logging.WARNING): | ||
| with TimingLogger("test", "default_test"): | ||
| time.sleep(0.05) | ||
|
|
||
| assert len(caplog.records) == 0 | ||
|
|
||
| def test_timing_disabled_when_false(self, caplog): | ||
| """Test that timing is disabled when _show_timing is False.""" | ||
| timing_logger._show_timing = False | ||
| with caplog.at_level(logging.WARNING): | ||
| with TimingLogger("test", "false_test"): | ||
| time.sleep(0.05) | ||
|
|
||
| assert len(caplog.records) == 0 | ||
|
|
There was a problem hiding this comment.
Remove duplicate test and fix misleading test name.
The tests test_timing_disabled_by_default (lines 105-112) and test_timing_disabled_when_false (lines 114-121) are functionally identical. Both explicitly set _show_timing = False and verify no logs are emitted. Additionally, test_timing_disabled_by_default is misleadingly named—it doesn't test the default behavior but rather explicitly sets the flag to False.
Apply this diff to remove the duplicate and clarify the remaining test:
- def test_timing_disabled_by_default(self, caplog):
- """Test that timing is disabled when _show_timing is False."""
- timing_logger._show_timing = False
- with caplog.at_level(logging.WARNING):
- with TimingLogger("test", "default_test"):
- time.sleep(0.05)
-
- assert len(caplog.records) == 0
-
def test_timing_disabled_when_false(self, caplog):
"""Test that timing is disabled when _show_timing is False."""
timing_logger._show_timing = False🤖 Prompt for AI Agents
In libs/core/kiln_ai/utils/test_timing_logger.py around lines 105 to 122, there
are two identical tests that both set timing_logger._show_timing = False and
assert no logs; remove the duplicate test (either the first or second) and keep
a single test that is accurately named and documented (e.g., rename to
test_timing_disabled_when_false and update the docstring to state it explicitly
sets _show_timing to False), ensuring the remaining test still sets the flag to
False, uses caplog.at_level(logging.WARNING) with TimingLogger, and asserts
len(caplog.records) == 0.
| def __init__(self, operation: str, name: str): | ||
| """ | ||
| Initialize the timing logger. | ||
|
|
||
| Args: | ||
| name: Name/description of the operation being timed | ||
| print_start: Whether to print when the operation starts | ||
| """ | ||
| self.operation = operation | ||
| self.name = name | ||
| self.start_time: Optional[float] = None |
There was a problem hiding this comment.
Remove obsolete parameter from docstring.
The docstring references a print_start parameter that doesn't exist in the signature.
Apply this diff to fix the docstring:
def __init__(self, operation: str, name: str):
"""
Initialize the timing logger.
Args:
- name: Name/description of the operation being timed
- print_start: Whether to print when the operation starts
+ operation: Type/category of the operation being timed
+ name: Name/description of the operation being timed
"""📝 Committable suggestion
‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation. Thoroughly test & benchmark the code to ensure it meets the requirements.
| def __init__(self, operation: str, name: str): | |
| """ | |
| Initialize the timing logger. | |
| Args: | |
| name: Name/description of the operation being timed | |
| print_start: Whether to print when the operation starts | |
| """ | |
| self.operation = operation | |
| self.name = name | |
| self.start_time: Optional[float] = None | |
| def __init__(self, operation: str, name: str): | |
| """ | |
| Initialize the timing logger. | |
| Args: | |
| operation: Type/category of the operation being timed | |
| name: Name/description of the operation being timed | |
| """ | |
| self.operation = operation | |
| self.name = name | |
| self.start_time: Optional[float] = None |
🤖 Prompt for AI Agents
In libs/core/kiln_ai/utils/timing_logger.py around lines 16 to 26, the __init__
docstring references a non-existent print_start parameter; update the docstring
to remove print_start and accurately document the actual parameters (operation
and name) with brief descriptions and types so the Args section matches the
function signature.
| @contextmanager | ||
| def time_operation( | ||
| operation: str, name: str = "unknown" | ||
| ) -> Generator[None, None, None]: | ||
| """ | ||
| Context manager for timing operations. | ||
|
|
||
| Args: | ||
| type: Type/category of the operation being timed | ||
| name: Name/description of the operation being timed | ||
|
|
||
| Example: | ||
| with time_operation("api", "my_task"): | ||
| # Your code here | ||
| time.sleep(1) | ||
| """ | ||
| timing_logger = TimingLogger(operation, name) | ||
| with timing_logger: | ||
| yield |
There was a problem hiding this comment.
Fix parameter name in docstring.
The docstring references a parameter named type, but the actual parameter is operation.
Apply this diff to fix the docstring:
"""
Context manager for timing operations.
Args:
- type: Type/category of the operation being timed
+ operation: Type/category of the operation being timed
name: Name/description of the operation being timed🤖 Prompt for AI Agents
In libs/core/kiln_ai/utils/timing_logger.py around lines 52 to 70, the docstring
incorrectly references the parameter name "type" instead of "operation"; update
the Args section to use "operation" (and adjust its description if needed) so
the parameter names in the docstring match the function signature, ensuring the
example and other doc references remain accurate.
1 participant
1 line to add timing information to dev logs, from there you can copy and paste into new Viz tool: https://github.com/Kiln-AI/experiments/tree/main/timing_visualizer
Note
Introduces a timing logger gated by
KILN_SHOW_TIMING, integrates it into task invocation and tool runs, enables it in the dev server, and adds unit tests.TimingLoggerandtime_operationinlibs/core/kiln_ai/utils/timing_logger.py, controlled byKILN_SHOW_TIMING.BaseAdapter.invoke_returning_run_outputwithtime_operation(refactors core toinvoke_returning_run_output_core).LiteLlmAdapter.process_tool_callswithtime_operation.KILN_SHOW_TIMING="true"inapp/desktop/dev_server.py.libs/core/kiln_ai/utils/test_timing_logger.pycovering logging behavior, timestamping, and exception paths.reset_configfixture inconftest.pyto resetConfigsingleton between tests.Written by Cursor Bugbot for commit dd78b9e. This will update automatically on new commits. Configure here.
Summary by CodeRabbit
New Features
Tests
Chores
✏️ Tip: You can customize this high-level summary in your review settings.