Optimize the performance of PyramidDNN on CPU

[zhaoyuchen2018]

负责人

@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：[DON'T MERGE] add hash_embedding OP Paddle#18611

[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实现。

[Xreki]

search_pyramid_hash分析

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

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

[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优化，是无法起到上面这个“减少内存访问”的效果的。

优化计划和进展

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

[Xreki]

确定框架耗时，@zhaoyuchen2018

• 测试方法：
• 测试结论：

[zhaoyuchen2018]

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

[luotao1]

release分支

从Vtune结果看，memcpy占比14%

debug分支

[zhaoyuchen2018]

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的执行效率。

[luotao1]

bloomfilter_get内部占比：

sse_axpy走到sse指令，而非avx指令。但这部分占比很小，改后PaddlePaddle/Paddle@64c7fd9 基本没变化。

[zhaoyuchen2018]

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

[jianhang-liu]

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

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

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

[luotao1]

@jianhang-liu 初步怀疑是numpy调用的OpenBlas库，类似issue：ray-project/ray#1654 tensorflow/tensorflow#17315

[jianhang-liu]

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

[zhaoyuchen2018]

从下面两点做了尝试：

1. 调整代码顺序，把第二次的%操作放到bit_get之后，这样如果第一个bit_get返回之后有一定的概率省去第二次的%操作。
2. 考虑到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;
    }

[luotao1]

复现了 @zhaoyuchen2018 在#151 (comment) 中的结论。

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倍：缺页异常的次数。当应用程序请求的页面尚未建立、请求的页面不在内存中，或者请求的页面虽然在内存中，但物理地址和虚拟地址的映射关系尚未建立时，都会触发一次缺页异常。

[luotao1]

跑3个epoch的对比，hotspots

• paddle
  
• 竞品
  

[zhaoyuchen2018]

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上的计算增加了整体的耗时。

[bingyanghuang]

根据骆涛给出的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么？

[luotao1]

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

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

[zhaoyuchen2018]

去掉了read lock重新profile的结果：PaddlePaddle/Paddle#19203
可以看出只有一个主线程core在忙，其他占比时间都很少。

从CPU运行时间上看，也是除了一开始有3个线程在RUN之外，后面只有主线程在run:

从函数消耗时间上看，reader函数消耗的时间都很少：

[luotao1]

使用amplxe-cl -collect threading sh run_train.sh，日志截图如下

其中wait_count=5544，是iteration数。

[luotao1]

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

[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后的矩阵，导致数据结构没对齐。
  • Optimize the performance of PyramidDNN on CPU #151 (comment) 中测出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。

[zhaoyuchen2018]

去掉reader lock测试了一个epoch(5500个iter)的整体时间：PaddlePaddle/Paddle#19203

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

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

[luotao1]

根据补0操作的分析 #151 (comment) ， 尝试了@ Aurelius84 PaddlePaddle/Paddle#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。

结论

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

[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中的
  
  

[zhaoyuchen2018]

测试多线程的结果：
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%

[luotao1]

@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。

[luotao1]

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

[zhaoyuchen2018]

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

[luotao1]

• 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，PaddlePaddle/Paddle@36acfae
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 #151 (comment)

大致结论：

• 使用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%以内。

[luotao1]

使用pyreader的paddle vtune

使用dataset的paddle vtune

可以看出只有一个主线程core在忙，其他占比时间都很少。

[luotao1]

• Cloud上是混布机器，有E5 2650v3，5117和E5 2450v2
• Paddle：不设置MKL环境变量，下面的数据单位均是 s/epoch
• drop_out_percent = 0.5，sampling_rate = 0.06 。之前采样率是1。
• 单机每个线程测试40个part，24线程测试960个part，之前单机每个线程测试1个part。

平台	单线程(6148)	24线程(6148)	单线程(Cloud)	24线程(Cloud)	备注
竞品	466	554	775	829	baseline
Paddle	397(+14.8%)	526(+5%)	626(+19.2%)	892(-7.5%)	PaddlePaddle/Paddle@25ffa8445d0900 murmurhash3_x64_128优化
Paddle	381(+18.2%)	495(+10.6%)			PaddlePaddle/Paddle@1cd6721 去掉反向copy，去掉反向中的临时Tensor，memcpy写死拷贝16
Paddle	367.6(+21.1%)	484.7(+12.5%)	616(+20.5%)	872(-5.2%)	PaddlePaddle/Paddle@b19e1a1 使用memcpy预取

[luotao1]

由于：

• drop_out_percent = 0.5，sampling_rate = 0.06 。之前采样率是1。
• 单机每个线程测试40个part，24线程测试960个part，之前单机每个线程测试1个part。

每个epoch时间和profile结果也有变化。2650 V4上的profile结果见
PaddlePaddle Benchmark.pdf

Op	占比
pyramid_hash	51.2%
pyramid_hash_grad	12.15%
sum	10.86%
fused_embedding_seq_pool	4.8%
mul_grad	4.4%
fused_embedding_seq_pool_grad	3.3%
mul	2.4%

• 一些结论：
  • pyramid_hash前向仍是大头
  • sum占比比较多

[jianhang-liu]

@luotao1 优化的目标是什么？在Clould 24线程环境下追齐竞品？892(-7.5%)

[luotao1]

@jianhang-liu 是的。单机24线程追平竞品。

目前有以下几个可尝试的点：

• fuse op使用了临时Tensor，接手@intel的PR， 完成Remove some temporary variables Paddle#21159 的合入。@luotao
• pyramid_hash前向：@jianhang-liu 建议尝试使用libdivide高性能库，加速64位mod运算性能。可参考 PaddlePaddle/Paddle@4133302 @luotao
• 调查sum是否有可优化空间

[jianhang-liu]

@LeoZhao-Intel Please help to have a check. Thanks!

[LeoZhao-Intel]

看完长长的history，感觉是在用PE做CPU上的PyramidDNN training, 有guide可以帮助我把reproduce环境setup起来吗？或者是ut ？

[LeoZhao-Intel]

PaddlePaddle/Paddle#21206 is to improve memcpy perf by prefetching