如何优雅地测量GPU CUDA Kernel耗时？

背景

Rainlin：如何优雅地测量GPU CUDA Kernel耗时？（一）中介绍了常用的测量gpu耗时方法，而实际应用中，还会遇到其他的问题，比如：

1. 为什么同样的输入，测量的耗时存在较大差距？
2. 怎样才能精确的测量kernel耗时？

问题

我们看以下常见代码，仅仅做了linear操作：

def test():  
    a_size = (20, 8192)  
    b_size = (5120, 8192)  
    events = [  
        [torch.cuda.Event(enable_timing=True) for _ in range(6)] for _ in range(50)  
    ]  
  
    # warm up  
    for _ in range(10):  
        a = torch.rand(a_size, dtype=torch.float16).cuda()  
        b = torch.rand(  
            b_size,  
            dtype=torch.float16,  
        ).cuda()  
        c = F.linear(a, b)  
  
    # 测量  
    for i in range(10):  
        a = torch.rand(a_size, dtype=torch.float16).cuda()  
        b = torch.rand(b_size, dtype=torch.float16).cuda()  
  
        events[i][0].record()  
        c = F.linear(a, b)  
        events[i][1].record()  
  
        events[i][2].record()  
        c = F.linear(a, b)  
        events[i][3].record()  
  
        events[i][4].record()  
        c = F.linear(a, b)  
        events[i][5].record()  
    torch.cuda.synchronize()  
  
    # 输出时间  
    for i in range(5):  
        print(  
            f"{i}: t1:{events[i][0].elapsed_time(events[i][1])},t2:{events[i][2].elapsed_time(events[i][3])},t3:{events[i][4].elapsed_time(events[i][5])}"  
        )  
    torch.cuda.synchronize()  
  
  
if __name__ == "__main__":  
    test()  

以上代码在A100上输出为：

可以看到，t1耗时远大于t2与t3，显然这不合理，同样的输入，计算时间不可能相差这么多，接下来我们逐步分析。

为什么同样的输入，kernel的耗时相差巨大？

我们先对以上代码进行nsys分析：

观察到：三次linear在kernel层面只有60us+，但torch.cuda.event测量与nsys没对齐，第一次远大于kernel运行的时间。 推测第一次torch.cuda.event测量的耗时并非kernel的耗时，应该包含了其他部分的耗时。

观察到代码：

a = torch.rand(a_size, dtype=torch.float16).cuda()  
       b = torch.rand(b_size, dtype=torch.float16).cuda()  

这里存在cpu数据拷贝到gpu，猜测torch.cuda.event把拷贝的时间也算进去了，那我们去掉拷贝试试：

.....  
   
for i in range(10):  
        # 改成直接从GPU生成rand数据，而不是拷贝  
        a = torch.rand(a_size, dtype=torch.float16, device="cuda")  
        b = torch.rand(b_size, dtype=torch.float16, device="cuda")  
          
        events[i][0].record()  
        c = F.linear(a, b)  
        events[i][1].record()  
  
        events[i][2].record()  
        c = F.linear(a, b)  
        events[i][3].record()  
  
        events[i][4].record()  
        c = F.linear(a, b)  
        events[i][5].record()  
.....  

测量结果为

果然第一次的torch.cuda.event的正常了不少，但发现第1次还是比第2、3次大，观察nsys的时间：

从nsys看，第1次linear是67us，而第2次kernel耗时是60us，第1次的确大于第2次耗时，由于两次运算是同样的数据，猜测是由于GPU缓存导致，可以尝试清空缓存：

fc = torch.empty(int(40 * (1024**2)), dtype=torch.int8, device="cuda")  
  
  
def flush_cache():  
    fc.zero_()  
  
  
...  
    for i in range(10):  
        a = torch.rand(a_size, dtype=torch.float16, device="cuda")  
        b = torch.rand(b_size, dtype=torch.float16, device="cuda")  
          
        flush_cache()  
        events[i][0].record()  
        c = F.linear(a, b)  
        events[i][1].record()  
          
        flush_cache()  
        events[i][2].record()  
        c = F.linear(a, b)  
        events[i][3].record()  
          
        flush_cache()  
        events[i][4].record()  
        c = F.linear(a, b)  
        events[i][5].record()  
...  

再次运行，结果为：

nsys结果为：

可以发现此时3个计算kernel的耗时基本一致，说明缓存的确影响了kernel的耗时。

除此之外，影响耗时的原因还可能是GPU频率的变化，可以通过以下代码进行设置频率：

DEVICE = os.environ.get("CUDA_VISIBLE_DEVICES")  
CLOCK_SPEED = 1350  # Must choose a clock speed that's supported on your device.  
  
  
def set_clock_speed():  
    """  
    Set GPU clock speed to a specific value.  
    This doesn't guarantee a fixed value due to throttling, but can help reduce variance.  
    """  
    process = subprocess.Popen("nvidia-smi", stdout=subprocess.PIPE, shell=True)  
    stdout, _ = process.communicate()  
    process = subprocess.run(f"nvidia-smi -pm ENABLED -i {DEVICE}", shell=True)  
    process = subprocess.run(f"nvidia-smi -lgc {CLOCK_SPEED} -i {DEVICE}", shell=True)  
  
  
def reset_clock_speed():  
    """  
    Reset GPU clock speed to default values.  
    """  
    subprocess.run(f"nvidia-smi -pm ENABLED -i {DEVICE}", shell=True)  
    subprocess.run(f"nvidia-smi -rgc -i {DEVICE}", shell=True)  

以上代码是将GPU频率锁定到指定值上，可自行尝试不同频率下的耗时情况。

结论

根据以上分析，同样的输入，测量kernel耗时不同的原因，有以下可能：

1. torch.cuda.event测量的时间包含了其他过程，不只是kernel本身
2. kernel运行时存在命中缓存，导致时间变短
3. GPU频率存在变化，当频率不同时，kernel的时间也会变化

一些建议

1. 从以上示例来看，torch.cuda.event在统计并非与kernel绑定，而是两个时间点之差。在使用时，要注意是否存在其他流程影响了统计的时间点。如果要观察kernel的耗时，建议直接使用nsys更为准确和直观。
   
   

参考

1. How to Accurately Time CUDA Kernels in Pytorch | Speechmatics