项目链接，fork一下即可使用 https://aistudio.baidu.com/aistudio/projectdetail/4482932?contributionType=1
Paddle模型性能分析Profiler：定位性能瓶颈点优化程序提升性能
Paddle Profiler是飞桨框架自带的低开销性能分析器，可以对模型运行过程的性能数据进行收集、统计和展示。性能分析器提供的数据可以帮助定位模型的瓶颈，识别造成程序运行时间过长或者GPU利用率低的原因，从而寻求优化方案来获得性能的提升。
1.使用Profiler工具调试程序性能
在模型性能分析中，通常采用如下四个步骤：
- 获取模型正常运行时的ips(iterations per second， 每秒的迭代次数)，给出baseline数据。
- 开启性能分析器，定位性能瓶颈点。
- 优化程序，检查优化效果。
- 获取优化后模型正常运行时的ips，和baseline比较，计算真实的提升幅度。
下面是使用神经网络对cifar10进行分类的示例代码，里面加上了启动性能分析的代码。通过这个比较简单的示例，来看性能分析工具是如何通过上述四个步骤在调试程序性能中发挥作用。
1.1 使用cifar10数据集卷积神经网络进行图像分类
import paddleimport paddle.nn.functional as Ffrom paddle.vision.transforms import ToTensorimport numpy as npimport matplotlib.pyplot as pltprint(paddle.__version__)
加载数据集
cifar10数据集由60000张大小为32 * 32的彩色图片组成，其中有50000张图片组成了训练集，另外10000张图片组成了测试集。这些图片分为10个类别，将训练一个模型能够把图片进行正确的分类。
transform = ToTensor()cifar10_train = paddle.vision.datasets.Cifar10(mode=’train’, transform=transform)cifar10_test = paddle.vision.datasets.Cifar10(mode=’test’,transform=transform)
组建网络
接下来使用飞桨定义一个使用了三个二维卷积（ Conv2D ) 且每次卷积之后使用 relu 激活函数，两个二维池化层（ MaxPool2D ），和两个线性变换层组成的分类网络，来把一个(32, 32, 3)形状的图片通过卷积神经网络映射为10个输出，这对应着10个分类的类别
class MyNet(paddle.nn.Layer):def __init__(self, num_classes=1):super(MyNet, self).__init__()self.conv1 = paddle.nn.Conv2D(in_channels=3, out_channels=32, kernel_size=(3, 3))self.pool1 = paddle.nn.MaxPool2D(kernel_size=2, stride=2)self.conv2 = paddle.nn.Conv2D(in_channels=32, out_channels=64, kernel_size=(3,3))self.pool2 = paddle.nn.MaxPool2D(kernel_size=2, stride=2)self.conv3 = paddle.nn.Conv2D(in_channels=64, out_channels=64, kernel_size=(3,3))self.flatten = paddle.nn.Flatten()self.linear1 = paddle.nn.Linear(in_features=1024, out_features=64)self.linear2 = paddle.nn.Linear(in_features=64, out_features=num_classes)def forward(self, x):x = self.conv1(x)x = F.relu(x)x = self.pool1(x)x = self.conv2(x)x = F.relu(x)x = self.pool2(x)x = self.conv3(x)x = F.relu(x)x = self.flatten(x)x = self.linear1(x)x = F.relu(x)x = self.linear2(x)return x
模型训练&预测
接下来，用一个循环来进行模型的训练，将会:
使用 paddle.optimizer.Adam 优化器来进行优化。
使用 F.cross_entropy 来计算损失值。
使用 paddle.io.DataLoader 来加载数据并组建batch。
import paddle.profiler as profiler#参数设置epoch_num = 10batch_size = 32learning_rate = 0.001val_acc_history = []val_loss_history = []def train(model):print(‘start training … ‘)# turn into training modemodel.train()opt = paddle.optimizer.Adam(learning_rate=learning_rate,parameters=model.parameters())train_loader = paddle.io.DataLoader(cifar10_train,shuffle=True,batch_size=batch_size,num_workers=4)valid_loader = paddle.io.DataLoader(cifar10_test, batch_size=batch_size)# 创建性能分析器相关的代码def my_on_trace_ready(prof):# 定义回调函数，性能分析器结束采集数据时会被调用callback = profiler.export_chrome_tracing(‘./profiler_demo’) # 创建导出性能数据到profiler_demo文件夹的回调函数callback(prof)# 执行该导出函数prof.summary(sorted_by=profiler.SortedKeys.GPUTotal) # 打印表单，按GPUTotal排序表单项p = profiler.Profiler(scheduler = [3,14], on_trace_ready=my_on_trace_ready, timer_only=True) # 初始化Profiler对象p.start() # 性能分析器进入第0个stepfor epoch in range(epoch_num):for batch_id, data in enumerate(train_loader()):x_data = data[0]y_data = paddle.to_tensor(data[1])y_data = paddle.unsqueeze(y_data, 1)logits = model(x_data)loss = F.cross_entropy(logits, y_data)if batch_id % 1000 == 0:print(“epoch: {}, batch_id: {}, loss is: {}”.format(epoch, batch_id, loss.numpy()))loss.backward()opt.step()opt.clear_grad()p.step() # 指示性能分析器进入下一个stepif batch_id == 19:p.stop() # 关闭性能分析器exit() # 做性能分析时，可以将程序提前退出# evaluate model after one epochmodel.eval()accuracies = []losses = []for batch_id, data in enumerate(valid_loader()):x_data = data[0]y_data = paddle.to_tensor(data[1])y_data = paddle.unsqueeze(y_data, 1)logits = model(x_data)loss = F.cross_entropy(logits, y_data)acc = paddle.metric.accuracy(logits, y_data)accuracies.append(acc.numpy())losses.append(loss.numpy())avg_acc, avg_loss = np.mean(accuracies), np.mean(losses)print(“[validation] accuracy/loss: {}/{}”.format(avg_acc, avg_loss))val_acc_history.append(avg_acc)val_loss_history.append(avg_loss)model.train()model = MyNet(num_classes=10)train(model)**部分结果展示：**epoch: 6, batch_id: 0, loss is: [0.91811454]epoch: 6, batch_id: 1000, loss is: [0.89851004][validation] accuracy/loss: 0.7232428193092346/0.8434960246086121epoch: 7, batch_id: 0, loss is: [0.60690844]epoch: 7, batch_id: 1000, loss is: [0.6912922][validation] accuracy/loss: 0.7049720287322998/0.887704074382782epoch: 8, batch_id: 0, loss is: [0.6330824]epoch: 8, batch_id: 1000, loss is: [0.5715592][validation] accuracy/loss: 0.7176517844200134/0.8511289954185486epoch: 9, batch_id: 0, loss is: [0.29487646]epoch: 9, batch_id: 1000, loss is: [0.9094696][validation] accuracy/loss: 0.7097643613815308/0.9166476130485535
1.1.1 获取性能调试前模型正常运行的ips
上述程序在创建Profiler时候，timer_only设置的值为True，此时将只开启benchmark功能，不开启性能分析器，程序输出模型正常运行时的benchmark信息如下
- Reader Ratio：表示数据读取部分占训练batch迭代过程的时间占比，
- reader_cost：代表数据读取时间，
- batch_cost：代表batch迭代的时间，
- ips：表示每秒能迭代多少次，即跑多少个batch。
可以看到，此时的ips为70.99，可将这个值作为优化对比的baseline。
============================================Perf Summary============================================ Reader Ratio: 35.240% Time Unit: s, IPS Unit: steps/s| | avg | max | min | | reader_cost | 0.00496 | 0.00542 | 0.00469 ||batch_cost | 0.01408 | 0.01325 | 0.01246 | | ips | 70.99914| 80.24470| 75.46403|
1.1.2. 开启性能分析器，定位性能瓶颈点
修改程序，将Profiler的timer_only参数设置为False， 此时代表不只开启benchmark功能，还将开启性能分析器，进行详细的性能分析。
p = profiler.Profiler(scheduler = [3,14], on_trace_ready=my_on_trace_ready, timer_only=False)
性能分析器会收集程序在第3到14次（不包括14）训练迭代过程中的性能数据，并在profiler_demo文件夹中输出一个json格式的文件，用于展示程序执行过程的timeline，可通过chrome浏览器的chrome://tracing 插件打开这个文件进行查看。
如图所示，把json文件load即可：
性能分析器还会直接在终端打印统计表单（建议重定向到文件中查看），查看程序输出的Model Summary表单
———————————————–Model Summary———————————————–Time unit: ms—————————————————————————————————–Name Calls CPU Total / Avg / Max / Min / Ratio(%)GPU Total / Avg / Max / Min / Ratio(%)—————————————————————————————————–ProfileStep11138.99 / 12.64 / 17.91 / 10.65 / 100.00 8.81 / 0.80 / 0.80 / 0.80 / 100.00Dataloader 1116.88 / 1.53 / 6.91 / 0.09 / 12.140.00 / 0.00 / 0.00 / 0.00 / 0.00Forward1145.18 / 4.11 / 4.41 / 3.61 / 32.502.73 / 0.25 / 0.25 / 0.25 / 31.01 Backward 1127.63 / 2.51 / 2.85 / 2.37 / 19.884.04 / 0.37 / 0.37 / 0.36 / 45.81 Optimization 1119.75 / 1.80 / 1.89 / 1.61 / 14.211.05 / 0.10 / 0.10 / 0.09 / 11.56 Others – 29.55 / – / – / – / 21.26 1.05 / – / – / – / 11.63—————————————————————————————————–Note:在此表中，GPU 时间是该阶段调用的所有设备（GPU）事件的总和。与概述摘要不同，如果两个设备（GPU）事件在不同的流上执行重叠时间，我们直接在这里求和。
- 其中ProfileStep表示训练batch的迭代step过程，对应代码中每两次调用p.step()的间隔时间；
- Dataloader表示数据读取的时间，即for batchid, data in enumerate(trainloader())的执行时间；
- Forward表示模型前向的时间，即logits = model(x_data)的执行时间，
- Backward表示反向传播的时间，即loss.backward()的执行时间；
- Optimization表示优化器的时间，即opt.step()的执行时间。
通过timeline可以看到，Dataloader占了执行过程的很大比重，Model Summary显示其接近了12%。分析程序发现，这是由于模型本身比较简单，需要的计算量小，再加上Dataloader 准备数据时只用了单进程来读取，使得程序读取数据时和执行计算时没有并行操作，导致Dataloader占比过大。
1.1.3. 优化程序，检查优化效果
识别到了问题产生的原因，对程序继续做如下修改，将Dataloader的num_workers设置为4，使得能有多个进程并行读取数据。
train_loader = paddle.io.DataLoader(cifar10_train,shuffle=True,batch_size=batch_size,num_workers=4)
重新对程序进行性能分析，新的timeline和Model Summary如下所示
———————————————–Model Summary———————————————–Time unit: ms—————————————————————————————————–Name Calls CPU Total / Avg / Max / Min / Ratio(%)GPU Total / Avg / Max / Min / Ratio(%)—————————————————————————————————–ProfileStep1189.44 / 8.13 / 8.76 / 7.82 / 100.00 8.82 / 0.80 / 0.80 / 0.80 / 100.00Dataloader 111.51 / 0.14 / 0.16 / 0.12 / 1.690.00 / 0.00 / 0.00 / 0.00 / 0.00Forward1131.67 / 2.88 / 3.17 / 2.82 / 35.412.72 / 0.25 / 0.25 / 0.24 / 36.11 Backward 1125.35 / 2.30 / 2.49 / 2.20 / 28.344.07 / 0.37 / 0.37 / 0.37 / 42.52 Optimization 1111.67 / 1.06 / 1.16 / 1.01 / 13.041.04 / 0.09 / 0.10 / 0.09 / 10.59 Others – 19.25 / – / – / – / 21.52 1.06 / – / – / – / 10.78—————————————————————————————————–
可以看到，从Dataloader中取数据的时间大大减少，从12%变成了平均只占一个step的1.69%，并且平均一个step所需要的时间也相应减少了从1.53到0.14。
### 1.1.4 获取优化后模型正常运行的ips，确定真实提升幅度重新将timer_only设置的值为True，获取优化后模型正常运行时的benchmark信息============================================Perf Summary============================================Reader Ratio: 1.718%Time Unit: s, IPS Unit: steps/s| | avg | max | min || reader_cost | 0.00013 | 0.00015 | 0.00012 ||batch_cost | 0.00728 | 0.00690 | 0.00633 || ips |137.30879|158.01126|144.91796|
此时从原来的Reader Ratio: 35.240%—->Reader Ratio: 1.718%
ips的值变成了137.3，相比优化前的baseline70.99，模型真实性能提升了193%。
注意点：
由于Profiler开启的时候，收集性能数据本身也会造成程序性能的开销，因此正常跑程序时请不要开启性能分析器，性能分析器只作为调试程序性能时使用。
- 1.如果想获得程序正常运行时候的 benchmark信息（如ips），可以像示例一样将Profiler的timer_only参数设置为True，此时不会进行详尽的性能数据收集，几乎不影响程序正常运行的性能，所获得的benchmark信息也趋于真实。
- 2.benchmark信息计算的数据范围是从调用Profiler的start方法开始，到调用stop方法结束这个过程的数据。而Timeline和性能数据的统计表单的数据范围是所指定的采集区间，如这个例子中的第3到14次迭代，这会导致开启性能分析器时统计表单和benchmark信息输出的值不同（如统计到的Dataloader的时间占比）。
- 3.当benchmark统计的范围和性能分析器统计的范围不同时， 由于benchmark统计的是平均时间，如果benchmark统计的范围覆盖了性能分析器开启的范围，也覆盖了关闭性能调试时的正常执行的范围，此时benchmark的值没有意义，因此开启性能分析器时请以性能分析器输出的统计表单为参考，这也是为何上面示例里在开启性能分析器时没贴benchmark信息的原因。
1.1.5 结果展示
#结果展示plt.plot(val_acc_history, label = ‘validation accuracy’)plt.xlabel(‘Epoch’)plt.ylabel(‘Accuracy’)plt.ylim([0.5, 0.8])plt.legend(loc=’lower right’)
2.2 统计表单展示
统计表单负责对采集到的数据(Event)从多个不同的角度进行解读，也可以理解为对timeline进行一些量化的指标计算。 目前提供Device Summary、Overview Summary、Model Summary、Distributed Summary、Operator Summary、Kernel Summary、Memory Manipulation Summary和UserDefined Summary的统计表单，每个表单从不同的角度进行统计计算。每个表单的统计内容简要叙述如下：
Device Summary
——————-Device Summary———————————————————————DeviceUtilization (%)————————————————–CPU(Process)77.13CPU(System) 25.99GPU255.50————————————————–Note:CPU(进程) 利用率 = 当前进程在所有 cpu 内核上的 CPU 时间/经过的时间，因此最大利用率可以达到 100% * cpu 内核数。CPU（系统）利用率=所有进程在所有cpu内核上的CPU时间（忙碌时间）/（忙碌时间+空闲时间）。GPU 利用率 = 当前进程 GPU 时间 / 已用时间。—————————————————-
DeviceSummary提供CPU和GPU的平均利用率信息。其中
CPU(Process): 指的是进程的cpu平均利用率，算的是从Profiler开始记录数据到结束这一段过程，进程所利用到的 cpu core的总时间与该段时间的占比。因此如果是多核的情况，对于进程来说cpu平均利用率是有可能超过100%的，因为同时用到的多个core的时间进行了累加。
CPU(System): 指的是整个系统的cpu平均利用率，算的是从Profiler开始记录数据到结束这一段过程，整个系统所有进程利用到的cpu core总时间与该段时间乘以cpu core的数量的占比。可以当成是从cpu的视角来算的利用率。
GPU: 指的是进程的gpu平均利用率，算的是从Profiler开始记录数据到结束这一段过程，进程在gpu上所调用的kernel的执行时间 与 该段时间 的占比。
Overview Summary
Overview Summary用于展示每种类型的Event一共分别消耗了多少时间，对于多线程或多stream下，如果同一类型的Event有重叠的时间段，采取取并集操作，不对重叠的时间进行重复计算。
———————————————Overview Summary———————————————Time unit: ms—————————————————————————————————-Event Type CallsCPU Time Ratio (%)—————————————————————————————————-ProfileStep84945.15100.00CudaRuntime283362435.6349.25UserDefined4862280.5446.12Dataloader 81819.1536.79Forward81282.6425.94Operator 8056 1244.4125.16OperatorInner21880374.18 7.57Backward 8160.43 3.24Optimization 8102.34 2.07—————————————————————————————————-CallsGPU Time Ratio (%)—————————————————————————————————-Kernel 136882744.6155.50Memcpy 49629.820.60Memset 1040.12 0.00Communication784257.23 5.20—————————————————————————————————-Note:在此表中，我们根据事件类型汇总了所有收集到的事件。在主机上收集的事件时间显示为 CPU 时间，如果在设备上则显示为 GPU 时间。不同类型的事件可能会重叠或包含，例如 Operator 包括 OperatorInner，因此比率之和不是 100%。有重叠的同类型事件的时间不会计算两次，合并后所有时间相加。Example:Thread 1:Operator: |___________| |__________|Thread 2:Operator: |____________| |___|After merged:Result: |______________||__________|———————————————————————————————————-
不在继续详细说明，参考项目即可：
项目链接，fork一下即可使用 https://aistudio.baidu.com/aistudio/projectdetail/4482932?contributionType=1
