search

PaddlePaddle / benchmark

77 stars 157 forks source link

Optimize the performance of PyramidDNN on CPU #151

Open zhaoyuchen2018 opened 5 years ago

zhaoyuchen2018 commented 5 years ago

负责人

@zhaoyuchen2018 , @luotao1

初始性能

epoch id Paddle (MKL_CBWR=COMPATIBLE) Paddle (MKL_CBWR="") 竞品
1 357 307 277
2 343 310 278
epoch id Paddle (MKL_CBWR=COMPATIBLE) Paddle (MKL_CBWR="") 竞品
1 268 254 219
2 283 245 220
zhaoyuchen2018 commented 5 years ago

Profile分析结果

@Aurelius84 提供的profile对比

image

Xreki commented 5 years ago

search_pyramid_hash分析

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

使用gperftools分析得到：bloomfilter_get在前向中占比最多。15%里面占比13%。

  1. 如果只跑前向网络，search_pyramid_hash op的耗时，比跑整个网络的耗时少了7%。@zhaoyuchen2018
Xreki commented 5 years ago

lookup_table & sequence_pool优化方案分析 @intel

优化计划和进展

Xreki commented 5 years ago

确定框架耗时，@zhaoyuchen2018

zhaoyuchen2018 commented 5 years ago

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

luotao1 commented 5 years ago

release分支

image

image 从Vtune结果看，memcpy占比14%

debug分支

image image image

zhaoyuchen2018 commented 5 years ago

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 commented 5 years ago

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

zhaoyuchen2018 commented 5 years ago

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 commented 5 years ago

@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 commented 5 years ago

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

jianhang-liu commented 5 years ago

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

zhaoyuchen2018 commented 5 years ago

从下面两点做了尝试：

  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 commented 5 years ago

复现了 @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相比竞品

luotao1 commented 5 years ago

跑3个epoch的对比，hotspots

zhaoyuchen2018 commented 5 years ago

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

bingyanghuang commented 5 years ago

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

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

luotao1 commented 5 years ago

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

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

zhaoyuchen2018 commented 5 years ago

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

luotao1 commented 5 years ago

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

luotao1 commented 5 years ago

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

luotao1 commented 5 years ago

Search_pyramid_hash分析：

@jianhang-liu 的分析：

@luotao 的分析

zhaoyuchen2018 commented 5 years ago

去掉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%的影响

luotao1 commented 5 years ago

根据补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，则输出分为以下两种情况：

结论

luotao1 commented 5 years ago

使用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)

结果对比

zhaoyuchen2018 commented 5 years ago

测试多线程的结果： 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 commented 5 years ago

@jianhang-liu @bingyanghuang @yinghu5

wangyang的分析：

wangyang的建议

luotao1 commented 5 years ago

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

zhaoyuchen2018 commented 5 years ago

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

luotao1 commented 5 years ago
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

大致结论：

luotao1 commented 5 years ago

使用pyreader的paddle vtune

image

使用dataset的paddle vtune

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

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

由于：

每个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%
jianhang-liu commented 5 years ago

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

luotao1 commented 5 years ago

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

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

jianhang-liu commented 5 years ago

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

LeoZhao-Intel commented 5 years ago

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

LeoZhao-Intel commented 5 years ago

https://github.com/PaddlePaddle/Paddle/pull/21206 is to improve memcpy perf by prefetching