近期竞价服务的几个性能优化点

2014-10-29

自上次做竞价服务的性能优化已经过了一段时间。这几天做频次数据库线下测试，遇到了一些问题，一个是数据库延时过高，另一个是CPU不稳定。于是找找原因，顺带看看竞价服务这边的情况。

据说流量压力正常，有时候CPU会暴涨到600%。为了定位问题，还是先祭出神器pprof。pprof没有看出问题了，跟最近一次的对比，垃圾回收的比以前升高了一些，以前大概4%，现在到6%了。这个是由于新加的一些业务代码中引入的小内存分配。

另一个跟以前不同的地方是有2%的CPU开销浪费在了抢锁上面。来源是rand.Float64的调用，系统的rand.Floa64会加锁，而这边代码在一个高并发请求下，有几个循环中调用rand.Float64函数，导致锁的占用严重。上次优化时没观察到这个问题，这部分代码没变过，问了一下是不是Go版本变过了，果然是这方面的原因。

最高的几项，mapaccess占了9%优化不了，这个是因为业务代码中太多地使用map数据结构，不好动。

然后排第二的syscall调用，主要来源是net.http库和redis的库一直调用到net.Write，也是没法优化的，标准库自不必说，都是bufio过的。

接着有regex的，这个是判断浏览器类型使用到了，每来一个竞价请求都会判断浏览器类型信息，用到正则。请求量很大之后这边就引入了3%以上的CPU开销。上次尝试优化这块，可耻的失败了。

然后的mallocgc什么的，内存分配和垃圾回收相关的，比上次涨了一些，业务需要引入的。

还有system和futex，推测跟我们自己的日志库实现相关，多个goroutine同时写日志，用锁保护。我上次就提过merge了，日志发到channel，由单个goroutine在后台写log。只不过还没合到master。

总体来说简单能做的上次都优化掉了。然后看内存，内存占用在100MB-200MB之间，跟之前差不多。其中大概50M多是加载IP数据库所占用的。这种单个大块内存对垃圾回收没什么影响。但是代码写得太恶劣了ioutil.ReadAll，顺手优化下，改成多进程共享内存的了。因为我们会在一个物理机器上起很多的竞价进程，而每个进程都加载一份IP数据库到内存，实在太浪费了。这份数据是只读的，很容易共享。虽然说单个进程节省50M并不多，总的竞价进程至少也有100+，算一下起码可以省下5G的内存。

顺便说说单机多进程，为什么要这么搞？为什么不是一个大进程呢？至少在垃圾回收方面，拆分是明显有好处的。每个进程中的对象更少了，则垃圾回收的停顿时间就更短。目前的Go的实现，是并行的垃圾回收，但是停下来后，并不是所有goroutine都去回收垃圾了，只有最多8个参与垃圾回收工作，其它都闲着。另外，拆成多个小进程，一个挂掉了影响并不严重，换成一个大进程挂掉受影响的连接就多得多。

按理说从我上次优化完代码后，正常压力下CPU使用不应该超过200%的，大概1500QPS时160%左右的CPU。pprof没问题，内存使用率也很正常，到底是什么导致不稳定的暴涨呢。

再看看GC的情况了，终于定位了问题所在：

gc1897(8): 10+26+6891+59 us, 52 -> 105 MB, 549368 (604823203-604273835) objects, 19379/9699/0 sweeps, 72(3501) handoff, 32(466) steal, 613/133/8 yields gc1898(8): 57+21+7989+167 us, 52 -> 105 MB, 558217 (605170322-604612105) objects, 19379/10265/0 sweeps, 120(6726) handoff, 69(940) steal, 696/199/14 yields gc1899(8): 9+25+8149+8 us, 52 -> 105 MB, 541706 (605502236-604960530) objects, 19379/10346/0 sweeps, 128(11526) handoff, 22(420) steal, 869/308/20 yields gc1900(8): 34+23+7647+46 us, 52 -> 105 MB, 560347 (605852769-605292422) objects, 19379/10342/0 sweeps, 140(7751) handoff, 46(800) steal, 875/246/20 yields gc1901(8): 10+1405+9143+56 us, 52 -> 105 MB, 552926 (606195933-605643007) objects, 19379/10043/0 sweeps, 143(7594) handoff, 43(935) steal, 689/197/13 yields gc1902(8): 30088+10246+28392+45 us, 52 -> 105 MB, 549819 (606535495-605985676) objects, 19379/10331/0 sweeps, 84(7100) handoff, 49(1301) steal, 444/148/17 yields gc1903(8): 44+25+6694+143 us, 53 -> 106 MB, 549086 (606872247-606323161) objects, 19379/10699/0 sweeps, 44(4354) handoff, 47(702) steal, 466/131/26 yields gc1904(8): 31+23+6411+7 us, 53 -> 107 MB, 555695 (607214066-606658371) objects, 19379/3515/0 sweeps, 107(10192) handoff, 67(1024) steal, 657/219/16 yields gc1905(8): 36+29+6668+14 us, 53 -> 107 MB, 550426 (607551487-607001061) objects, 19379/5634/0 sweeps, 96(6921) handoff, 21(294) steal, 679/176/22 yields gc1906(8): 9+31+8006+148 us, 52 -> 105 MB, 548565 (607890212-607341647) objects, 19379/10430/0 sweeps, 158(9644) handoff, 47(567) steal, 881/219/11 yields gc1907(8): 3+33+8252+81 us, 52 -> 105 MB, 539877 (608220352-607680475) objects, 19379/10218/0 sweeps, 63(4975) handoff, 19(372) steal, 474/148/9 yields gc1908(8): 22+30+7976+137 us, 52 -> 105 MB, 552635 (608563239-608010604) objects, 19379/10103/0 sweeps, 68(7029) handoff, 69(918) steal, 538/126/11 yields

平时正常的垃圾回收时间大概在7-8ms，现在gc的压力变大了一些，以前应该在5ms的。

注意到其中有异常的一项，30088+10246+28392+45us，居然有68ms!!!问题找到了，大部分时候垃圾回收正常，时间稳定在7-8ms，但一阵一阵的突然变到好几十毫秒，接来下就是CPU暴涨到几百了。应该是垃圾回收期间积压了大量请求，导致后面处理不过来...

继续调查，为什么会有一阵一阵的垃圾回收时间变化这么长呢？我仔细观察测试服务器的负载情况，结果发现是受到了外界的影响。ngnix那边会一阵一阵的突然蹦一下，跑满5 6个核以上。然后平静下去又好了，结果就是导致这边跟着一阵一阵垃圾回收受到影响，继而在stop the world期间积压大量请求，导致的竞价服务处理不过来，又一波的CPU暴涨。蝴蝶效应，呵呵。至此至少已经确定不是我这边的问题，ngnix那边就由其它同事去看了。