I am trying to profile my model with pytorch profiler. I used the below code to profile
with profile(activities=[ProfilerActivity.CPU, ProfilerActivity.CUDA], record_shapes=True) as prof:
with record_function("model_inference"):
output_batch = self.model(input_batch)
print(prof.key_averages().table(sort_by="cpu_time_total", row_limit=10))
The profiler output is as follows
------------------------------------------------------- ------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------
Name Self CPU % Self CPU CPU total % CPU total CPU time avg Self CUDA Self CUDA % CUDA total CUDA time avg # of Calls
------------------------------------------------------- ------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------
model_inference 3.17% 83.011ms 63.97% 1.675s 1.675s 0.000us 0.00% 373.844ms 373.844ms 1
aten::copy_ 0.24% 6.333ms 39.93% 1.046s 1.504ms 28.758ms 7.69% 29.035ms 41.777us 695
cudaHostAlloc 36.02% 943.053ms 36.02% 943.053ms 30.421ms 0.000us 0.00% 0.000us 0.000us 31
cudaLaunchKernel 35.93% 940.773ms 35.93% 940.773ms 86.619us 0.000us 0.00% 0.000us 0.000us 10861
aten::repeat 0.04% 979.000us 33.77% 884.170ms 30.489ms 0.000us 0.00% 204.000us 7.034us 29
aten::conv2d 0.06% 1.481ms 8.71% 228.183ms 695.680us 0.000us 0.00% 145.688ms 444.171us 328
aten::convolution 0.05% 1.391ms 8.66% 226.702ms 691.165us 0.000us 0.00% 145.688ms 444.171us 328
aten::_convolution 0.10% 2.742ms 8.61% 225.311ms 686.924us 0.000us 0.00% 145.688ms 444.171us 328
aten::cudnn_convolution 0.53% 13.803ms 8.33% 218.051ms 664.790us 137.822ms 36.87% 137.822ms 420.189us 328
cudaFree 7.46% 195.373ms 7.46% 195.373ms 48.843ms 0.000us 0.00% 0.000us 0.000us 4
------------------------------------------------------- ------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------ ------------
Self CPU time total: 2.618s
Self CUDA time total: 373.844ms
I notice that a large part of the time (self CPU) is taken by cudaHostAlloc and cudaLaunchKernel. What are these cudaHostAlloc and cudaLaunchKernel? Is it possible to reduce this time? If yes how? Are there any standard operations that I'm missing which is leading to this high time consumption?
PS: I'm new to profiling as such. Kindly let me know if any other information is needed.
I am not an expert but I think cudaLaunchKernel is called at every operation done with cuda. So I think you cannot optimize it.
If you plot a detailed tracing https://pytorch.org/tutorials/recipes/recipes/profiler_recipe.html#using-tracing-functionality, you see that it is called everytime you do a cuda operation like here for a linear layer.

One note on you profiler output: aten::copy_ cudaHostAlloc cudaLaunchKernel and aten::repeat all take roughly 40% of the CPU total time. I think it may be related to ProfilerActivity.CUDA that records CUDA operation but it also add a lot of CPU time on your first CUDA operation that is profiled. In my case a simple torch.ones(1000, device="cuda") took a full second of CPU time because it was the first cuda operation.
It may be the problem in your case, try to remove ProfilerActivity.CUDA and maybe aten::copy_ cudaHostAlloc cudaLaunchKernel and aten::repeat will have a much smaller CPU time and will disappear from the table.
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With