<jupyter_start><jupyter_text>PyTorch Profiler====================================This recipe explains how to use PyTorch profiler and measure the time andmemory consumption of the model's operators.Introduction------------PyTorch includes a simple profiler API that is useful when user needsto determine the most expensive operators in the model.In this recipe, we will use a simple Resnet model to demonstrate how touse profiler to analyze model performance.Setup-----To install ``torch`` and ``torchvision`` use the following command:::   pip install torch torchvision Steps-----1. Import all necessary libraries2. Instantiate a simple Resnet model3. Using profiler to analyze execution time4. Using profiler to analyze memory consumption5. Using tracing functionality6. Examining stack traces7. Visualizing data as a flamegraph8. Using profiler to analyze long-running jobs1. Import all necessary libraries~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~In this recipe we will use ``torch``, ``torchvision.models``and ``profiler`` modules:<jupyter_code>import torch
import torchvision.models as models
from torch.profiler import profile, record_function, ProfilerActivity<jupyter_output><empty_output><jupyter_text>2. Instantiate a simple Resnet model~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~Let's create an instance of a Resnet model and prepare an inputfor it:<jupyter_code>model = models.resnet18()
inputs = torch.randn(5, 3, 224, 224)<jupyter_output><empty_output><jupyter_text>3. Using profiler to analyze execution time~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~PyTorch profiler is enabled through the context manager and acceptsa number of parameters, some of the most useful are:- ``activities`` - a list of activities to profile:   - ``ProfilerActivity.CPU`` - PyTorch operators, TorchScript functions and     user-defined code labels (see ``record_function`` below);   - ``ProfilerActivity.CUDA`` - on-device CUDA kernels;- ``record_shapes`` - whether to record shapes of the operator inputs;- ``profile_memory`` - whether to report amount of memory consumed by  model's Tensors;- ``use_cuda`` - whether to measure execution time of CUDA kernels.Note: when using CUDA, profiler also shows the runtime CUDA eventsoccuring on the host. Let's see how we can use profiler to analyze the execution time:<jupyter_code>with profile(activities=[ProfilerActivity.CPU], record_shapes=True) as prof:
    with record_function("model_inference"):
        model(inputs)<jupyter_output>/usr/local/lib/python3.7/dist-packages/torch/nn/functional.py:718: UserWarning: Named tensors and all their associated APIs are an experimental feature and subject to change. Please do not use them for anything important until they are released as stable. (Triggered internally at  /pytorch/c10/core/TensorImpl.h:1156.)
  return torch.max_pool2d(input, kernel_size, stride, padding, dilation, ceil_mode)<jupyter_text>Note that we can use ``record_function`` context manager to labelarbitrary code ranges with user provided names(``model_inference`` is used as a label in the example above).Profiler allows one to check which operators were called during theexecution of a code range wrapped with a profiler context manager.If multiple profiler ranges are active at the same time (e.g. inparallel PyTorch threads), each profiling context manager tracks onlythe operators of its corresponding range.Profiler also automatically profiles the async tasks launchedwith ``torch.jit._fork`` and (in case of a backward pass)the backward pass operators launched with ``backward()`` call.Let's print out the stats for the execution above:<jupyter_code>print(prof.key_averages().table(sort_by="cpu_time_total", row_limit=10))<jupyter_output>---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------  
                             Name    Self CPU %      Self CPU   CPU total %     CPU total  CPU time avg    # of Calls  
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------  
                  model_inference         3.90%      29.904ms        99.71%     764.855ms     764.855ms             1  
                     aten::conv2d         0.03%     259.000us        71.82%     550.883ms      27.544ms            20  
                aten::convolution         0.04%     311.000us        71.78%     550.624ms      27.531ms            20  
               aten::_convolution         0.06%     439.000us        71.74%     550.313ms      27.516ms            20  
         aten::mkldnn_convolution        71.59%     549.142ms        71.69%     549.874ms      27.494ms            20  
                 aten::batch_norm       [...]<jupyter_text>The output will look like (omitting some columns):<jupyter_code># ---------------------------------  ------------  ------------  ------------  ------------
#                              Name      Self CPU     CPU total  CPU time avg    # of Calls
# ---------------------------------  ------------  ------------  ------------  ------------
#                   model_inference       5.509ms      57.503ms      57.503ms             1
#                      aten::conv2d     231.000us      31.931ms       1.597ms            20
#                 aten::convolution     250.000us      31.700ms       1.585ms            20
#                aten::_convolution     336.000us      31.450ms       1.573ms            20
#          aten::mkldnn_convolution      30.838ms      31.114ms       1.556ms            20
#                  aten::batch_norm     211.000us      14.693ms     734.650us            20
#      aten::_batch_norm_impl_index     319.000us      14.482ms     724.100us            20
#           aten::native_batch_norm       9.229ms      14.109ms     705.450us            20
#                        aten::mean     332.000us       2.631ms     125.286us            21
#                      aten::select       1.668ms       2.292ms       8.988us           255
# ---------------------------------  ------------  ------------  ------------  ------------
# Self CPU time total: 57.549ms<jupyter_output><empty_output><jupyter_text>Here we see that, as expected, most of the time is spent in convolution (and specifically in ``mkldnn_convolution``for PyTorch compiled with MKL-DNN support).Note the difference between self cpu time and cpu time - operators can call other operators, self cpu time exludes timespent in children operator calls, while total cpu time includes it. You can choose to sort by the self cpu time by passing``sort_by="self_cpu_time_total"`` into the ``table`` call.To get a finer granularity of results and include operator input shapes, pass ``group_by_input_shape=True``(note: this requires running the profiler with ``record_shapes=True``):<jupyter_code>print(prof.key_averages(group_by_input_shape=True).table(sort_by="cpu_time_total", row_limit=10))

# (omitting some columns)
# ---------------------------------  ------------  -------------------------------------------
#                              Name     CPU total                                 Input Shapes
# ---------------------------------  ------------  -------------------------------------------
#                   model_inference      57.503ms                                           []
#                      aten::conv2d       8.008ms      [5,64,56,56], [64,64,3,3], [], ..., []]
#                 aten::convolution       7.956ms     [[5,64,56,56], [64,64,3,3], [], ..., []]
#                aten::_convolution       7.909ms     [[5,64,56,56], [64,64,3,3], [], ..., []]
#          aten::mkldnn_convolution       7.834ms     [[5,64,56,56], [64,64,3,3], [], ..., []]
#                      aten::conv2d       6.332ms    [[5,512,7,7], [512,512,3,3], [], ..., []]
#                 aten::convolution       6.303ms    [[5,512,7,7], [512,512,3,3], [], ..., []]
#                aten::_convolution       6.273ms    [[5,512,7,7], [512,512,3,3], [], ..., []]
#          aten::mkldnn_convolution       6.233ms    [[5,512,7,7], [512,512,3,3], [], ..., []]
#                      aten::conv2d       4.751ms  [[5,256,14,14], [256,256,3,3], [], ..., []]
# ---------------------------------  ------------  -------------------------------------------
# Self CPU time total: 57.549ms<jupyter_output>---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------  --------------------------------------------------------------------------------  
                             Name    Self CPU %      Self CPU   CPU total %     CPU total  CPU time avg    # of Calls                                                                      Input Shapes  
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------  --------------------------------------------------------------------------------  
                  model_inference         3.90%      29.904ms        99.71%     764.855ms     764.855ms             1                                                                                []  
                     aten::conv2d         0.01%      57.000us        21.51%     165.014ms     165.014ms             1                             [[5, 3, 224, 224], [64, 3, 7, 7], [], [], [], [...]<jupyter_text>Note the occurence of ``aten::convolution`` twice with different input shapes. Profiler can also be used to analyze performance of models executed on GPUs:<jupyter_code># model = models.resnet18().cuda()
# inputs = torch.randn(5, 3, 224, 224).cuda()

model = models.resnet18()
inputs = torch.randn(5, 3, 224, 224)

with profile(activities=[
        ProfilerActivity.CPU, ProfilerActivity.CUDA], record_shapes=True) as prof:
    with record_function("model_inference"):
        model(inputs)

print(prof.key_averages().table(sort_by="cuda_time_total", row_limit=10))<jupyter_output>/usr/local/lib/python3.7/dist-packages/torch/autograd/profiler.py:427: UserWarning: CUDA is not available, disabling CUDA profiling
  warn("CUDA is not available, disabling CUDA profiling")<jupyter_text>(Note: the first use of CUDA profiling may bring an extra overhead.) The resulting table output:<jupyter_code># (omitting some columns)
# -------------------------------------------------------  ------------  ------------
#                                                    Name     Self CUDA    CUDA total
# -------------------------------------------------------  ------------  ------------
#                                         model_inference       0.000us      11.666ms
#                                            aten::conv2d       0.000us      10.484ms
#                                       aten::convolution       0.000us      10.484ms
#                                      aten::_convolution       0.000us      10.484ms
#                              aten::_convolution_nogroup       0.000us      10.484ms
#                                       aten::thnn_conv2d       0.000us      10.484ms
#                               aten::thnn_conv2d_forward      10.484ms      10.484ms
# void at::native::im2col_kernel<float>(long, float co...       3.844ms       3.844ms
#                                       sgemm_32x32x32_NN       3.206ms       3.206ms
#                                   sgemm_32x32x32_NN_vec       3.093ms       3.093ms
# -------------------------------------------------------  ------------  ------------
# Self CPU time total: 23.015ms
# Self CUDA time total: 11.666ms<jupyter_output><empty_output><jupyter_text>Note the occurence of on-device kernels in the output (e.g. ``sgemm_32x32x32_NN``). 4. Using profiler to analyze memory consumption~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~PyTorch profiler can also show the amount of memory (used by the model's tensors)that was allocated (or released) during the execution of the model's operators.In the output below, 'self' memory corresponds to the memory allocated (released)by the operator, excluding the children calls to the other operators.To enable memory profiling functionality pass ``profile_memory=True``.<jupyter_code>model = models.resnet18()
inputs = torch.randn(5, 3, 224, 224)

with profile(activities=[ProfilerActivity.CPU],
        profile_memory=True, record_shapes=True) as prof:
    model(inputs)

print(prof.key_averages().table(sort_by="self_cpu_memory_usage", row_limit=10))

# (omitting some columns)
# ---------------------------------  ------------  ------------  ------------
#                              Name       CPU Mem  Self CPU Mem    # of Calls
# ---------------------------------  ------------  ------------  ------------
#                       aten::empty      94.79 Mb      94.79 Mb           121
#     aten::max_pool2d_with_indices      11.48 Mb      11.48 Mb             1
#                       aten::addmm      19.53 Kb      19.53 Kb             1
#               aten::empty_strided         572 b         572 b            25
#                     aten::resize_         240 b         240 b             6
#                         aten::abs         480 b         240 b             4
#                         aten::add         160 b         160 b            20
#               aten::masked_select         120 b         112 b             1
#                          aten::ne         122 b          53 b             6
#                          aten::eq          60 b          30 b             2
# ---------------------------------  ------------  ------------  ------------
# Self CPU time total: 53.064ms

print(prof.key_averages().table(sort_by="cpu_memory_usage", row_limit=10))

# (omitting some columns)
# ---------------------------------  ------------  ------------  ------------
#                              Name       CPU Mem  Self CPU Mem    # of Calls
# ---------------------------------  ------------  ------------  ------------
#                       aten::empty      94.79 Mb      94.79 Mb           121
#                  aten::batch_norm      47.41 Mb           0 b            20
#      aten::_batch_norm_impl_index      47.41 Mb           0 b            20
#           aten::native_batch_norm      47.41 Mb           0 b            20
#                      aten::conv2d      47.37 Mb           0 b            20
#                 aten::convolution      47.37 Mb           0 b            20
#                aten::_convolution      47.37 Mb           0 b            20
#          aten::mkldnn_convolution      47.37 Mb           0 b            20
#                  aten::max_pool2d      11.48 Mb           0 b             1
#     aten::max_pool2d_with_indices      11.48 Mb      11.48 Mb             1
# ---------------------------------  ------------  ------------  ------------
# Self CPU time total: 53.064ms<jupyter_output>---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------  ------------  ------------  
                             Name    Self CPU %      Self CPU   CPU total %     CPU total  CPU time avg       CPU Mem  Self CPU Mem    # of Calls  
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------  ------------  ------------  
                      aten::empty         0.29%       1.540ms         0.29%       1.540ms      15.248us      94.79 Mb      94.79 Mb           101  
    aten::max_pool2d_with_indices         8.99%      47.763ms         8.99%      47.763ms      47.763ms      11.48 Mb      11.48 Mb             1  
                      aten::addmm         0.09%     487.000us         0.10%     505.000us     505.000us      19.53 Kb      19.53 Kb             1  
                        aten::add         0.14%     743.000us         0.14%     743.000us      37.150us         [...]<jupyter_text>5. Using tracing functionality~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~Profiling results can be outputted as a .json trace file:<jupyter_code># model = models.resnet18().cuda()
# inputs = torch.randn(5, 3, 224, 224).cuda()

model = models.resnet18()
inputs = torch.randn(5, 3, 224, 224)

with profile(activities=[ProfilerActivity.CPU, ProfilerActivity.CUDA]) as prof:
    model(inputs)

prof.export_chrome_trace("trace.json")
!head trace.json<jupyter_output>{
  "schemaVersion": 1,
  "deviceProperties": [
  ],
  "traceEvents": [
  {
    "ph": "X", "cat": "Operator", 
    "name": "aten::empty", "pid": 129, "tid": "129",
    "ts": 1631262068462487, "dur": 311,<jupyter_text>You can examine the sequence of profiled operators and CUDA kernelsin Chrome trace viewer (``chrome://tracing``):![](https://github.com/pytorch/tutorials/blob/gh-pages/_static/img/trace_img.png?raw=1)   :scale: 25 % 6. Examining stack traces~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~Profiler can be used to analyze Python and TorchScript stack traces:<jupyter_code>with profile(
    activities=[ProfilerActivity.CPU, ProfilerActivity.CUDA],
    with_stack=True,
) as prof:
    model(inputs)

# Print aggregated stats
print(prof.key_averages(group_by_stack_n=5).table(sort_by="self_cuda_time_total", row_limit=2))

# (omitting some columns)
# -------------------------  -----------------------------------------------------------
#                      Name  Source Location
# -------------------------  -----------------------------------------------------------
# aten::thnn_conv2d_forward  .../torch/nn/modules/conv.py(439): _conv_forward
#                            .../torch/nn/modules/conv.py(443): forward
#                            .../torch/nn/modules/module.py(1051): _call_impl
#                            .../site-packages/torchvision/models/resnet.py(63): forward
#                            .../torch/nn/modules/module.py(1051): _call_impl
#
# aten::thnn_conv2d_forward  .../torch/nn/modules/conv.py(439): _conv_forward
#                            .../torch/nn/modules/conv.py(443): forward
#                            .../torch/nn/modules/module.py(1051): _call_impl
#                            .../site-packages/torchvision/models/resnet.py(59): forward
#                            .../torch/nn/modules/module.py(1051): _call_impl
#
# -------------------------  -----------------------------------------------------------
# Self CPU time total: 34.016ms
# Self CUDA time total: 11.659ms<jupyter_output><empty_output><jupyter_text>Note the two convolutions and the two callsites in ``torchvision/models/resnet.py`` script.(Warning: stack tracing adds an extra profiling overhead.) 7. Visualizing data as a flamegraph~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~Execution time (``self_cpu_time_total`` and ``self_cuda_time_total`` metrics) and stack tracescan also be visualized as a flame graph. To do this, first export the raw data using ``export_stacks`` (requires ``with_stack=True``):<jupyter_code>prof.export_stacks("/tmp/profiler_stacks.txt", "self_cuda_time_total")<jupyter_output><empty_output><jupyter_text>We recommend using e.g. `Flamegraph tool `_ to generate aninteractive SVG:<jupyter_code># git clone https://github.com/brendangregg/FlameGraph
# cd FlameGraph
# ./flamegraph.pl --title "CUDA time" --countname "us." /tmp/profiler_stacks.txt > perf_viz.svg<jupyter_output><empty_output><jupyter_text>![](https://github.com/pytorch/tutorials/blob/gh-pages/_static/img/perf_viz.png?raw=1)   :scale: 25 % 8. Using profiler to analyze long-running jobs~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~PyTorch profiler offers an additional API to handle long-running jobs(such as training loops). Tracing all of the execution can beslow and result in very large trace files. To avoid this, use optionalarguments:- ``schedule`` - specifies a function that takes an integer argument (step number)  as an input and returns an action for the profiler, the best way to use this parameter  is to use ``torch.profiler.schedule`` helper function that can generate a schedule for you;- ``on_trace_ready`` - specifies a function that takes a reference to the profiler as  an input and is called by the profiler each time the new trace is ready.To illustrate how the API works, let's first consider the following example with``torch.profiler.schedule`` helper function:<jupyter_code>from torch.profiler import schedule

my_schedule = schedule(
    skip_first=10,
    wait=5,
    warmup=1,
    active=3,
    repeat=2)<jupyter_output><empty_output><jupyter_text>Profiler assumes that the long-running job is composed of steps, numberedstarting from zero. The example above defines the following sequence of actionsfor the profiler:1. Parameter ``skip_first`` tells profiler that it should ignore the first 10 steps   (default value of ``skip_first`` is zero);2. After the first ``skip_first`` steps, profiler starts executing profiler cycles;3. Each cycle consists of three phases:   - idling (``wait=5`` steps), during this phase profiler is not active;   - warming up (``warmup=1`` steps), during this phase profiler starts tracing, but     the results are discarded; this phase is used to discard the samples obtained by     the profiler at the beginning of the trace since they are usually skewed by an extra     overhead;   - active tracing (``active=3`` steps), during this phase profiler traces and records data;4. An optional ``repeat`` parameter specifies an upper bound on the number of cycles.   By default (zero value), profiler will execute cycles as long as the job runs. Thus, in the example above, profiler will skip the first 15 steps, spend the next step on the warm up,actively record the next 3 steps, skip another 5 steps, spend the next step on the warm up, activelyrecord another 3 steps. Since the ``repeat=2`` parameter value is specified, the profiler will stopthe recording after the first two cycles.At the end of each cycle profiler calls the specified ``on_trace_ready`` function and passes itself asan argument. This function is used to process the new trace - either by obtaining the table output orby saving the output on disk as a trace file.To send the signal to the profiler that the next step has started, call ``prof.step()`` function.The current profiler step is stored in ``prof.step_num``.The following example shows how to use all of the concepts above:<jupyter_code>def trace_handler(p):
    output = p.key_averages().table(sort_by="self_cuda_time_total", row_limit=10)
    print(output)
    p.export_chrome_trace("/tmp/trace_" + str(p.step_num) + ".json")

with profile(
    activities=[ProfilerActivity.CPU, ProfilerActivity.CUDA],
    schedule=torch.profiler.schedule(
        wait=1,
        warmup=1,
        active=2),
    on_trace_ready=trace_handler
) as p:
    for idx in range(8):
        model(inputs)
        p.step()<jupyter_output><empty_output>
{'fraction_non_alphanumeric': 0.2006407161978321, 'fraction_numerical': 0.050686795102470705, 'mean_word_length': 1.6283737024221454, 'pattern_counts': {'":': 10, '<': 56, '<?xml version=': 0, '>': 57, 'https://': 3, 'lorem ipsum': 0, 'www.': 0, 'xml': 0}, 'pii_count': 0, 'substrings_counts': 0, 'word_list_counts': {'cursed_substrings.json': 27, 'profanity_word_list.json': 0, 'sexual_word_list.json': 0, 'zh_pornsignals.json': 0}}
{'chain_length': '15', 'dir': 'jupyter-structured-clean-dedup', 'id': '595204', 'license': 'Apache-2.0', 'n_tokens_mistral': 6657, 'n_tokens_neox': 5889, 'n_words': 1771, 'path': '_docs/nbs/T506315-PyTorch-Profiler.ipynb', 'repo_name': 'sparsh-ai/recohut', 'size': '22787'}