PyTorch Profiler built with Bazel doesn't produce GPU trace

[btian]

🐛 Bug

PyTorch profiler doesn't produce GPU trace when I build with bazel.

To Reproduce

Steps to reproduce the behavior:

1. Add Kineto to PyTorch bazel build

pytorch/BUILD.bazel

Add

    "-DUSE_KINETO",
    "-DEDGE_PROFILER_USE_KINETO",

to COMMON_COPTS

Add
"@libkineto//:libkineto",
under deps of cc_library caffe2 and torch

libkineto.BUILD

cc_library(
    name = "libkineto",
    srcs = glob(
        [
            "src/*.cpp",
            "src/*.h",
        ],
    ),
    hdrs = glob([
        "include/*.h",
        "src/*.tpp",
    ]),
    copts = [
        "-DKINETO_NAMESPACE=libkineto",
        "-DHAS_CUPTI",
    ],
    includes = [
        "include",
    ],
    deps = [
        "@cuda//:cuda_headers",
        "@cuda//:cupti",
        "@cuda//:cupti_headers",
        "@cuda//:nvperf_host",
        "@cuda//:nvperf_target",
        "@fmt",
    ],
)

1. Run example script https://github.com/pytorch/kineto/blob/main/tb_plugin/examples/resnet50_profiler_api.py

2. No GPU trace in Tensorboard

Expected behavior

GPU trace is produced (I managed to get the trace by running with pre-built PyTorch)

Environment

PyTorch version: 1.9.0
Is debug build: False
CUDA used to build PyTorch: 10.2
ROCM used to build PyTorch: N/A

OS: Ubuntu 18.04.6 LTS (x86_64)
GCC version: (Ubuntu 7.5.0-3ubuntu1~18.04) 7.5.0
Clang version: Could not collect
CMake version: Could not collect
Libc version: glibc-2.10

Python version: 3.7.3 | packaged by conda-forge | (default, Jul 1 2019, 21:52:21) [GCC 7.3.0] (64-bit runtime)
Python platform: Linux-5.4.0-1053-gcp-x86_64-with-debian-buster-sid
Is CUDA available: True
CUDA runtime version: Could not collect
GPU models and configuration:
GPU 0: Tesla T4
GPU 1: Tesla T4

Nvidia driver version: 460.73.01
cuDNN version: Could not collect
HIP runtime version: N/A
MIOpen runtime version: N/A

Additional context

cc @ilia-cher @robieta @chaekit @gdankel @bitfort @ngimel @orionr @nbcsm @guotuofeng @guyang3532 @gaoteng-git

[gdankel]

@btian can you please attach the broken trace file? The strange thing here is that you're getting GPU streams (7, 14 and 15), which I think means Kineto must be active. There might be some other build issue leading to different behavior? How do the two runs compare otherwise? Iteration times and GPU utilization from nvidia-smi looks the same on both?

[btian]

Uploaded broken trace file to https://drive.google.com/file/d/1bPwLhA8EBYN-ziU7Fms4eho70DKaG7Nf/view?usp=sharing

Indeed Kineto is active, and I checked that PyTorch was not using KINETO_GPU_FALLBACK.

Iteration times and GPU utilization from nvidia-smi look the same.

[gdankel]

Thanks Bo. Json contains a ton of GPU events. Next step: figure out why they don't appear.

[btian]

Thanks for looking, Gisle.

I wrote a small C++ program that just uses libkineto, and still manage to replicate a bad trace - https://drive.google.com/file/d/1BRmiTUcfP3cpZynO5O2GOUZ_oqNxNhEO/view?usp=sharing

There are some garbage values in the JSON trace

"blocks per SM": -4096,
      "warps per SM": -32768,
      "grid": [4096, 1, 1],
      "block": [256, 1, 1],
      "est. achieved occupancy %": -102399

I also saw errors in libkineto

Starting profiling program...Log file: /tmp/libkineto_activities_7445.json
Net filter: 
Target net for iteration count: 
Net Iterations: 3
Trace duration: 500ms
Warmup duration: 5s
Net size threshold: 0
GPU op count threshold: 0
Max GPU buffer size: 128MB
Enabled activities: cpu_op gpu_memcpy gpu_memset concurrent_kernel external_correlation cuda_runtime 
INFO:2021-11-17 17:05:15 7445:7445 ActivityProfiler.cpp:475] GPU-only tracing for 500ms
INFO:2021-11-17 17:05:15 7445:7445 ActivityProfiler.cpp:497] Enabling GPU tracing
INFO:2021-11-17 17:05:15 7445:7445 ActivityProfiler.cpp:518] Tracing starting in 5s
INFO:2021-11-17 17:05:15 7445:7445 ActivityProfiler.cpp:124] Processing 0 CPU buffers
INFO:2021-11-17 17:05:15 7445:7445 ActivityProfiler.cpp:155] Processed 16 GPU records (888 bytes)
INFO:2021-11-17 17:05:15 7445:7445 ActivityProfiler.cpp:658] Recorded nets:
Stopped and processed trace. Got 14 activities.WARNING:2021-11-17 17:05:15 7445:7445 CuptiActivityInterface.cpp:67] function cuptiDeviceGetNumEventDomains(0, &domainCount) failed with error CUPTI_ERROR_LEGACY_PROFILER_NOT_SUPPORTED (38)
WARNING:2021-11-17 17:05:15 7445:7445 CuptiActivityInterface.cpp:70] function cuptiDeviceEnumEventDomains(0, &sz, ids.data()) failed with error CUPTI_ERROR_LEGACY_PROFILER_NOT_SUPPORTED (38)
INFO:2021-11-17 17:05:15 7445:7445 output_json.cpp:60] Tracing to /tmp/kineto_trace.json
INFO:2021-11-17 17:05:15 7445:7445 output_json.cpp:496] Chrome Trace written to /tmp/kineto_trace.json

[btian]

I wonder if the reason why CUDA kernel traces don't appear is due to a huge difference in timestamp between CUDA kernels and CPU, e.g.,

{
    "ph": "X", "cat": "Kernel", 
    "name": "cudnn::gemm::computeOffsetsKernel(cudnn::gemm::ComputeOffsetsParams)", "pid": 0, "tid": "stream 7",
    "ts": 1635202069792700, "dur": 4,
    "args": {
      "queued": 0, "device": 0, "context": 1,
      "stream": 7, "correlation": 34, "external id": 0,
      "registers per thread": 16,
      "shared memory": 0,
      "blocks per SM": -99,
      "warps per SM": -396,
      "grid": [99, 1, 1],
      "block": [128, 1, 1],
      "est. achieved occupancy %": -1237
    }
  },

But for CPU operators:

  {
    "ph": "X", "cat": "Operator", 
    "name": "ProfilerStep#10", "pid": 31383, "tid": "31383",
    "ts": 4687921561, "dur": 292460,
    "args": {
      "Device": 31383, "External id": 19719,
      "Trace name": "PyTorch Profiler", "Trace iteration": 0 
      
    }
  },

1635202069792700 vs 4687921561.

It feels like the ts for kernels are correct, but totally wrong for CPU operators.

[btian]

I believe I found the issue.

Profiler started working when I changed high_resolution_clock to system_clock here https://github.com/pytorch/pytorch/blob/v1.9.1/torch/csrc/autograd/profiler_kineto.cpp#L35

[sraikund16]

Stale issue, no longer relevant