benchmark Optimize the performance of PyramidDNN on CPU

负责人

@zhaoyuchen2018 , @luotao1

初始性能

测试时间：2019年7月15日
Paddle commit：
模型配置：
- 单机单线程：CPU_NUM=1，1个进程读数据
测试者：@Aurelius84
单位：s/epoch
CPU型号：Intel(R) Xeon(R) Gold 5117 CPU @ 2.00GHz

epoch id	Paddle (MKL_CBWR=COMPATIBLE)	Paddle (MKL_CBWR="")	竞品
1	357	307	277
2	343	310	278

CPU型号：Intel(R) Xeon(R) CPU E5-2620 v4 @2.10GHz，16核

epoch id	Paddle (MKL_CBWR=COMPATIBLE)	Paddle (MKL_CBWR="")	竞品
1	268	254	219
2	283	245	220

结论：
- 因为竞品是设置了MKL_CBWR=COMPATIBLE跑的，所以需要用Paddle (MKL_CBWR=COMPATIBLE)和竞品对比，为了发现Paddle慢的地方。
- Paddle比竞品慢~25%
新增op
- search_pyramid_hash：https://github.com/PaddlePaddle/Paddle/pull/18611

Jul 25 '19 02:07 zhaoyuchen2018

Profile分析结果

@Aurelius84 提供的profile对比

新增的search_pyramid_hash op的实现，基本仿照竞品，但前向op的时间比竞品多15%。
Paddle的lookup_table+sequence_pool，竞品中使用一个融合的EmbeddingWithVSum op实现，且调用了mkl的稀疏计算库。
另外还有几个基础op，Paddle的实现比竞品慢很多，主要有：softsign_grad、cos_sim、cos_sim_grad
sum op耗时也比较多，Paddle目前使用Eigen实现。

Jul 25 '19 02:07 zhaoyuchen2018

search_pyramid_hash分析

该Op里面调用了两个SSE函数sse_axpy和sse_axpy_noadd，可以尝试调用MKL。@luotao1
需比较该Op的实现和竞品实现的diff。@luotao1
确定该Op的框架开销。@zhaoyuchen2018

使用gperftools分析得到：bloomfilter_get在前向中占比最多。15%里面占比13%。 4. 如果只跑前向网络，search_pyramid_hash op的耗时，比跑整个网络的耗时少了7%。@zhaoyuchen2018

Jul 26 '19 05:07 Xreki

lookup_table & sequence_pool优化方案分析 @intel

确定path
- lookup_table：走的是LoDTensor path，path里面的padding_idx走了少数几次
- lookup_table_grad：走的是sparse的非grad_inplace path
- sequence_pool：走的是SUM path
结论：参照竞品的做法
1. 将embedding和sequence pool (sum) fuse起来
2. 调用（sparse）GEMM实现
具体分析：
- embedding (lookup_table) 和 sequence_pool（sum）这两个OP都非计算密集的算子，主要时间耗费在内存搬移上。
  - lookup_table OP: 根据word id查表，把每个词向量从字典中逐个拷贝到output里（就是memcpy）
  - sequence_pool OP (sum): 将输入（即lookup_table的output）的所有词向量，做向量加后，写入output
竞品分析：
- 竞品采用了一种比较巧妙的做法，当lookup_table + seq_pool (sum)时，无需先将词向量从字典中拷贝出来，而是直接将字典中特定的行（词向量）直接加起来。
- 具体做法是为每个句子构建一个稀疏向量，向量长度即为字典的长度（行数），句子中每个word id, 都在该稀疏向量的对应位置加1. 然后用这个稀疏向量和字典做矩阵乘(sparse GEMM)，这样就直接得到了句子所有词的词向量之和。
总结：单独对这两个OP优化，是无法起到上面这个“减少内存访问”的效果的。

优化计划和进展

[x] 完成fuse后的lookup_table和sequence_pool前向Op，在MKLML测试版本基础上，能够编译通过且通过unit test，具体见CODE @intel， 2019年7月25日
[x] 完成反向Op实现，打包加入MKL_CSRMM的libmklml_intel.so @intel
[x] 进行正确性验证 @luotao1 @Aurelius84

Jul 26 '19 05:07 Xreki

确定框架耗时，@zhaoyuchen2018

测试方法：
测试结论：

Jul 26 '19 05:07 Xreki

从timeline上来看，search_pyramid_hash时间都消耗在CPU上

Jul 31 '19 12:07 zhaoyuchen2018

release分支

从Vtune结果看，memcpy占比14%

debug分支

Jul 31 '19 14:07 luotao1

cmd: perf stat sh run_train.sh

system	task-clock	context-switches	cpu-migrations	page-faults	cycles	instructions	branches	branch-misses
paddle	1.252 CPUs utilized	770,000(0.002 M/sec)	16,462(0.042 K/sec)	10,591,434(0.027 M/sec)	2.288 GHz	1.35 insns per cycle	429.774 M/sec	21.35% of all branches
竞品	1.001 CPUs utilized	3,979(0.000 M/sec)	8,385（0.000 M/sec）	5,017,948(0.010 M/sec)	2.284 GHz	1.50 insns per cycle	296.205 M/sec	25.53% of all branches

上面是perf的结果，可以看出来paddle相比竞品 context switch多了~200倍，会影响CPU的执行效率。

Aug 01 '19 02:08 zhaoyuchen2018

bloomfilter_get内部占比： sse_axpy走到sse指令，而非avx指令。但这部分占比很小，改后https://github.com/PaddlePaddle/Paddle/pull/18814/commits/64c7fd92c1bbda62ddce4c6ec9a102321bfc482c 基本没变化。

Aug 01 '19 05:08 luotao1

murmurhash3_x64_128优化
优化前：

 switch (len & 15) {
        case 15:
            nk2 ^= ((uint64_t) tail[14]) << 48;
        case 14:
            nk2 ^= ((uint64_t) tail[13]) << 40;
        case 13:
            nk2 ^= ((uint64_t) tail[12]) << 32;
        case 12:
            nk2 ^= ((uint64_t) tail[11]) << 24;
        case 11:
            nk2 ^= ((uint64_t) tail[10]) << 16;
        case 10:
            nk2 ^= ((uint64_t) tail[9]) << 8;
        case 9:
            nk2 ^= ((uint64_t) tail[8]) << 0;
            nk2 *= c2;
            nk2 = ROTL64(nk2, 33);
            nk2 *= c1;
            h2 ^= nk2;
        case 8:
            nk1 ^= ((uint64_t) tail[7]) << 56;
        case 7:
            nk1 ^= ((uint64_t) tail[6]) << 48;
        case 6:
            nk1 ^= ((uint64_t) tail[5]) << 40;
        case 5:
            nk1 ^= ((uint64_t) tail[4]) << 32;
        case 4:
            nk1 ^= ((uint64_t) tail[3]) << 24;
        case 3:
            nk1 ^= ((uint64_t) tail[2]) << 16;
        case 2:
            nk1 ^= ((uint64_t) tail[1]) << 8;
        case 1:
            nk1 ^= ((uint64_t) tail[0]) << 0;
            nk1 *= c1;
            nk1 = ROTL64(nk1, 31);
            nk1 *= c2;
            h1 ^= nk1;
    };

优化后：

   uint64_t tail0_64 = *(uint64_t*)(tail);
   uint64_t tail_64 = *(uint64_t*)(tail + 8);
   uint64_t mask0 = 0xffffffffffffffff;
   uint64_t mask = 0x00ffffffffffffff;

   int flag = len & 15;
   if (flag && flag <= 8) {
       tail0_64 &= (mask0 >> ((8 - flag)<<3));
   } else if (flag > 8){
       tail_64 &= (mask >> ((15 - flag)<<3));
       nk2 ^= tail_64;
       nk2 *= c2;
       nk2 = ROTL64(nk2, 33);
       nk2 *= c1;
       h2 ^= nk2;
    }

   if (flag) {
       nk1 ^= tail0_64;
       nk1 *= c1;
       nk1 = ROTL64(nk1, 31);
       nk1 *= c2;
       h1 ^= nk1;
   }

op 时间：

测试次数	1	2	3	avg
优化前(ms)	3.43268	3.27932	3.25202	3.32
优化后(ms)	3.33146	3.32852	3.13379	3.26

Aug 01 '19 06:08 zhaoyuchen2018

@luotao1 关于perf log里观察到context_switch的次数比竞品高200倍的问题，我看了一下vtune log。

未看出明显的因为lock而导致频繁切换context
被观察进程有多达47个线程，其中只有4个线程为有效线程（一个主线程，两个python reader线程，一个大部分时间idle的ThreadPool线程）。其它线程均为OpenBLAS的BlasServer启动的thread。这些OpenBLAS线程都是idle （block在__sched_yield)

一个疑问是：是否这些“无用的”OpenBLAS线程导致了context_switch次数的增加? 尽管它们不占用多少CPU时间，但会增加CPU调度的几率。

Aug 06 '19 08:08 jianhang-liu

@jianhang-liu 初步怀疑是numpy调用的OpenBlas库，类似issue：https://github.com/ray-project/ray/issues/1654 https://github.com/tensorflow/tensorflow/issues/17315

Aug 06 '19 10:08 luotao1

可以试试用export OPENBLAS_NUM_THREADS=1(或通过代码在runtime进行设置）控制OpenBLAS线程数，然后用Vtune看看是否生效

Aug 06 '19 11:08 jianhang-liu

从下面两点做了尝试：

调整代码顺序，把第二次的%操作放到bit_get之后，这样如果第一个bit_get返回之后有一定的概率省去第二次的%操作。
考虑到64bit的div操作比较耗时，在做之前进行判断，看是否需要64bit的%操作。

   if (result[0] < (uint32_t)0xffffffff) {
       result[0] = (uint32_t)result[0] % (uint32_t)bloomfilter->m;
   } else {
       result[0] %= bloomfilter->m;
   }
   if (!bit_get(bloomfilter->bit_vector, result[0])){
       return 0;
   }

   if (result[1] < (uint32_t)0xffffffff) {
       result[1] = (uint32_t)result[1] % (uint32_t)bloomfilter->m;
   } else {
       result[1] %= bloomfilter->m;
   }
   if (!bit_get(bloomfilter->bit_vector, result[1])){
       return 0;
    }

Aug 08 '19 06:08 zhaoyuchen2018

复现了 @zhaoyuchen2018 在https://github.com/PaddlePaddle/benchmark/issues/151#issuecomment-517095618 中的结论。

system	task-clock	context-switches	cpu-migrations	page-faults	cycles	instructions	branches	branch-misses
paddle	1.259 CPUs utilized	586,038(0.606 K/sec)	22,668(0.023 K/sec)	28,124,157(0.029 M/sec)	2.587 GHz	1.49 insns per cycle	122.262 M/sec	0.71% of all branches
竞品	1.000 CPUs utilized	4,969(0.000 M/sec)	1,851（0.000 M/sec）	5,959,013(0.010 M/sec)	2.595 GHz	1.52 insns per cycle	36.894 M/sec	1.15% of all branches

机器和 @zhaoyuchen2018 的不一样。但占比类似。可以看出来paddle相比竞品

context switch多了~100倍，会影响CPU的执行效率。
cpu-migrations CPU迁移多了12倍。Linux为了维持多个处理器的负载均衡，在特定条件下会将某个任务从一个CPU迁移到另一个CPU。
page-faults多了4倍：缺页异常的次数。当应用程序请求的页面尚未建立、请求的页面不在内存中，或者请求的页面虽然在内存中，但物理地址和虚拟地址的映射关系尚未建立时，都会触发一次缺页异常。

Aug 13 '19 09:08 luotao1

跑3个epoch的对比，hotspots

paddle
竞品

Aug 13 '19 11:08 luotao1

paddle: 从上图可以看出CPU0+CPU1+CPU2+CPU3=elapsed time(747.4s), 其中CPU1=540.9s，CPU2=190.9s。竞品：竞品CPU1=605.4s，elapsed time=(610.3s)几乎所有时间都在CPU1. paddle主要有2个CPU在run，猜测CPU2上的计算增加了整体的耗时。

Aug 13 '19 13:08 zhaoyuchen2018

根据骆涛给出的paddle上的vtune log，我们可以看到有一个主线程和两个子线程较忙：在vtune的Bottom-up中我们可以看到，虽然起了非常多的thread，但是真正运行的只有前四个线程。（绿色为没有任务，褐色表示正忙，红色表示在等）其中PID 8702和PID 8701对应的是我们第一张图中那两个较繁忙的子线程。我们选择一段三个线程都较为繁忙的时间来查看具体某一个线程做了什么。

线程PID 8701 主要在feed data 对应data_feeder.py这个文件，其中有有些时间在等待，可以从彩色条形图里看到一些红色cpu spin time
线程PID 8702 这个线程主要在read data，对应pyramid_data_reader.py这个文件，同样可以看到有部分等待时间。
主线程主线程基本在忙，主要在做memcpy，bllomfilter_get和CPUSearchPyramidHash

所以这个是训练的过程，是因为用了parallel executor所以一边在做计算，一遍再feed和read data准备下一个batch么？

Aug 14 '19 01:08 bingyanghuang

是因为用了parallel executor所以一边在做计算，一遍再feed和read data准备下一个batch么？

@bingyanghuang 是的。PE里读数据和主线程计算是异步的。

Aug 14 '19 03:08 luotao1

去掉了read lock重新profile的结果：https://github.com/PaddlePaddle/Paddle/pull/19203 可以看出只有一个主线程core在忙，其他占比时间都很少。从CPU运行时间上看，也是除了一开始有3个线程在RUN之外，后面只有主线程在run: 从函数消耗时间上看，reader函数消耗的时间都很少：

Aug 14 '19 09:08 zhaoyuchen2018

使用amplxe-cl -collect threading sh run_train.sh，日志截图如下其中wait_count=5544，是iteration数。

Aug 14 '19 11:08 luotao1

@jianhang-liu 的分析报告见 PyramidDNN模型分析（training).pdf

Aug 19 '19 04:08 luotao1

Search_pyramid_hash分析：

@jianhang-liu 的分析：

慢的25%时间的9.0%: Paddle的CPUSearchPrymidHashOPKernel(前向)实现，比竞品对应的 BatchPyramidHashLayer(前向)实现，要慢60s (两者反向的性能基本一致)。而在60s 里，有36s是因为Paddle里的memcpy比Lego里的__memcpy_sse2_unligned多花的
- Paddle的memcpy耗时114.592s, 比竞品的__memcpy_sse2_unaligned(耗时78.517s)，要多花了35s
- Paddle的bloomfilter_get (141.179s)比竞品的bloomfilter_get (118.612s)，要多花了23s
建议:
- _memcpy_sse2_unaligned只是memcpy的一个具体实现。竞品/Paddle性能差异这么大，要么是两者copy的数据量不一样，要么是Paddle的memcpy执行时走到的非 _memcpy_sse2_unaligned(而是一个性能更差的分支)

@luotao 的分析

Paddle的CPUSearchPrymidHashOP和竞品相比，多了一个补0操作：也就是在一个空输入下，补一行0。这样会导致该Op的输出矩阵是比竞品高的。这样能解释两个现象：
- memcpy没有走到_memcpy_sse2_unaligned，很可能多了几行0后的矩阵，导致数据结构没对齐。
- https://github.com/PaddlePaddle/benchmark/issues/151#issuecomment-520754498 中测出page-faults（缺页异常的次数）多了4倍。很可能多了几行0后的矩阵，内存就需要换页了。
建议：
1. Paddle的sequence_pool(input, pool_type, is_test=False, pad_value=0.0)也有补0的操作，可以把补0从CPUSearchPrymidHashOP挪到sequence_pool，和竞品对齐么？
2. 在sequence_pool中补0的计算量应该要远小于CPUSearchPrymidHashOP。

Aug 19 '19 04:08 luotao1

去掉reader lock测试了一个epoch(5500个iter)的整体时间：https://github.com/PaddlePaddle/Paddle/pull/19203

测试次数	1	2	3	avg
有lock(s)	244	270	246	253
没有lock(s)	239	250	250	246

lock对整体时间大概有2%的影响

Aug 21 '19 01:08 zhaoyuchen2018

根据补0操作的分析 https://github.com/PaddlePaddle/benchmark/issues/151#issuecomment-522403630 ，尝试了@ Aurelius84 https://github.com/PaddlePaddle/Paddle/pull/19290

改动逻辑

逻辑是这样的，在pyramid_hash里做padding，之后在squence_pool里是不会再走padding逻辑的，因为不存在有长度为0的sequence; 如果不在pyramid_hash里做padding，则输出分为以下两种情况：

输出lod_len=[0, 0, 0], 输出data_dims = [0, 256]这种空tensor 。
- 修改后：全空改为一次性memset，输出为[batch_size ,256]，输入到seq_pool不会进行pooling操作，因为输入就是已经pooling。
输出lod_len = [1, 0, 1], 输出data_dims=[2, 256]这种部分seq_len为0的情况。
- 修改后：去掉非全空的padding，输入到seq_pool后，develop分支的seq_pool会自动进行padding。

结论

正反向精度对齐
但在性能上没有效果。

Aug 21 '19 05:08 luotao1

使用AVX汇编的memcpy.S，能看到search_pyramid_hash中的memcpy的时间（35s-》30s）降下来了，但整体时间没有明显变化。

memcpy的量

memcpy(top_pos + j, weights + pos, _rand_len * sizeof(T));

其中_rand_len * sizeof(T)=16*sizeof(float)

结果对比

before: memcpy排第一，47s里面35s是search_pyramid_hash中的。
after：memcpy1排第四，30s全是search_pyramid_hash中的

Aug 22 '19 13:08 luotao1

测试多线程的结果： paddle设置：thread_num = 8, reader_threads = 8 竞品设置：thread_num = 8

测试次数	1	2	3	avg
paddle(s)	365	372	322	353
竞品(s)	252	254	228	245

paddle比竞品慢44%

Aug 29 '19 06:08 zhaoyuchen2018

@jianhang-liu @bingyanghuang @yinghu5

wangyang的分析：

竞品用的是libc-2.18.so，但paddle用的是libc-2.12.so，比竞品老很多。可能导致memcpy和bloomfilter慢。
memcpy的指令数instructions retired，paddle大于竞品
- paddle的SearchPyramid中memcpy是44,400,000,000（一个epoc）
- 竞品的SearchPyramid中memcpy是116,136,000,000.（3个epoc）
bloomfilter的指令数，paddle小于竞品，但总时间却大于竞品
- paddle是55,908,000,000(一个epoc)
- 竞品是184,776,000,000（3个epoc）

wangyang的建议

让paddle使用libc-2.18.so
memcpy的指令总数instructions retired= memcpy的调用次数 * memcpy内部指令数。 @luotao 确认调用次数是否一样。（需要更高级的vtune命令）
编译选项可以直接对memcpy做优化，即调用memcpy不会走入libc.so。

Sep 04 '19 05:09 luotao1

@Aurelius84 在pyramid_hash调用memcpy的地方都做了调用计数，分别用1行样本和5000条样本，在drop_out_percent=0. samplint_rate=1.的条件下，测了一下结果。paddle和竞品的memcpy次数几乎是一样的。从数据里可以看出，竞品同样的数据在每轮也会有波动。

Sep 04 '19 12:09 luotao1

GCC5.4，libc2.23 测试memcpy依然没有走进sse的版本：

Sep 05 '19 00:09 zhaoyuchen2018

2620 v3机器，竞品 baseline：202s，下表时间均为秒

paddle(设置环境变量)epoc均值	3个epoc	paddle(不设置环境变量)epoc均值	3个epoc	备注
242.34	---	204.03	---	baseline PR18814@b0fe063 做了一些代码清理
238.8	241.98, 237.62, 236.97	200.2	199.80, 207.08, 193.69	使用python.fluid.dataset代替pyreader
218(提速8%)	218.02, 220.89, 217.92	198	200.80, 198.24, 197.46	使用dataset+memcpy写死拷贝16个，9月17日
227	228.48，225.29，229.53			使用dataset+memcpy写死拷贝16个，使用vtune采集
232.3(develop慢了6.5%)	237.61，227.99，231.34	191.22(develop快了3.4%)	190.54，189.68，193.45	使用dataset+memcpy写死拷贝16个，develop重新测，10月14日
225.8(提速2.8%)	229.51，229.44，218.71	187.24(提速2%)	188.37，187.05，186.32	使用fuse_emb_seq_pool，https://github.com/PaddlePaddle/Paddle/commit/36acfaeeda4cf2f23411d6adc15c495291d1354d
222(提速1.7%)	216.94，220.10，229.21	186(提速0.67%)	189.68，183.48，184.79	去掉debug按钮：运行时不打出中间结果
221.67(提速0.15%)	228.00，218.44，218.59	183.01(提速1.6%)	185.73，179.46，183.85	axpy使用avx实现，之前是sse实现
214.66(提速3.1%)	221.52，206.26，216.21	179.72(提速1.8%)	176.82，178.06，184.29	使用 @zhaoyuchen2018 优化的murmurhash3_x64_128 https://github.com/PaddlePaddle/benchmark/issues/151#issuecomment-517139284

大致结论：

使用dataset代替pyreader，会有1.5%左右的性能提升。
memcpy写死拷贝16个的加速
- 在pyreader的版本中，是被隐藏了。在dataset版本设置环境变量中，可以看到有8%的提升，而且非常稳定没有波动。
- 传常数给memcpy目的就是让编译器用__builtin_memcpy，可以节省函数调用以及libc里面的按字节拷贝
使用vtune采集后，速度从218降到227。
使用fuse_emb_seq_pool，在dataset版本+memcpy写死拷贝16上，提速2～3%。
debug按钮影响在2%以内。

Sep 11 '19 07:09 luotao1

benchmark benchmark copied to clipboard

Optimize the performance of PyramidDNN on CPU

负责人

初始性能

Profile分析结果

search_pyramid_hash分析

lookup_table & sequence_pool优化方案分析 @intel

优化计划和进展

确定框架耗时，@zhaoyuchen2018

release分支

debug分支

Search_pyramid_hash分析：

@jianhang-liu 的分析：

@luotao 的分析

改动逻辑

结论

memcpy的量

结果对比

wangyang的分析：

wangyang的建议

benchmark
benchmark copied to clipboard