mkl-profile-performance ยท diff
git:20261006.0761fa6 to git:20261016.a313256
78 added, 80 removed. Audit A to A.
---
name: "mkl-profile-performance"
description: "Analyze cProfile or py-spy tables to optimize real bottlenecks without code guessing."
---
- # Interpret profiler output and optimize hot paths
-
- Do not guess performance bottlenecks by reading code. Human intuition about execution time is notoriously unreliable in dynamic languages like Python. Never rewrite algorithms, add complex caches, or micro-optimize functions without empirical profiler evidence establishing that the target function is a dominant contributor to overall runtime.
-
- ## Capture empirical profiler data
-
- Establish a reproducible, deterministic workload that exercises the suspected performance regression or slow operation. Capture profile data using Python's built-in `cProfile` or sampling profilers (`py-spy`, `scalene`).
-
- To capture the top CPU consumers sorted by internal function time:
-
- ```bash
- python3 -m cProfile -s tottime script.py | head -n 25
- ```
-
- To capture functions by cumulative time (useful for locating high-level subsystems):
-
- ```bash
- python3 -m cProfile -s cumtime script.py | head -n 25
- ```
-
- Record the complete environment: Python version, OS, CPU architecture, library versions, dataset size, and iteration count.
-
- ## Interpret the profiler table columns
-
- A standard `cProfile` output presents five critical numeric columns:
-
- 1. `ncalls`: The number of times the function was called. If two numbers appear (e.g. `1000/10`), the function is recursive; the first is total calls, the second is primitive calls.
- 2. `tottime`: Total time spent in the given function's own body, excluding all time spent in calls to subfunctions. **This is the primary indicator of CPU bottlenecks.**
- 3. `percall` (first): Average time spent per call inside the function body (`tottime / ncalls`).
- 4. `cumtime`: Cumulative time spent in this function and all called subfunctions. Top-level runners (such as `main` or `run_pipeline`) will naturally have large `cumtime`.
- 5. `percall` (second): Average cumulative time per call (`cumtime / ncalls`).
- 6. `filename:lineno(function)`: The exact code site. Distinguish application code from third-party libraries and Python built-ins.
+ <skill name="mkl-profile-performance">
+ <description>Analyze cProfile or py-spy tables to optimize real bottlenecks without code guessing.</description>
+ <context>
+ Do not guess performance bottlenecks by reading code. Human intuition about execution time is notoriously unreliable in dynamic languages like Python. Never rewrite algorithms, add complex caches, or micro-optimize functions without empirical profiler evidence establishing that the target function is a dominant contributor to overall runtime.
+ </context>
+ <section name="capture-empirical-profiler-data">
+ Establish a reproducible, deterministic workload that exercises the suspected performance regression or slow operation. Capture profile data using Python's built-in `cProfile` or sampling profilers (`py-spy`, `scalene`).
- ### Distinguish hot bodies from orchestrators
+ To capture the top CPU consumers sorted by internal function time:
- - **High `tottime`, moderate/low `cumtime`**: The function itself executes slow Python bytecode (e.g., tight loops, string concatenations, quadratic lookups). This is an immediate optimization candidate.
- - **Low `tottime`, high `cumtime`**: The function is merely an orchestrator or wrapper delegating to subroutines. Do not optimize this function body; drill down into its subcalls to locate where the cumulative time is actually consumed.
- - **High `ncalls` with tiny `percall`**: Function overhead multiplied across millions of iterations. Common causes include unmemoized helper calculations, repeated regex compilation, redundant object instantiation, or repeated attribute lookups inside nested loops.
+ ```bash
+ python3 -m cProfile -s tottime script.py | head -n 25
+ ```
- ## Focus strictly on the top-3 bottlenecks
+ To capture functions by cumulative time (useful for locating high-level subsystems):
- Follow Amdahl's Law: optimizing a function that accounts for 2% of total runtime can yield at most a 2% overall improvement even if optimized to zero seconds.
+ ```bash
+ python3 -m cProfile -s cumtime script.py | head -n 25
+ ```
- 1. Rank all application functions by `tottime`.
- 2. Select only the top 1 to 3 functions that account for the majority of execution time.
- 3. Ignore functions below the top tier. Reject PRs and changes that add caching, cythonization, or algorithmic complexity to non-bottleneck functions.
+ Record the complete environment: Python version, OS, CPU architecture, library versions, dataset size, and iteration count.
+ </section>
+ <section name="interpret-the-profiler-table-columns">
+ A standard `cProfile` output presents five critical numeric columns:
- ### Select targeted remedies
+ 1. `ncalls`: The number of times the function was called. If two numbers appear (e.g. `1000/10`), the function is recursive; the first is total calls, the second is primitive calls.
+ 2. `tottime`: Total time spent in the given function's own body, excluding all time spent in calls to subfunctions. **This is the primary indicator of CPU bottlenecks.**
+ 3. `percall` (first): Average time spent per call inside the function body (`tottime / ncalls`).
+ 4. `cumtime`: Cumulative time spent in this function and all called subfunctions. Top-level runners (such as `main` or `run_pipeline`) will naturally have large `cumtime`.
+ 5. `percall` (second): Average cumulative time per call (`cumtime / ncalls`).
+ 6. `filename:lineno(function)`: The exact code site. Distinguish application code from third-party libraries and Python built-ins.
- Match the diagnosed symptom with the appropriate optimization:
+ ### Distinguish hot bodies from orchestrators
- - **Repeated idempotent calculation with high `ncalls`**: Apply `functools.lru_cache` or precompute a lookup table outside the loop.
- - **Repeated membership tests in lists (`item in sequence`)**: Convert lists to `set` or `dict` to reduce lookup from $O(N)$ to $O(1)$.
- - **Repeated string building (`s += chunk`)**: Replace with list collection and `"".join(chunks)`.
- - **Heavy element-wise math in nested Python loops**: Replace with vectorized NumPy, PyTorch, or Polars operations to move computation into compiled C/CUDA kernels.
- - **Repeated regex compilation inside loops**: Hoist pattern compilation to module level via `re.compile()`.
- - **JSON serialization/deserialization hot paths**: Switch to faster native parsers (`orjson`) or defer serialization until transmission.
+ - **High `tottime`, moderate/low `cumtime`**: The function itself executes slow Python bytecode (e.g., tight loops, string concatenations, quadratic lookups). This is an immediate optimization candidate.
+ - **Low `tottime`, high `cumtime`**: The function is merely an orchestrator or wrapper delegating to subroutines. Do not optimize this function body; drill down into its subcalls to locate where the cumulative time is actually consumed.
+ - **High `ncalls` with tiny `percall`**: Function overhead multiplied across millions of iterations. Common causes include unmemoized helper calculations, repeated regex compilation, redundant object instantiation, or repeated attribute lookups inside nested loops.
+ </section>
+ <section name="focus-strictly-on-the-top-3-bottlenecks">
+ Follow Amdahl's Law: optimizing a function that accounts for 2% of total runtime can yield at most a 2% overall improvement even if optimized to zero seconds.
- ## Worked Example: Hot path diagnosis and verification
+ 1. Rank all application functions by `tottime`.
+ 2. Select only the top 1 to 3 functions that account for the majority of execution time.
+ 3. Ignore functions below the top tier. Reject PRs and changes that add caching, cythonization, or algorithmic complexity to non-bottleneck functions.
- ### Baseline Profiler Output
+ ### Select targeted remedies
- ```text
- ncalls tottime percall cumtime percall filename:lineno(function)
- 1 0.002 0.002 4.821 4.821 pipeline.py:1(run)
- 1000000 3.210 0.000 3.210 0.000 processor.py:42(is_valid_token)
- 1000000 1.120 0.000 1.120 0.000 {method 'match' of 're.Pattern'}
- 5000 0.410 0.000 0.480 0.000 processor.py:88(lookup_metadata)
- 1 0.079 0.079 4.821 4.821 main.py:1(<module>)
- ```
+ Match the diagnosed symptom with the appropriate optimization:
- **Diagnosis:**
- `is_valid_token` consumes 3.21s of 4.82s (66.6% of runtime) with 1,000,000 invocations. Inspecting `processor.py:42` reveals an internal check: `token in self.blacklist` where `self.blacklist` was initialized as a `list` containing 500 items. Searching a 500-element list $10^6$ times performs $5 \times 10^8$ equality checks.
+ - **Repeated idempotent calculation with high `ncalls`**: Apply `functools.lru_cache` or precompute a lookup table outside the loop.
+ - **Repeated membership tests in lists (`item in sequence`)**: Convert lists to `set` or `dict` to reduce lookup from $O(N)$ to $O(1)$.
+ - **Repeated string building (`s += chunk`)**: Replace with list collection and `"".join(chunks)`.
+ - **Heavy element-wise math in nested Python loops**: Replace with vectorized NumPy, PyTorch, or Polars operations to move computation into compiled C/CUDA kernels.
+ - **Repeated regex compilation inside loops**: Hoist pattern compilation to module level via `re.compile()`.
+ - **JSON serialization/deserialization hot paths**: Switch to faster native parsers (`orjson`) or defer serialization until transmission.
+ </section>
+ <example type="authored">
+ ### Baseline Profiler Output
- **Remedy:**
- Convert `self.blacklist` from `list` to `set` at class initialization.
+ ```text
+ ncalls tottime percall cumtime percall filename:lineno(function)
+ 1 0.002 0.002 4.821 4.821 pipeline.py:1(run)
+ 1000000 3.210 0.000 3.210 0.000 processor.py:42(is_valid_token)
+ 1000000 1.120 0.000 1.120 0.000 {method 'match' of 're.Pattern'}
+ 5000 0.410 0.000 0.480 0.000 processor.py:88(lookup_metadata)
+ 1 0.079 0.079 4.821 4.821 main.py:1(<module>)
+ ```
- ### Verified Profiler Output
+ **Diagnosis:**
+ `is_valid_token` consumes 3.21s of 4.82s (66.6% of runtime) with 1,000,000 invocations. Inspecting `processor.py:42` reveals an internal check: `token in self.blacklist` where `self.blacklist` was initialized as a `list` containing 500 items. Searching a 500-element list $10^6$ times performs $5 \times 10^8$ equality checks.
- ```text
- ncalls tottime percall cumtime percall filename:lineno(function)
- 1 0.002 0.002 1.682 1.682 pipeline.py:1(run)
- 1000000 1.115 0.000 1.115 0.000 {method 'match' of 're.Pattern'}
- 5000 0.408 0.000 0.478 0.000 processor.py:88(lookup_metadata)
- 1000000 0.082 0.000 0.082 0.000 processor.py:42(is_valid_token)
- 1 0.075 0.075 1.682 1.682 main.py:1(<module>)
- ```
+ **Remedy:**
+ Convert `self.blacklist` from `list` to `set` at class initialization.
- **Outcome:**
- `is_valid_token` dropped from 3.210s to 0.082s (39x function speedup). Overall execution dropped from 4.821s to 1.682s (2.86x end-to-end speedup).
+ ### Verified Profiler Output
- ## Verification and Pull Request checklist
+ ```text
+ ncalls tottime percall cumtime percall filename:lineno(function)
+ 1 0.002 0.002 1.682 1.682 pipeline.py:1(run)
+ 1000000 1.115 0.000 1.115 0.000 {method 'match' of 're.Pattern'}
+ 5000 0.408 0.000 0.478 0.000 processor.py:88(lookup_metadata)
+ 1000000 0.082 0.000 0.082 0.000 processor.py:42(is_valid_token)
+ 1 0.075 0.075 1.682 1.682 main.py:1(<module>)
+ ```
- Before committing performance improvements:
- 1. Re-run the profiler command under the exact same dataset and hardware conditions.
- 2. Confirm that total elapsed time and target function `tottime` decreased measurably.
- 3. Run the full unit and regression test suite to ensure functional correctness was not compromised.
- 4. Include both before and after profiler summaries in the pull request description.
+ **Outcome:**
+ `is_valid_token` dropped from 3.210s to 0.082s (39x function speedup). Overall execution dropped from 4.821s to 1.682s (2.86x end-to-end speedup).
+ </example>
+ <verification name="verification-and-pull-request-checklist">
+ Before committing performance improvements:
+ 1. Re-run the profiler command under the exact same dataset and hardware conditions.
+ 2. Confirm that total elapsed time and target function `tottime` decreased measurably.
+ 3. Run the full unit and regression test suite to ensure functional correctness was not compromised.
+ 4. Include both before and after profiler summaries in the pull request description.
+ </verification>
+ </skill>