feat: implement line-level profiling agent with ASM instrumentation #1543
feat: implement line-level profiling agent with ASM instrumentation #1543HeshamHM28 merged 22 commits intoomni-javafrom
Conversation
- Rename test class to TestLineProfilerInstrumentation for clarity. - Add tests for instrumenting Java classes with and without package declarations. - Enhance instrumentation tests to verify that source files remain unmodified. - Implement checks for generated configuration files, ensuring correct content and structure. - Introduce tests for deeply nested packages and verify line contents extraction. - Add end-to-end tests for spin-timer profiling, validating timing accuracy and hit counts.
Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
| */ | ||
| public static int register(String sourceFile, String className, String methodName, int lineNumber) { | ||
| // Pack className hash + lineNumber into a 64-bit key for fast lookup | ||
| long key = ((long) className.hashCode() << 32) | (lineNumber & 0xFFFFFFFFL); |
There was a problem hiding this comment.
Bug (High): The registry key ((long) className.hashCode() << 32) | (lineNumber & 0xFFFFFFFFL) is vulnerable to hash collisions. If two different class names produce the same hashCode() (a well-known occurrence in Java, e.g. "Aa" vs "BB") and share a line number, the second class silently gets the first class's ID, corrupting profiling data.
Consider using the full class name as part of the key (e.g., a composite className + ":" + lineNumber string key) instead of packing a lossy hash into 64 bits.
codeflash-java-runtime/src/main/java/com/codeflash/profiler/ProfilerData.java
Show resolved
Hide resolved
| def test_find_agent_jar(self): | ||
| jar = find_agent_jar() | ||
| # Should find it in either resources or dev build | ||
| assert jar is not None |
There was a problem hiding this comment.
✅ Fixed in latest commit
PR Review SummaryPrek ChecksStatus: Passing after auto-fixes applied in commits
Mypy Type Checks6 of 11 errors fixed — added type annotations for generic types ( 3 remaining errors (require logic changes, not safe to auto-fix):
Code ReviewPreviously reported issues — now resolved (3/4):
New issues found (2):
Test CoverageOverall: Coverage for changed files improved from 51% → 58% (+7pp), with 851 new passing tests from the Java test suite. New Files (below 75% threshold flagged)
Modified Files with Coverage Regression
Last updated: 2026-02-21T00:49:00Z |
Co-authored-by: claude[bot] <209825114+claude[bot]@users.noreply.github.com>
| with contextlib.suppress(ImportError): | ||
| from codeflash.languages.java import support as _ # noqa: F401 |
There was a problem hiding this comment.
Bug (Medium): Duplicate import of codeflash.languages.java.support — this is likely a merge artifact. The @register_language decorator will be triggered twice, causing a "Language 'java' already registered" warning and unnecessary re-registration. The second import block (lines 61-62) should be removed.
| with contextlib.suppress(ImportError): | |
| from codeflash.languages.java import support as _ # noqa: F401 |
|
|
||
| Adds profiling instrumentation to track line-level execution for the | ||
| specified functions. | ||
| def generate_agent_config( |
There was a problem hiding this comment.
Bug (Medium): Neither agent_jar nor config_path are quoted. If either path contains spaces (e.g., /home/John Doe/...), the JVM will fail to parse the -javaagent argument. Consider quoting the paths or documenting this limitation.
The optimization achieves a **383% speedup** (from 4.41ms to 912μs) by removing unnecessary overhead that was consuming 99% of the original runtime. **Key Changes:** 1. **Removed unused `contextlib` import** - The import statement alone took ~386ns per call 2. **Eliminated four empty `contextlib.suppress()` blocks** - These consumed ~527ms total across all calls in profiling: - Each `with contextlib.suppress(ImportError):` block added ~1.6ms of overhead - The actual import statements inside were commented out/missing, making these blocks pure overhead - Line profiler shows 92.6% of time was spent in the first suppress block alone **Why This Works:** The original code imported `contextlib` and created four context managers that did absolutely nothing - the import statements they were meant to protect were already removed or commented out. Each `contextlib.suppress()` call creates a context manager object and executes `__enter__` and `__exit__` methods, which is expensive when done repeatedly for no purpose. **Performance Impact by Test Pattern:** - **Hot path calls** (flag already True): ~6% overhead change (280ns → 310ns) - negligible - **Cold path calls** (flag False, first-time registration): **1300-1800% faster** (5-6μs → 350-430ns) - **Repeated registration loops**: Dramatic speedup in tests like `test_large_scale_reinitialize_each_iteration` (2.97ms → 156μs per iteration) The optimization is especially beneficial when `_ensure_languages_registered()` is called frequently with the flag reset, as the function now does minimal work - just checking a boolean and setting it to True. For already-registered cases (the common path after first call), the impact is minimal since the early return short-circuits most logic anyway.
⚡️ Codeflash found optimizations for this PR📄 383% (3.83x) speedup for
|
This optimization achieves a **17% runtime improvement** (327ms → 277ms) by fundamentally restructuring the type detection logic in the hot path.
## Key Optimization: Early-Exit Type Detection
The original `_column_type()` function used `reduce()` to process every element in a column, calling `_type()` and `_more_generic()` repeatedly. The optimized version implements **early-exit logic** that stops processing as soon as a string type is detected:
```python
# Original: processes all elements regardless
types = [_type(s, has_invisible, numparse) for s in strings]
return reduce(_more_generic, types, bool)
# Optimized: exits early when string type found
for s in strings:
# ... type checking ...
if detected_string:
return str # immediate return - no more processing needed
```
## Why This Works
1. **String is the most generic type**: In Python's type hierarchy for tabular data, string can represent anything. Once we know a column contains strings, we don't need to check remaining values.
2. **Reduces function call overhead**: The original implementation called `_type()` for every element, plus `_more_generic()` for N-1 reductions. The optimized version eliminates these function calls by inlining the type checking logic.
3. **Profiler evidence**: The line `coltypes = [_column_type(col, numparse=np) for col, np in zip(cols, numparses)]` drops from **53% of runtime** (523ms) to **48.2%** (434ms) - an 89ms improvement that accounts for most of the overall speedup.
## Performance by Test Case
The optimization excels on tests with **mixed-type columns** or **large datasets**:
- `test_large_scale_many_rows_and_sorting_stability`: 20% faster (34.8ms → 29.0ms) - 1000 rows benefit from early exits
- `test_large_scale_many_lines_per_function`: 19% faster (38.0ms → 31.9ms) - columns with strings exit early
- `test_large_scale_complex_timings`: 18.1% faster (203ms → 172ms) - 5000 data points across 50 functions
For smaller datasets, the improvement is more modest (5-12%) but still measurable.
## Implementation Details
The optimized `_column_type()` also:
- Passes `has_invisible` parameter directly instead of via `_type()` calls
- Uses in-place type checking rather than intermediate list construction
- Maintains the same type priority (bool → int → float → str) while enabling early termination
This optimization is particularly valuable since `tabulate()` is called repeatedly when formatting profiling output, making the cumulative savings significant for typical workloads.
⚡️ Codeflash found optimizations for this PR📄 18% (0.18x) speedup for
|
…2026-02-21T01.53.56 ⚡️ Speed up function `_ensure_languages_registered` by 383% in PR #1543 (`fix/java/line-profiler`)
|
This PR is now faster! 🚀 @claude[bot] accepted my optimizations from: |
…2026-02-21T01.59.07 ⚡️ Speed up function `show_text_non_python` by 18% in PR #1543 (`fix/java/line-profiler`)
|
This PR is now faster! 🚀 @claude[bot] accepted my optimizations from: |
mashraf-222
left a comment
mashraf-222
left a comment
There was a problem hiding this comment.
Review: Line-Level Profiling Agent with ASM Instrumentation
Testing Performed
All existing tests pass (76/76):
- 21 unit tests (config generation, class name resolution, JAR location, warmup, boundary conditions, result parsing)
- 11 integration tests (config via JavaSupport, multi-method, nested packages, line contents)
- 44 instrumentation tests (behavior/performance modes, timing markers, edge cases)
Deep spin-test verification (6 additional tests, all passing):
| Test | What it validates | Result |
|---|---|---|
| Per-line timing proportionality | 100ms+50ms spin → ~150ms total | 150.1ms total, while-loop 100% of time |
| Raw JSON format | All fields present, correct types, key consistency | All correct, loop hits=1000 exact |
| Multi-method profiling | Two methods (80ms + 40ms) profiled independently | 80.1ms + 40.0ms, ratio 2.00x |
| Self-time attribution | inner(60ms) called from outer(30ms) — outer excludes callee | inner=60.1ms, outer=30.1ms |
| parse_results grouping | Method grouping, sorted lines, str_out formatting | Correctly grouped, tabulate output well-formatted |
| Three-line timing ratios | 30+60+90ms sequential spins, hit counts | 180.1ms total, hits=3 exact |
Key Observations
Timing accuracy is excellent — measured values consistently within 1% of expected spin durations across all tests.
Self-time attribution works correctly — the enterMethod/exitMethod call stack properly excludes callee time from caller lines. When outer(30ms) calls inner(60ms), outer's self-time reports ~30ms (not ~90ms).
Hit counts are exact — a loop running 1000 iterations reports exactly 1000 hits. A method called 3 times reports exactly 3 hits on its entry line.
Zero-allocation hot path — ThreadLocal primitive arrays with no boxing keeps profiling overhead minimal.
Output format compatibility — JSON output matches the expected format, parse_results() correctly groups by method using config ranges, and format_line_profile_results() produces clean tabulate pipe-formatted output.
Note: The .m2 cached JAR needs rebuilding (mvn clean package -DskipTests + mvn install) since this PR adds Premain-Class to the manifest. The bundled JAR in resources/ is included in the diff so CI should be fine.
LGTM — the profiler produces accurate, well-structured output and the Python integration layer correctly parses and formats it.
misrasaurabh1
left a comment
misrasaurabh1
left a comment
There was a problem hiding this comment.
approving to keep things moving. we should deeply understand its behavior in reality and see if it is accurate
…flash into fix/java/line-profiler
Runtime improvement: the optimized version runs ~25% faster (2.06 ms -> 1.64 ms), with larger wins on functions with many instrumentable lines.
What changed
- Precompute file_path.as_posix() once per function: file_posix = file_path.as_posix() and reuse it for content_key and the profiled f-string instead of calling file_path.as_posix() repeatedly inside the loop.
- Combined multiple startswith checks into a single startswith(("//", "/*", "*")) call to replace three separate str.startswith() calls.
Why this speeds things up
- Attribute lookups and small method calls are relatively expensive in Python. In the original code file_path.as_posix() was called twice for every instrumented line (once for content_key and once inside the profiled f-string). Moving that result into a local variable removes those repeated method calls and attribute lookups and replaces them with a fast local variable load.
- Multiple str.startswith() calls were replaced by one startswith(tuple) call, cutting the number of Python-level function calls and condition checks for candidate comment lines.
- These savings multiply with the number of lines inside a function. The loop is the hot path: each instrumented statement previously did several extra method calls and string operations; removing them reduces per-line overhead and thus the total runtime.
Observed evidence
- Line-profiling shows heavy time spent on the two expressions that used file_path.as_posix() repeatedly; those costs drop in the optimized profile.
- The annotated tests show the biggest improvements on the large-scale test (many lines), which matches the expectation that per-line micro-optimizations are most beneficial when the loop has many iterations.
Behavioral impact and trade-offs
- No functional change: the instrumented output and semantics are unchanged.
- A tiny upfront cost (computing file_posix once) is paid even if no lines are instrumented, but that's negligible and worth the per-line savings.
- The exception path (logger.warning) shows a larger percent of the shorter total time in the optimized profile — this is not a regression in practice, just a profiling artifact because the overall runtime decreased; exception handling remains unchanged.
When this matters most
- Hot paths that instrument long functions or many functions (the large-scale test) gain the most.
- Small functions still benefit (the overall runtime measured improved), but the relative improvement is smaller because fixed costs (parse, etc.) dominate.
Summary
Precomputing file_posix and reducing redundant startswith/attribute calls cut down repeated Python-level work inside the main loop. That directly lowers per-line overhead and yields the measured ~25% runtime improvement, especially on workloads with many instrumentable lines.
⚡️ Codeflash found optimizations for this PR📄 26% (0.26x) speedup for
|
…2026-02-25T06.07.49 ⚡️ Speed up method `JavaLineProfiler.instrument_function` by 26% in PR #1543 (`fix/java/line-profiler`)
|
This PR is now faster! 🚀 @HeshamHM28 accepted my optimizations from: |
4 participants
No description provided.