# 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)