Optimize inference performance of ERNIE on CPU

[tensor-tang]

负责人

@tensor-tang @GaoWei8

机器型号

6148

commit号

based on #164

初始性能

10个sample

I0820 10:33:36.597270 35686 inference.cc:211] Load 10 samples from /home/tangjian/ernie/Inference/c++/ernie/seq128_data/test_ds_10
I0820 10:33:37.552497 35686 inference.cc:351] Run 10 samples, average latency: 95.519 ms per sample.
I0820 10:33:37.552565 35686 inference.cc:356] Run 9 samples, average latency [exclude 1 warmup steps]: 89.8265 ms per sample.

profile 结果

Event                       Calls       Total       Min.        Max.        Ave.        Ratio.
thread0::fc                 740         625.813     0.013066    2.59008     0.845693    0.511826
thread0::load               202         269.789     0.009506    168.902     1.33559     0.220649
thread0::elementwise_add    380         78.8811     0.045364    29.1685     0.207582    0.0645135
thread0::transpose2         480         63.5249     0.089001    4.08297     0.132343    0.0519543
thread0::dropout            380         51.7229     0.01217     0.262424    0.136113    0.0423019
thread0::layer_norm         250         43.0832     0.150904    0.226994    0.172333    0.0352359
thread0::matmul             250         36.4239     0.033627    14.6704     0.145696    0.0297895
thread0::relu               120         22.7715     0.130891    1.77192     0.189762    0.0186238
thread0::scale              140         11.0508     0.006102    0.105016    0.0789342   0.00903797
thread0::softmax            120         9.73205     0.050275    0.451451    0.0811004   0.00795943
thread0::reshape2           480         4.47205     0.006964    0.022523    0.00931677  0.0036575
thread0::lookup_table       30          2.67894     0.074823    0.105928    0.089298    0.00219099
thread0::stack              10          1.43889     0.130984    0.154692    0.143889    0.00117681
thread0::tanh               10          0.986778    0.084346    0.191761    0.0986778   0.000807043
thread0::slice              10          0.12234     0.009367    0.033865    0.012234    0.000100057
thread0::feed               40          0.109835    0.001013    0.005219    0.00274588  8.98293e-05
thread0::fetch              10          0.106458    0.006874    0.011848    0.0106458   8.70674e-05

TODO

• 去掉load @tensor-tang，不会统计进预测时间，可以忽略
• dropout多线程 @GaoWei8
• fuse @intel

[tensor-tang]

全量结果

I0821 06:53:24.524538 37140 inference.cc:351] Run 5010 samples, average latency: 88.4711 ms per sample.
I0821 06:53:24.524575 37140 inference.cc:356] Run 5009 samples, average latency [exclude 1 warmup steps]: 88.465 ms per sample.
W0821 06:53:25.474104 37140 profiler.cc:89] CUDA CUPTI is not enabled

------------------------->     Profiling Report     <-------------------------

Place: CPU
Time unit: ms
Sorted by total time in descending order in the same thread

                       Event       Calls       Total        Min.        Max.        Ave.      Ratio.
                 thread0::fc      370740      272578    0.011775     19.7095    0.735228    0.616268
    thread0::elementwise_add      190380     48865.5    0.114381     1.73744    0.256674    0.110479
         thread0::transpose2      240480     32294.4    0.077649    0.449438    0.134291   0.0730139
               thread0::relu       60120     21220.9    0.263376     1.20742    0.352976    0.047978
            thread0::dropout      190380     18181.7    0.009459    0.272083   0.0955024   0.0411068
         thread0::layer_norm      125250     16305.7    0.106911    0.322171    0.130185   0.0368654
            thread0::softmax       60120     13706.9    0.214626    0.525724    0.227993   0.0309898
             thread0::matmul      125250     9322.28    0.022049     3.70151   0.0744294   0.0210766
              thread0::scale       70140      4563.8    0.006707    0.204413    0.065067   0.0103182
           thread0::reshape2      240480     2619.45    0.007166    0.078659   0.0108926  0.00592229
       thread0::lookup_table       15030        1331    0.070208    0.277766   0.0885562  0.00300924
              thread0::stack        5010     684.089    0.046387    0.335377    0.136545  0.00154665
               thread0::load         202     268.195    0.010278     152.841      1.3277 0.000606358
               thread0::tanh        5010     184.327    0.029071    0.183187   0.0367917 0.000416741
              thread0::fetch        5010     63.0403    0.009063    0.024473   0.0125829 0.000142527
               thread0::feed       20040     58.3227    0.001681    0.020759  0.00291031 0.000131861
              thread0::slice        5010     56.4965    0.009148    0.039881   0.0112767 0.000127732

[tensor-tang]

单线程 10个数据

 Run 10 samples, average latency: 352.382 ms per sample.
I0821 12:07:01.099709   319 inference.cc:359] Run 9 samples, average latency [exclude 1 warmup steps]: 355.139 ms per sample.
W0821 12:07:01.102002   319 profiler.cc:89] CUDA CUPTI is not enabled

------------------------->     Profiling Report     <-------------------------

Place: CPU
Time unit: ms
Sorted by total time in descending order in the same thread

                       Event       Calls       Total        Min.        Max.        Ave.      Ratio.
                 thread0::fc         740     3074.14     0.01086      20.773     4.15425    0.807906
               thread0::load         202     286.345    0.010896     166.914     1.41755   0.0752534
    thread0::elementwise_add         380     115.306    0.116436     1.67314    0.303438   0.0303033
             thread0::matmul         250     83.0643    0.029765     3.11798    0.332257   0.0218299
         thread0::transpose2         480     65.5743    0.075499    0.488148    0.136613   0.0172334
            thread0::dropout         380     45.1451     0.01092     0.46845    0.118803   0.0118645
               thread0::relu         120     43.6511    0.262822     1.60205    0.363759   0.0114718
         thread0::layer_norm         250     33.2642    0.110461    0.214669    0.133057  0.00874208
            thread0::softmax         120     29.9144    0.215222    0.439892    0.249287  0.00786172
              thread0::scale         140     15.0192    0.005788    0.402538     0.10728  0.00394716
           thread0::reshape2         480     5.56671    0.007877    0.046785   0.0115973  0.00146297
       thread0::lookup_table          30      5.1676    0.070664     0.60177    0.172253  0.00135808
              thread0::stack          10     1.93474    0.128399    0.227941    0.193474 0.000508463
               thread0::tanh          10    0.542741    0.035165    0.146138   0.0542741 0.000142636
              thread0::slice          10    0.160324    0.011435    0.042496   0.0160324 4.21343e-05
               thread0::feed          40    0.147486    0.001027     0.01444  0.00368715 3.87604e-05
              thread0::fetch          10    0.126759    0.007186    0.018538   0.0126759 3.33132e-05

[tensor-tang]

20线程，10个sample

I0821 12:07:48.280498   335 inference.cc:354] Run 10 samples, average latency: 64.4593 ms per sample.
I0821 12:07:48.280521   335 inference.cc:359] Run 9 samples, average latency [exclude 1 warmup steps]: 62.4416 ms per sample.
W0821 12:07:48.282289   335 profiler.cc:89] CUDA CUPTI is not enabled

------------------------->     Profiling Report     <-------------------------

Place: CPU
Time unit: ms
Sorted by total time in descending order in the same thread

                       Event       Calls       Total        Min.        Max.        Ave.      Ratio.
                 thread0::fc         740     432.367    0.012076     1.36456     0.58428    0.470114
               thread0::load         202     277.494    0.011123     168.398     1.37373     0.30172
            thread0::dropout         380     51.7348    0.011015    0.214377    0.136144   0.0562514
         thread0::layer_norm         250     40.4131    0.153628     0.20805    0.161652   0.0439413
    thread0::elementwise_add         380     32.8085    0.044845     3.63877   0.0863381   0.0356728
             thread0::matmul         250     27.6031    0.030286     9.82356    0.110413    0.030013
         thread0::transpose2         480      22.741     0.03887    0.200149   0.0473772   0.0247264
              thread0::scale         140     10.2398    0.005754    0.100433   0.0731412   0.0111337
               thread0::relu         120      8.8092    0.060546    0.175747     0.07341  0.00957827
            thread0::softmax         120     6.71831    0.042472    0.268144   0.0559859  0.00730484
           thread0::reshape2         480     4.31378    0.007102    0.021215  0.00898705  0.00469039
       thread0::lookup_table          30     2.57996     0.07498    0.093309   0.0859988   0.0028052
              thread0::stack          10     1.11586    0.104187      0.1304    0.111586  0.00121328
               thread0::tanh          10     0.42612    0.030598    0.114753    0.042612 0.000463322
              thread0::slice          10    0.130643    0.009965     0.03432   0.0130643 0.000142049
               thread0::feed          40    0.106352    0.001016    0.004525   0.0026588 0.000115637
              thread0::fetch          10    0.104856    0.006945    0.011369   0.0104856  0.00011401

[GaoWei8]

baseline：
在CPU上面的测试数据
@徐屹， 82.7681ms
intel BRTR 28.62ms

优化迭代：
82.7681 ms → 60.3766 ms (提升27%)

[luotao1]

ERNIE BERT 分析.pdf
@bingyanghuang 的分析。

主要结论为

• 单线程
  • 状态
    • 去掉冗余的reshape和transpose后，在BERT base上的性能提升1.8%
    • 在FP32 上进一步优化空间较少
  • 下一步
    • 使用INT8量化进一步优化FC，以达到较为大幅度的性能提升
• 多线程
  • 状态
    • 与竞品的2倍左右的差距初步怀疑是paddle多线程中存在一些bug导致CPU空转时间较长
  • 下一步
    • 查看Vtune log找到paddle 多线程缓慢的root cause
    • 总结竞品所使用的优化方式

[tensor-tang]

一个需求：

layernorm 多线程

Top Serial Hotspots (outside parallel regions)
            Function                                            Module          Serial CPU Time
            --------------------------------------------------  --------------  ---------------
            paddle::operators::jit::more::intrinsic::LayerNorm  inference                1.338s
            __kmp_join_call                                     libiomp5.so              0.782s
            __GI_                                               libc.so.6                0.413s
            _mm256_storeu_ps                                    inference                0.296s
            std::string::string                                 libstdc++.so.6           0.290s
            [Others]                                            N/A                      4.855s

[tensor-tang]

Next step

1. mkl sgemm 尺寸测试

在ernie中

在paddle中单独测试，包含了每次iteration刷新矩阵X。

2. 去掉锁。PaddlePaddle/Paddle#19624

3. 更优可以layernorm的多线程问题。

[zhaify]

@tensor-tang Ernie关于多线程性能差的问题，我们这边做了如下测试：

• 环境变量
  disable HT and Turbo Boost

export OMP_NUM_THREADS=20
export KMP_BLOCKTIME=1
export KMP_AFFINITY=granularity=fine,compact,1,0
numactl --cpunodebind=0 --membind=0 CMD

• Intel-MKLML 小包 UT

GEMM Size(M,N,K)	TH=1	TH=20
128 * 768 * 3072	4.02 ms	578 us
128 * 800 * 3100	3.01 ms	277 us

• Ernie

GEMM Size(M,N,K)	TH=1	TH=20	comment
128 * 768 * 3072	3.45 ms	969 us	*
128 * 768 * 3072	4.00 ms	530 us	多次调用 gemm

• TF

GEMM Size(M,N,K)	TH=1	TH=20
128 * 768 * 3072	4.84 ms	343 us

padding
128 * 768 * 3072 > 128 * 772 * 3076
128 * 3072 * 768 > 128 * 3076 * 772
128 * 768 * 768 > 128 * 772 * 772
128 * 2304 * 768 > 128 * 2308 * 772

• 结论
  相同的Gemm操作，在单线程下 Ernie和 UT相近，但在多线程下 Ernie 和 UT 差了一倍。
  在Ernie计算Gemm 耗时占比约为35ms/50ms=70%,还算正常.

• Next

1. 用 VTune 细看多线程区别
2. 关掉HT重新测试一遍(done)
3. 用Vtune 查看 UT 和 Ernie 在 memory 上的区别

• Ernie 20 TH 是瓶颈在 L3 和 DDR,并且 和 TF走了不同的MKL path

4. 在Ernie 中 同时跑多次Gemm, 观察Gemm 耗时

[tensor-tang]

paddle的单侧数据我们也测了，20threads 时是600us左右，貌似跟你这里的结果不一致呢。

[zhaify]

paddle的单侧数据我们也测了，20threads 时是600us左右，貌似跟你这里的结果不一致呢。

UT 单测和我们的数据一样吗？

[tensor-tang]

#180 (comment) 就是这里的，应该一样。

[zhaify]

我更新了128 * 800 * 3100, 可以看出 UT 加上Padding 可以和TF 打平。

[tensor-tang]

嗯赞，那先首要一起分析下多线程问题。

[zhaify]

结论

Ernie 20 线程瓶颈在 L3 和 DDR， 原因是Ernie MKL 在20 线程的时候走了不同于TF 的MKL path。由于TF 中添加了Padding，如下

128 * 768 * 3072 > 128 * 772 * 3076
128 * 3072 * 768 > 128 * 3076 * 772
128 * 768 * 768 > 128 * 772 * 772
128 * 2304 * 768 > 128 * 2308 * 772

但Ernie 中没有，这个Padding 会导致Ernie 走到了另一个比较差的MKL path，解决方法是在Paddle中添加padding，我会先尝试一下。