一、问题描述

某交易系统在CPU资源配置5C、应用的并发进程数为30的情况下，TPS=22，此时CPU几乎跑满（87.5%）。鉴于CPU利用率饱和，提升CPU资源（从5C提升到10C）并相应的稍稍提高应用的并发进程数（从30提高到40）。然而意想不到的事情发生了，CPU（10C）利用率一直只有20%，大量报文堆积，TPS=7。

二、原因分析

EC=5情况下，TPS=22。CPU增加、线程增加后，TPS竟然明显下降了。可能由于多个线程共同争抢同一个或几个资源。软件线程如果要争抢资源，必须先去占用CPU，然后站在CPU上抢资源。以前CPU少，只有少量活着的软件线程争用资源；现在CPU多了，人为增加了并发线程，有更多的线程争用资源，导致该资源的有效使用时间下降。我们抓取AIX下的tprof数据显示，pthread lock/unlock占据了CPU消耗榜单的第二位（占16%），也从另一个侧面反映资源争用的情况。

那么可能的资源争用是什么呢？
数据库是多个进程共用的，日志是多个进程共同写的。
我们先看数据库的情况
查询数据库SQL语句执行时间。数据库是db2，采用下面的命令

db2 "select (TOTAL_CPU_TIME/NUM_EXEC_WITH_METRICS) avg_cpu_time,varchar(STMT_TEXT,800) stmt from table(mon_get_pkg_cache_stmt('s',null,null,-1)) as t where NUM_EXEC_WITH_METRICS<>0 order by avg_cpu_time desc fetch >

这里顺便提一下，这里AVG_CPU_TIME=(TOTAL_CPU_TIME/NUM_EXEC_WITH_METRICS)，即总时间除以执行次数，总时间TOTAL_CPU_TIME的单位是微秒，不是毫秒。

经监控，数据库SQL语句的执行时间最长的一条为8毫秒，第二位的4毫秒，其他不足1毫秒。而交易的处理时间大于1秒钟，因此数据库的SQL执行时间不足以解释报文处理时间长。同时，数据库的CPU（4C）利用率非常低，大概10%。数据库应该没有问题

因此，另一个可能的资源是“写日志”。
多个进程同时写日志，但同一个时刻日志文件只能有一个写入者，这就产生了进程对文件的争用。况且，tprof显示，pthread lock/unlock很严重，这个线程锁显然也是和数据库没什么关系的。

三、解决

为了验证这个问题，我们在日志上做功课，目的要证明写日志是“CPU利用率上不去”的瓶颈，那么只要减少写日志的频率就可以。

修改写日志的逻辑
1）分析写日志的代码，以前是一个字符一个字符往日志文件里面写，每次写都要有文件锁（系统自动加的），现在改为N个字符串合并为一个长串写入日志。

2）发现每次写日志都调用fflush（内存的脏数据刷入磁盘），比较消耗系统资源，严重影响效率，因此将fflush去掉，由系统自行决定什么时候把脏数据刷入磁盘，最新的日志在断电的时候会丢，但数据库里有业务的保存，业务的一致性并不会因为日志丢失而破坏。。

经修改，TPS从7提高到40。

通过上述的小实验，证明的了吞吐量下降是写日志导致的瓶颈。如果应用可以设置日志级别，也可以更方便的验证这个问题，前提是在正常业务的情况下，降低日志级别的确可以少写日志。

搜索微信号关注“性能测试与调优”