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

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那边就由其它同事去看了。

性能优化golang垃圾回收