flight-profiler-trace

Trace the execution time of a specified method invocation, displaying a call tree with timing. Unlike watch which shows individual invocations, trace reveals the full call hierarchy underneath a function — making it ideal for finding which sub-call is the bottleneck.

Prerequisites: Read the flight-profiler-attach skill first for platform requirements, installation, permissions, and connection details.

When to Use

• You want to find which sub-call inside a function is slow
• You need a hierarchical view of function execution with timing at each level
• You want to filter out fast calls and only see slow ones (via -i interval threshold)
• You need to understand the call chain depth of a specific function

Usage

flight_profiler <pid> --cmd "trace module [class] method [options]" --no-color --timeout <seconds>

-n bounds how many invocations are captured; --timeout bounds how long to wait for them. Always pass both — without a deadline the command blocks forever when the target function is never called. Exit code 124 means the window elapsed with no invocation observed, which is a result, not an error.

Positional Arguments

• module — the module name as it would be imported in the target process. For example, if the target code does from myapp.utils import helper, then module is myapp.utils. PyFlightProfiler locates the module via importlib.import_module. If you're unsure of the module name, run a separate command to resolve it first: flight_profiler <pid> --cmd "module /absolute/path/to/file.py" --no-color, then use the returned module name here.
• class (optional) — class name, omit if module-level function
• method — target method name

Options

Flag	Description	Default
-i, --interval <value>	Only display sub-calls costing more than N milliseconds. Calls below this threshold are hidden from the tree.	0.1
-et, --entrance_time <value>	Only display invocations where the entrance (top-level) cost exceeds N milliseconds. Invocations below this threshold are silently skipped.	0
-d, --depth <value>	Limit call tree display depth. -d 2 shows only direct children of the traced method. When set, ignores -i interval.	-1 (unlimited)
-nm, --nested-method <value>	Trace a nested (inner) function defined inside the target method. Depth is restricted to 1.	none
-n, --limits <value>	Maximum number of invocations to capture before stopping	10
-f, --filter_expr <value>	Filter expression on (target, *args, **kwargs). Only invocations where the expression is truthy are traced. For class methods, args[0] is self.	none

Output Format

Each captured invocation produces a block:

────────────────────────────────────────────────────────────
🔍 2026-04-19 11:35:38:953 thread=MainThread tid=8722965056 daemon=False cost=90.003ms
[90.003ms] process_order    trace_demo_script.py:6
├─ [5.574ms] validate    trace_demo_script.py:13
│  └─ [5.52ms]  sleep    <built-in>
├─ [31.402ms] compute_price    trace_demo_script.py:16
│  ├─ [21.285ms]  sleep    <built-in>
│  └─ [10.074ms] apply_discount    trace_demo_script.py:20
│     └─ [10.049ms]  sleep    <built-in>
└─ [52.99ms] save_to_db    trace_demo_script.py:23
   └─ [52.949ms]  sleep    <built-in>

Title line fields:

Field	Description
🔍	trace command icon
Timestamp	When the entrance method was called
thread	Thread name that executed the method
tid	Thread ID
daemon	Whether the thread is a daemon thread
cost	Total execution time of the entrance method (milliseconds)

Call tree fields (each line):

Field	Description
[Nms]	Execution time of that specific call. Color-coded in terminal: >50% of parent = red, >20% = yellow, >5% = green, else faint green
Method name	Function name. [await] prefix indicates an async await point
Location	filename:lineno for Python methods, <built-in> for C extension methods

Tree structure: ├─ / └─ show child calls, │ connects sibling levels.

Examples

1. Class method — full call tree

Shows the complete hierarchy with all sub-calls and their timing:

flight_profiler <pid> --cmd "trace __main__ OrderService process_order -n 1" --no-color

🔍 2026-04-19 11:35:38:953 thread=MainThread tid=8722965056 daemon=False cost=90.003ms
[90.003ms] process_order    trace_demo_script.py:6
├─ [5.574ms] validate    trace_demo_script.py:13
│  └─ [5.52ms]  sleep    <built-in>
├─ [31.402ms] compute_price    trace_demo_script.py:16
│  ├─ [21.285ms]  sleep    <built-in>
│  └─ [10.074ms] apply_discount    trace_demo_script.py:20
│     └─ [10.049ms]  sleep    <built-in>
└─ [52.99ms] save_to_db    trace_demo_script.py:23
   └─ [52.949ms]  sleep    <built-in>

Reading: save_to_db takes 52.99ms (59% of total) — the dominant bottleneck. compute_price takes 31.4ms including its child apply_discount.

2. Module-level function

flight_profiler <pid> --cmd "trace __main__ compute -n 1" --no-color

🔍 2026-04-19 11:35:42:462 thread=MainThread tid=8722965056 daemon=False cost=21.672ms
[21.672ms] compute    trace_demo_script.py:43
├─ [10.104ms]  sleep    <built-in>
├─ [6.298ms] helper    trace_demo_script.py:48
│  └─ [6.269ms]  sleep    <built-in>
└─ [5.217ms] helper    trace_demo_script.py:48
   └─ [5.184ms]  sleep    <built-in>

3. Limit depth with -d

-d 2 shows only the entrance method and its direct children — hides deeper calls:

flight_profiler <pid> --cmd "trace __main__ OrderService process_order -d 2 -n 1" --no-color

🔍 2026-04-19 11:35:51:448 thread=MainThread tid=8722965056 daemon=False cost=90.374ms
[90.374ms] process_order    trace_demo_script.py:6
├─ [6.282ms] validate    trace_demo_script.py:13
├─ [31.704ms] compute_price    trace_demo_script.py:16
└─ [52.336ms] save_to_db    trace_demo_script.py:23

Useful for getting an overview of the top-level breakdown without noise from deeper calls.

4. Interval threshold with -i

-i 10 hides sub-calls costing less than 10ms. validate (5ms) is hidden:

flight_profiler <pid> --cmd "trace __main__ OrderService process_order -i 10 -n 1" --no-color

🔍 2026-04-19 11:35:52:586 thread=MainThread tid=8722965056 daemon=False cost=92.380ms
[92.38ms] process_order    trace_demo_script.py:6
├─ [35.176ms] compute_price    trace_demo_script.py:16
│  ├─ [22.783ms]  sleep    <built-in>
│  └─ [12.343ms] apply_discount    trace_demo_script.py:20
│     └─ [12.313ms]  sleep    <built-in>
└─ [50.889ms] save_to_db    trace_demo_script.py:23
   └─ [50.844ms]  sleep    <built-in>

5. Entrance time threshold with -et

-et 50 silently skips entire invocations where total cost < 50ms. Only invocations costing >= 50ms are captured. Unlike -i which filters sub-calls within a tree, -et filters the entire invocation.

flight_profiler <pid> --cmd "trace __main__ OrderService process_order -et 50 -n 1" --no-color

If the method typically takes 90ms, output appears normally. If an invocation only takes 30ms, it is silently dropped and does not count toward -n.

6. Nested method with -nm

Traces an inner function defined inside the target method. Depth is restricted to 1:

flight_profiler <pid> --cmd "trace __main__ OrderService nested_outer -nm inner_work -n 1" --no-color

🔍 2026-04-19 11:36:04:093 thread=MainThread tid=8722965056 daemon=False cost=12.526ms
[12.526ms] inner_work    trace_demo_script.py:27
└─ [12.511ms]  sleep    <built-in>

Note: the spy message shows nested_outer.inner_work, confirming the nested method was found.

7. Deep call chain

Automatically follows the full call chain depth:

flight_profiler <pid> --cmd "trace __main__ OrderService deep_call_a -n 1" --no-color

🔍 2026-04-19 11:36:05:247 thread=MainThread tid=8722965056 daemon=False cost=6.294ms
[6.294ms] deep_call_a    trace_demo_script.py:32
└─ [6.291ms] deep_call_b    trace_demo_script.py:35
   └─ [6.287ms] deep_call_c    trace_demo_script.py:38
      └─ [6.268ms]  sleep    <built-in>

8. Filter with -f

Only trace invocations matching the filter expression. For module-level functions, args[0] is the first argument:

flight_profiler <pid> --cmd "trace __main__ compute -f 'args[0]>=1' -n 1" --no-color

🔍 2026-04-19 11:37:42:600 thread=MainThread tid=8722965056 daemon=False cost=24.215ms
[24.215ms] compute    trace_demo_script.py:43
├─ [12.534ms]  sleep    <built-in>
├─ [6.314ms] helper    trace_demo_script.py:48
│  └─ [6.286ms]  sleep    <built-in>
└─ [5.321ms] helper    trace_demo_script.py:48
   └─ [5.303ms]  sleep    <built-in>

For class methods, args[0] is self, so use args[1] for the first real argument.

-i / -et / -d Guide

These three options control what appears in the output at different levels:

Option	What it filters	Effect
-i (interval)	Individual sub-calls in the tree	Hides branches where the call cost < N ms. The invocation is still captured, just with fewer branches shown.
-et (entrance_time)	Entire invocations	Silently skips invocations where the total entrance cost < N ms. Does not count toward -n.
-d (depth)	Tree depth	Truncates the tree at N levels. When set, -i is ignored.

Common combinations:

# Show only slow invocations, then only their expensive sub-calls
trace __main__ MyClass method -et 100 -i 10 -n 3

# Quick overview: just the top-level breakdown
trace __main__ MyClass method -d 2 -n 1

# Catch everything (debug mode)
trace __main__ MyClass method -i 0 -n 1

Troubleshooting: No Output

If trace produces no output:

1. Method not being called — make sure the code path is actually being triggered
2. Wrong module name — use flight_profiler <pid> --cmd "module /path/to/file.py" --no-color to verify
3. -et too high — invocations below the threshold are silently skipped (try -et 0)
4. -i too high — sub-calls below the threshold are hidden (try -i 0)

Handling Command Output

• Long output: trace call trees can be very deep. If the output is too long to display inline, redirect it to a file for the user to review later:

  flight_profiler <pid> --cmd "trace __main__ handle_request -n 1" --no-color > /tmp/trace_output.txt
  

• Short output: if the output is brief (e.g., -n 1 -d 2 capturing a shallow tree), display the full result directly to the user. If multiple traces were captured, showing just one representative case is sufficient.

Tips

• Start with -d 2 -n 1 for a quick overview, then remove -d to see the full tree
• Use -i 10 to focus on sub-calls taking > 10ms, lowering as needed to zoom in
• Combine with watch to first identify a slow function, then trace to find the bottleneck inside it
• Use -et to skip uninteresting fast invocations when the method is called frequently

Related Commands

• watch — observe individual function calls (args/return/cost), without call tree
• reload — hot-patch a function after editing its source file, without restarting the process. Use trace to inspect call tree timing before/after reload when you need to verify performance improvements that aren't visible from normal program output
• perf — generate flamegraph for broader performance overview via sampling

Source Files

• CLI plugin: flight_profiler/plugins/trace/cli_plugin_trace.py
• Parser: flight_profiler/plugins/trace/trace_parser.py
• Server plugin: flight_profiler/plugins/trace/server_plugin_trace.py