Repository: pytorch
Issue: torch.profiler.profile does't work well for CPU model when not using torch.profiler.schedule 
Labels: oncall: profiler

### 🐛 Describe the bug

According to https://pytorch.org/docs/stable/profiler.html, there has **torch.profiler.schedule** method when using **torch.profiler.profile** to profiling a model,  when I profile  a quantized resnet50 model on CPU device, I find that there has a different behavior when using **torch.profiler.schedule** or not :

1.  using **torch.profiler.schedule**:
```bash 
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
                             Name    Self CPU %      Self CPU   CPU total %     CPU total  CPU time avg    # of Calls
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
           quantized::conv2d_relu        38.54%      38.421ms        40.40%      40.272ms     122.036us           330
                    ProfilerStep*        30.00%      29.906ms        99.96%      99.654ms       9.965ms            10
                quantized::conv2d        21.72%      21.649ms        22.52%      22.446ms     112.230us           200
              quantized::add_relu         4.43%       4.412ms         4.96%       4.942ms      30.887us           160
    aten::_empty_affine_quantized         1.98%       1.969ms         1.98%       1.969ms       2.735us           720
                      aten::empty         0.66%     659.000us         0.66%     659.000us       1.156us           570
       aten::quantized_max_pool2d         0.59%     589.000us         0.61%     607.000us      60.700us            10
                quantized::linear         0.45%     450.000us         0.50%     497.000us      49.700us            10
                       aten::item         0.31%     305.000us         0.46%     458.000us       1.347us           340
                    aten::q_scale         0.29%     294.000us         0.29%     294.000us       0.278us          1059
               aten::q_zero_point         0.23%     228.000us         0.23%     228.000us       0.215us          1060
        aten::quantize_per_tensor         0.18%     177.000us         0.20%     200.000us      20.000us            10
       aten::_adaptive_avg_pool2d         0.17%     168.000us         0.19%     187.000us      18.700us            10
        aten::_local_scalar_dense         0.15%     153.000us         0.15%     153.000us       0.450us           340
                    aten::qscheme         0.12%     124.000us         0.12%     124.000us       0.279us           445
                 aten::dequantize         0.05%      50.000us         0.06%      64.000us       6.400us            10
             aten::_reshape_alias         0.03%      32.000us         0.03%      32.000us       3.200us            10
                      aten::zeros         0.02%      24.000us         0.04%      35.000us       3.500us            10
                    aten::flatten         0.02%      23.000us         0.06%      55.000us       5.500us            10
                    aten::resize_         0.02%      19.000us         0.02%      19.000us       1.900us            10
        aten::adaptive_avg_pool2d         0.02%      17.000us         0.20%     204.000us      20.400us            10
                 aten::max_pool2d         0.02%      16.000us         0.62%     623.000us      62.300us            10
                      aten::zero_         0.00%       4.000us         0.00%       4.000us       0.400us            10
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
Self CPU time total: 99.689ms
```
2. not using **torch.profiler.schedule**:
```bash
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
                             Name    Self CPU %      Self CPU   CPU total %     CPU total  CPU time avg    # of Calls
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
           quantized::conv2d_relu        55.26%     384.850ms        57.89%     403.138ms     122.163us          3300
                quantized::conv2d        30.90%     215.170ms        32.07%     223.334ms     111.667us          2000
              quantized::add_relu         6.42%      44.699ms         7.16%      49.828ms      31.142us          1600
    aten::_empty_affine_quantized         2.79%      19.419ms         2.79%      19.419ms       2.697us          7200
                      aten::empty         0.95%       6.650ms         0.95%       6.650ms       1.209us          5500
       aten::quantized_max_pool2d         0.80%       5.603ms         0.83%       5.798ms      57.980us           100
                quantized::linear         0.63%       4.380ms         0.70%       4.862ms      48.620us           100
                    aten::q_scale         0.45%       3.136ms         0.45%       3.136ms       0.296us         10593
                       aten::item         0.42%       2.959ms         0.64%       4.488ms       1.320us          3400
               aten::q_zero_point         0.29%       2.008ms         0.29%       2.008ms       0.190us         10594
       aten::_adaptive_avg_pool2d         0.24%       1.654ms         0.26%       1.839ms      18.390us           100
        aten::quantize_per_tensor         0.24%       1.648ms         0.27%       1.871ms      18.710us           100
        aten::_local_scalar_dense         0.22%       1.529ms         0.22%       1.529ms       0.450us          3400
                    aten::qscheme         0.17%       1.169ms         0.17%       1.169ms       0.262us          4470
                 aten::dequantize         0.07%     495.000us         0.09%     619.000us       6.190us           100
             aten::_reshape_alias         0.05%     326.000us         0.05%     326.000us       3.260us           100
                    aten::flatten         0.03%     223.000us         0.08%     549.000us       5.490us           100
                    aten::resize_         0.03%     185.000us         0.03%     185.000us       1.850us           100
        aten::adaptive_avg_pool2d         0.02%     152.000us         0.29%       1.991ms      19.910us           100
                 aten::max_pool2d         0.02%     149.000us         0.85%       5.947ms      59.470us           100
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
Self CPU time total: 696.404ms
```
you can see that there has less time when not using  **torch.profiler.schedule**, **6.96 ms** Vs **9.97 mas** for each iteration. the time of using **torch.profiler.schedule** is more close to the time of not using profiler(**10.40 ms**) than not using **torch.profiler.schedule**.  The main gap between using **torch.profiler.schedule** and not using **torch.profiler.schedule* is **ProfilerStep**'s time. So I have two questions about **torch.profiler.profile**:

1.  What is  **ProfilerStep***'? why does it spend such big time, about **30%** E2E?
2. Why the collected time is less than the real compute time when not using **torch.profiler.schedule**?

How to reproduce? Just run the following script by 
``` bash
OMP_NUM_THREADS=4 numactl --physcpubind=0-3 --membind=0 python resnet50_test.py
```

```python
import torch
from torch import nn
import torch.quantization.quantize_fx as quantize_fx
from torch.quantization import get_default_qconfig
from torch.quantization.quantize_fx import prepare_fx, convert_fx
from torchvision import models
import time
import copy
import torch.profiler as profiler

qengine = 'fbgemm'
torch.backends.quantized.engine = qengine
print('Quantization engine:', qengine)

rn50 = models.resnet50(pretrained=True)
model_fp32 = copy.deepcopy(rn50)
model_fp32.eval()
model_fp32.to(memory_format=torch.channels_last)

qconfig = get_default_qconfig(qengine)
qconfig_dict = {"": qconfig}
print('Preparing int8 model...')
prepared_model = prepare_fx(model_fp32, qconfig_dict)

print('Doing calibration...')
with torch.no_grad():
    for i in range(20):
        # print(i)
        x = torch.randn(1, 3, 224, 224)
        prepared_model(x)

print('Converting int8 model...')
quantized_model = convert_fx(prepared_model)

def run_benchmark(model_in, num_warmup: int, num_run: int):
    x = torch.randn((1, 3, 224, 224), dtype=torch.float) + 2
    x = x.to(memory_format=torch.channels_last)
    total_time = 0
    print('Warmup for int8 model...')
    for i in range(num_warmup):
        y = model_in(x)

    t1 = time.time()
    for i in range(num_run):
        y = model_in(x)

    t2 = time.time()
    total_time = t2 - t1
    lat = total_time / num_run * 1000 
    tp = 1.0 / lat * 1000
    print('Latency =', lat, 'ms, Throughput =', tp, 'fps')
    return tp

warmup = 200
run = 300
# INT8
print('Int8 model')
with torch.no_grad():
    int8_tp = run_benchmark(quantized_model, warmup, run)


x = torch.randn((1, 3, 224, 224), dtype=torch.float) + 2
x = x.to(memory_format=torch.channels_last)

def trace_handler(prof):
    print(prof.key_averages().table(sort_by="self_cpu_time_total", row_limit=-1))

print("schedule method")
with torch.no_grad():
    with profiler.profile(
        activities=[profiler.ProfilerActivity.CPU],
        schedule=torch.profiler.schedule(wait=10,warmup=50,active=10),
        # son_trace_ready=torch.profiler.tensorboard_trace_handler("profiler_result")
        on_trace_ready=trace_handler) as p:
        for i in range(200):
            y = quantized_model(x)
            p.step()

print("not using schedule method")
with profiler.profile(activities=[profiler.ProfilerActivity.CPU]) as p, torch.no_grad():
    for i in range(10):
        y = quantized_model(x)
print(p.key_averages().table(sort_by="self_cpu_time_total", row_limit=-1))
```

Expected output:
``` bash 
Latency = 10.398627916971844 ms, Throughput = 96.16653350658663 fps
schedule method
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
                             Name    Self CPU %      Self CPU   CPU total %     CPU total  CPU time avg    # of Calls
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
           quantized::conv2d_relu        38.61%      38.669ms        40.37%      40.428ms     122.509us           330
                    ProfilerStep*        29.66%      29.707ms        99.95%     100.103ms      10.010ms            10
                quantized::conv2d        21.98%      22.013ms        22.84%      22.880ms     114.400us           200
              quantized::add_relu         4.44%       4.445ms         4.97%       4.978ms      31.113us           160
    aten::_empty_affine_quantized         1.92%       1.926ms         1.92%       1.926ms       2.675us           720
                      aten::empty         0.69%     693.000us         0.69%     693.000us       1.216us           570
       aten::quantized_max_pool2d         0.57%     573.000us         0.59%     591.000us      59.100us            10
                quantized::linear         0.45%     452.000us         0.50%     500.000us      50.000us            10
                       aten::item         0.32%     322.000us         0.46%     465.000us       1.368us           340
                    aten::q_scale         0.28%     285.000us         0.28%     285.000us       0.269us          1060
               aten::q_zero_point         0.22%     216.000us         0.22%     216.000us       0.204us          1059
        aten::quantize_per_tensor         0.19%     186.000us         0.21%     211.000us      21.100us            10
       aten::_adaptive_avg_pool2d         0.16%     162.000us         0.19%     189.000us      18.900us            10
        aten::_local_scalar_dense         0.14%     143.000us         0.14%     143.000us       0.421us           340
                    aten::qscheme         0.14%     142.000us         0.14%     142.000us       0.315us           451
                 aten::dequantize         0.05%      49.000us         0.06%      63.000us       6.300us            10
             aten::_reshape_alias         0.04%      40.000us         0.04%      40.000us       4.000us            10
                    aten::flatten         0.04%      36.000us         0.08%      76.000us       7.600us            10
                      aten::zeros         0.03%      35.000us         0.05%      52.000us       5.200us            10
                    aten::resize_         0.02%      22.000us         0.02%      22.000us       2.200us            10
                 aten::max_pool2d         0.02%      17.000us         0.61%     608.000us      60.800us            10
        aten::adaptive_avg_pool2d         0.01%      15.000us         0.20%     204.000us      20.400us            10
                      aten::zero_         0.01%       7.000us         0.01%       7.000us       0.700us            10
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
Self CPU time total: 100.155ms

---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
                             Name    Self CPU %      Self CPU   CPU total %     CPU total  CPU time avg    # of Calls
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
           quantized::conv2d_relu        38.54%      38.421ms        40.40%      40.272ms     122.036us           330
                    ProfilerStep*        30.00%      29.906ms        99.96%      99.654ms       9.965ms            10
                quantized::conv2d        21.72%      21.649ms        22.52%      22.446ms     112.230us           200
              quantized::add_relu         4.43%       4.412ms         4.96%       4.942ms      30.887us           160
    aten::_empty_affine_quantized         1.98%       1.969ms         1.98%       1.969ms       2.735us           720
                      aten::empty         0.66%     659.000us         0.66%     659.000us       1.156us           570
       aten::quantized_max_pool2d         0.59%     589.000us         0.61%     607.000us      60.700us            10
                quantized::linear         0.45%     450.000us         0.50%     497.000us      49.700us            10
                       aten::item         0.31%     305.000us         0.46%     458.000us       1.347us           340
                    aten::q_scale         0.29%     294.000us         0.29%     294.000us       0.278us          1059
               aten::q_zero_point         0.23%     228.000us         0.23%     228.000us       0.215us          1060
        aten::quantize_per_tensor         0.18%     177.000us         0.20%     200.000us      20.000us            10
       aten::_adaptive_avg_pool2d         0.17%     168.000us         0.19%     187.000us      18.700us            10
        aten::_local_scalar_dense         0.15%     153.000us         0.15%     153.000us       0.450us           340
                    aten::qscheme         0.12%     124.000us         0.12%     124.000us       0.279us           445
                 aten::dequantize         0.05%      50.000us         0.06%      64.000us       6.400us            10
             aten::_reshape_alias         0.03%      32.000us         0.03%      32.000us       3.200us            10
                      aten::zeros         0.02%      24.000us         0.04%      35.000us       3.500us            10
                    aten::flatten         0.02%      23.000us         0.06%      55.000us       5.500us            10
                    aten::resize_         0.02%      19.000us         0.02%      19.000us       1.900us            10
        aten::adaptive_avg_pool2d         0.02%      17.000us         0.20%     204.000us      20.400us            10
                 aten::max_pool2d         0.02%      16.000us         0.62%     623.000us      62.300us            10
                      aten::zero_         0.00%       4.000us         0.00%       4.000us       0.400us            10
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
Self CPU time total: 99.689ms

-----------------  ------------  ------------  ------------  ------------  ------------  ------------
             Name    Self CPU %      Self CPU   CPU total %     CPU total  CPU time avg    # of Calls
-----------------  ------------  ------------  ------------  ------------  ------------  ------------
    ProfilerStep*        50.00%       8.000us        56.25%       9.000us       9.000us             1
      aten::zeros        31.25%       5.000us        43.75%       7.000us       7.000us             1
      aten::empty        12.50%       2.000us        12.50%       2.000us       1.000us             2
      aten::zero_         6.25%       1.000us         6.25%       1.000us       1.000us             1
-----------------  ------------  ------------  ------------  ------------  ------------  ------------
Self CPU time total: 16.000us

not using schedule method
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
                             Name    Self CPU %      Self CPU   CPU total %     CPU total  CPU time avg    # of Calls
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
           quantized::conv2d_relu        55.26%     384.850ms        57.89%     403.138ms     122.163us          3300
                quantized::conv2d        30.90%     215.170ms        32.07%     223.334ms     111.667us          2000
              quantized::add_relu         6.42%      44.699ms         7.16%      49.828ms      31.142us          1600
    aten::_empty_affine_quantized         2.79%      19.419ms         2.79%      19.419ms       2.697us          7200
                      aten::empty         0.95%       6.650ms         0.95%       6.650ms       1.209us          5500
       aten::quantized_max_pool2d         0.80%       5.603ms         0.83%       5.798ms      57.980us           100
                quantized::linear         0.63%       4.380ms         0.70%       4.862ms      48.620us           100
                    aten::q_scale         0.45%       3.136ms         0.45%       3.136ms       0.296us         10593
                       aten::item         0.42%       2.959ms         0.64%       4.488ms       1.320us          3400
               aten::q_zero_point         0.29%       2.008ms         0.29%       2.008ms       0.190us         10594
       aten::_adaptive_avg_pool2d         0.24%       1.654ms         0.26%       1.839ms      18.390us           100
        aten::quantize_per_tensor         0.24%       1.648ms         0.27%       1.871ms      18.710us           100
        aten::_local_scalar_dense         0.22%       1.529ms         0.22%       1.529ms       0.450us          3400
                    aten::qscheme         0.17%       1.169ms         0.17%       1.169ms       0.262us          4470
                 aten::dequantize         0.07%     495.000us         0.09%     619.000us       6.190us           100
             aten::_reshape_alias         0.05%     326.000us         0.05%     326.000us       3.260us           100
                    aten::flatten         0.03%     223.000us         0.08%     549.000us       5.490us           100
                    aten::resize_         0.03%     185.000us         0.03%     185.000us       1.850us           100
        aten::adaptive_avg_pool2d         0.02%     152.000us         0.29%       1.991ms      19.910us           100
                 aten::max_pool2d         0.02%     149.000us         0.85%       5.947ms      59.470us           100
---------------------------------  ------------  ------------  ------------  ------------  ------------  ------------
Self CPU time total: 696.404ms
```

Testing on ICX CPU device.

### Versions

Collecting environment information...
PyTorch version: 1.12.0a0+git6fceada
Is debug build: False
CUDA used to build PyTorch: None
ROCM used to build PyTorch: N/A

OS: Ubuntu 20.04.3 LTS (x86_64)
GCC version: (Ubuntu 9.3.0-17ubuntu1~20.04) 9.3.0
Clang version: Could not collect
CMake version: version 3.22.1
Libc version: glibc-2.31

Python version: 3.8.12 (default, Oct 12 2021, 13:49:34)  [GCC 7.5.0] (64-bit runtime)
Python platform: Linux-5.11.0-27-generic-x86_64-with-glibc2.17
Is CUDA available: False
CUDA runtime version: No CUDA
GPU models and configuration: No CUDA
Nvidia driver version: No CUDA
cuDNN version: No CUDA
HIP runtime version: N/A
MIOpen runtime version: N/A
Is XNNPACK available: True

Versions of relevant libraries:
[pip3] numpy==1.21.2
[pip3] torch==1.12.0a0+git6fceada
[pip3] torchvision==0.13.0a0+fbc8ea4
[conda] mkl                       2022.0.1           h06a4308_117
[conda] mkl-include               2022.0.1           h06a4308_117
[conda] numpy                     1.21.2           py38hd8d4704_0
[conda] numpy-base                1.21.2           py38h2b8c604_0
[conda] torch                     1.12.0a0+git6fceada          pypi_0    pypi
[conda] torchvision               0.13.0a0+fbc8ea4          pypi_0    pypi


cc @ilia-cher @robieta @chaekit @gdankel @bitfort @ngimel @orionr @nbcsm @guotuofeng @guyang3532 @gaoteng-git