Notes on timing LLVM

Getting LLVM Pass Timings

The dispatcher stores LLVM pass timings in the dispatcher object metadata under the llvm_pass_timings key when NUMBA_LLVM_PASS_TIMINGS is enabled or numba.config.LLVM_PASS_TIMINGS is set to truthy. The timings information contains details on how much time has been spent in each pass. The pass timings are also grouped by their purpose. For example, there will be pass timings for function-level pre-optimizations, module-level optimizations, and object code generation.

Code Example

from test_pass_timings of numba/tests/doc_examples/test_llvm_pass_timings.py
 1import numba
 2
 3@numba.njit
 4def foo(n):
 5    c = 0
 6    for i in range(n):
 7        for j in range(i):
 8            c += j
 9    return c
10
11foo(10)
12md = foo.get_metadata(foo.signatures[0])
13print(md['llvm_pass_timings'])

Example output:

Printing pass timings for JITCodeLibrary('DocsLLVMPassTimings.test_pass_timings.<locals>.foo')
Total time: 0.0376
== #0 Function passes on '_ZN5numba5tests12doc_examples22test_llvm_pass_timings19DocsLLVMPassTimings17test_pass_timings12$3clocals$3e7foo$241Ex'
Percent: 4.8%
Total 0.0018s
Top timings:
  0.0015s ( 81.6%) SROA #3
  0.0002s (  9.3%) Early CSE #2
  0.0001s (  4.0%) Simplify the CFG #9
  0.0000s (  1.5%) Prune NRT refops #4
  0.0000s (  1.1%) Post-Dominator Tree Construction #5
== #1 Function passes on '_ZN7cpython5numba5tests12doc_examples22test_llvm_pass_timings19DocsLLVMPassTimings17test_pass_timings12$3clocals$3e7foo$241Ex'
Percent: 0.8%
Total 0.0003s
Top timings:
  0.0001s ( 30.4%) Simplify the CFG #10
  0.0001s ( 24.1%) Early CSE #3
  0.0001s ( 17.8%) SROA #4
  0.0000s (  8.8%) Prune NRT refops #5
  0.0000s (  5.6%) Post-Dominator Tree Construction #6
== #2 Function passes on 'cfunc._ZN5numba5tests12doc_examples22test_llvm_pass_timings19DocsLLVMPassTimings17test_pass_timings12$3clocals$3e7foo$241Ex'
Percent: 0.5%
Total 0.0002s
Top timings:
  0.0001s ( 27.7%) Early CSE #4
  0.0001s ( 26.8%) Simplify the CFG #11
  0.0000s ( 13.8%) Prune NRT refops #6
  0.0000s (  7.4%) Post-Dominator Tree Construction #7
  0.0000s (  6.7%) Dominator Tree Construction #29
== #3 Module passes (cheap optimization for refprune)
Percent: 3.7%
Total 0.0014s
Top timings:
  0.0007s ( 52.0%) Combine redundant instructions
  0.0001s (  5.4%) Function Integration/Inlining
  0.0001s (  4.9%) Prune NRT refops #2
  0.0001s (  4.8%) Natural Loop Information
  0.0001s (  4.6%) Post-Dominator Tree Construction #2
== #4 Module passes (full optimization)
Percent: 43.9%
Total 0.0165s
Top timings:
  0.0032s ( 19.5%) Combine redundant instructions #9
  0.0022s ( 13.5%) Combine redundant instructions #7
  0.0010s (  6.1%) Induction Variable Simplification
  0.0008s (  4.8%) Unroll loops #2
  0.0007s (  4.5%) Loop Vectorization
== #5 Finalize object
Percent: 46.3%
Total 0.0174s
Top timings:
  0.0060s ( 34.6%) X86 DAG->DAG Instruction Selection #2
  0.0019s ( 11.0%) Greedy Register Allocator #2
  0.0013s (  7.4%) Machine Instruction Scheduler #2
  0.0012s (  7.1%) Loop Strength Reduction
  0.0004s (  2.3%) Induction Variable Users

API for custom analysis

It is possible to get more details then the summary text in the above example. The pass timings are stored in a numba.misc.llvm_pass_timings.PassTimingsCollection, which contains methods for accessing individual record for each pass.

class numba.misc.llvm_pass_timings.PassTimingsCollection(name)

A collection of pass timings.

This class implements the Sequence protocol for accessing the individual timing records.

__getitem__(i)

Get the i-th timing record.

Returns
res: (name, timings)

A named tuple with two fields:

  • name: str

  • timings: ProcessedPassTimings

__len__()

Length of this collection.

get_total_time()

Computes the sum of the total time across all contained timings.

Returns
res: float or None

Returns the total number of seconds or None if no timings were recorded

list_longest_first()

Returns the timings in descending order of total time duration.

Returns
res: List[ProcessedPassTimings]
summary(topn=5)

Return a string representing the summary of the timings.

Parameters
topn: int; optional, default=5.

This limits the maximum number of items to show. This function will show the topn most time-consuming passes.

Returns
res: str
See also ProcessedPassTimings.summary()
class numba.misc.llvm_pass_timings.ProcessedPassTimings(raw_data)

A class for processing raw timing report from LLVM.

The processing is done lazily so we don’t waste time processing unused timing information.

get_raw_data()

Returns the raw string data.

Returns
res: str
get_total_time()

Compute the total time spend in all passes.

Returns
res: float
list_records()

Get the processed data for the timing report.

Returns
res: List[PassTimingRecord]
list_top(n)

Returns the top(n) most time-consuming (by wall-time) passes.

Parameters
n: int

This limits the maximum number of items to show. This function will show the n most time-consuming passes.

Returns
res: List[PassTimingRecord]

Returns the top(n) most time-consuming passes in descending order.

summary(topn=5, indent=0)

Return a string summarizing the timing information.

Parameters
topn: int; optional

This limits the maximum number of items to show. This function will show the topn most time-consuming passes.

indent: int; optional

Set the indentation level. Defaults to 0 for no indentation.

Returns
res: str
class numba.misc.llvm_pass_timings.PassTimingRecord(user_time, user_percent, system_time, system_percent, user_system_time, user_system_percent, wall_time, wall_percent, pass_name, instruction)