项目链接，fork 一下即可使用https://aistudio.baidu.com/aistudio/projectdetail/4482932?contributionType=1
Paddle 模型性能分析 Profiler：定位性能瓶颈点优化程序提升性能
Paddle Profiler 是飞桨框架自带的低开销性能分析器，可以对模型运行过程的性能数据进行收集、统计和展示。性能分析器提供的数据可以帮助定位模型的瓶颈，识别造成程序运行时间过长或者 GPU 利用率低的原因，从而寻求优化方案来获得性能的提升。
1.使用 Profiler 工具调试程序性能
在模型性能分析中，通常采用如下四个步骤：
下面是使用神经网络对 cifar10 进行分类的示例代码，里面加上了启动性能分析的代码。通过这个比较简单的示例，来看性能分析工具是如何通过上述四个步骤在调试程序性能中发挥作用。
1.1 使用 cifar10 数据集卷积神经网络进行图像分类
import paddleimport paddle.nn.functional as Ffrom paddle.vision.transforms import ToTensorimport numpy as npimport matplotlib.pyplot as plt
print(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.001
val_acc_history = []val_loss_history = []
def train(model): print('start training ... ') # turn into training mode model.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个step for 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() # 指示性能分析器进入下一个step if batch_id == 19: p.stop() # 关闭性能分析器 exit() # 做性能分析时，可以将程序提前退出
# evaluate model after one epoch model.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(%) --------------- ------ ---------------------------------------- ---------------------------------------- ProfileStep 11 138.99 / 12.64 / 17.91 / 10.65 / 100.00 8.81 / 0.80 / 0.80 / 0.80 / 100.00 Dataloader 11 16.88 / 1.53 / 6.91 / 0.09 / 12.14 0.00 / 0.00 / 0.00 / 0.00 / 0.00 Forward 11 45.18 / 4.11 / 4.41 / 3.61 / 32.50 2.73 / 0.25 / 0.25 / 0.25 / 31.01 Backward 11 27.63 / 2.51 / 2.85 / 2.37 / 19.88 4.04 / 0.37 / 0.37 / 0.36 / 45.81 Optimization 11 19.75 / 1.80 / 1.89 / 1.61 / 14.21 1.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 batch_id, data in enumerate(train_loader())的执行时间；
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(%) --------------- ------ ---------------------------------------- ---------------------------------------- ProfileStep 11 89.44 / 8.13 / 8.76 / 7.82 / 100.00 8.82 / 0.80 / 0.80 / 0.80 / 100.00 Dataloader 11 1.51 / 0.14 / 0.16 / 0.12 / 1.69 0.00 / 0.00 / 0.00 / 0.00 / 0.00 Forward 11 31.67 / 2.88 / 3.17 / 2.82 / 35.41 2.72 / 0.25 / 0.25 / 0.24 / 36.11 Backward 11 25.35 / 2.30 / 2.49 / 2.20 / 28.34 4.07 / 0.37 / 0.37 / 0.37 / 42.52 Optimization 11 11.67 / 1.06 / 1.16 / 1.01 / 13.04 1.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 |
复制代码
<font size=3 color="red">此时从原来的 Reader Ratio: 35.240%---->Reader Ratio: 1.718%
ips 的值变成了 137.3，相比优化前的 baseline70.99，模型真实性能提升了 193%。
</font>
<font size=3 color="blue">注意点：</font>
由于 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------------------------------------------------- -------------------- Device Utilization (%) ------------------------------ -------------------- CPU(Process) 77.13 CPU(System) 25.99 GPU2 55.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 Calls CPU Time Ratio (%) ------------------------- ------------------------- ------------------------- ------------------------- ProfileStep 8 4945.15 100.00 CudaRuntime 28336 2435.63 49.25 UserDefined 486 2280.54 46.12 Dataloader 8 1819.15 36.79 Forward 8 1282.64 25.94 Operator 8056 1244.41 25.16 OperatorInner 21880 374.18 7.57 Backward 8 160.43 3.24 Optimization 8 102.34 2.07 ------------------------- ------------------------- ------------------------- ------------------------- Calls GPU Time Ratio (%) ------------------------- ------------------------- ------------------------- ------------------------- Kernel 13688 2744.61 55.50 Memcpy 496 29.82 0.60 Memset 104 0.12 0.00 Communication 784 257.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
评论