论代码级性能优化变迁之路(一)

一、前言

大家好，很久没有和大家一起讨论技术了，那么今天我将和大家一起探讨我负责的某项目的性能变迁之路。

我们以前看到的很多架构变迁或者演进方面的文章大多都是针对架构方面的介绍，很少有针对代码级别的性能优化介绍，这就好比盖楼一样，楼房的基础架子搭的很好，但是盖房的工人不够专业，有很多需要注意的地方忽略了，那么在往里面填砖加瓦的时候出了问题，后果就是房子经常漏雨，墙上有裂缝等各种问题出现，虽然不至于楼房塌陷，但楼房也已经变成了危楼。那么今天我们就将针对一些代码细节方面的东西进行介绍，欢迎大家吐槽以及提建议。

二、服务器环境

服务器配置：4核CPU 8G内存 共4台

MQ：RabbitMQ

数据库：DB2

SOA框架：公司内部封装的Dubbo

缓存框架：Redis，Memcached

统一配置管理系统：公司内部开发的系统

三、问题描述

1、单台40TPS，加到4台服务器能到60TPS，扩展性几乎没有。

2、在实际生产环境中，经常出现数据库死锁导致整个服务中断不可用。

3、数据库事务乱用，导致事务占用时间太长。

4、在实际生产环境中，服务器经常出现内存溢出和CPU时间被占满。

5、程序开发的过程中，考虑不全面，容错很差，经常因为一个小bug而导致服务不可用。

6、程序中没有打印关键日志，或者打印了日志，信息却是无用信息没有任何参考价值。

7、配置信息和变动不大的信息依然会从数据库中频繁读取，导致数据库IO很大。

8、项目拆分不彻底，一个tomcat中会布署多个项目WAR包。

9、因为基础平台的bug，或者功能缺陷导致程序可用性降低。

10、程序接口中没有限流策略，导致很多vip商户直接拿我们的生产环境进行压测，直接影响真正的服务可用性。

11、没有故障降级策略，项目出了问题后解决的时间较长，或者直接粗暴的回滚项目，但是不一定能解决问题。

12、没有合适的监控系统，不能准实时或者提前发现项目瓶颈。

四、优化解决方案

1、数据库死锁优化解决

我们从第二条开始分析，先看一个基本例子展示数据库死锁的发生：

在上述事例中，会话B会抛出死锁异常，死锁的原因就是A和B二个会话互相等待。

分析：出现这种问题就是我们在项目中混杂了大量的事务+for update语句，针对数据库锁来说有下面三种基本锁：

当for update语句和gap lock和next-key lock锁相混合使用，又没有注意用法的时候，就非常容易出现死锁的情况。

那我们用大量的锁的目的是什么，经过业务分析发现，其实就是为了防重，同一时刻有可能会有多笔支付单发到相应系统中，而防重措施是通过在某条记录上加锁的方式来进行。

针对以上问题完全没有必要使用悲观锁的方式来进行防重，不仅对数据库本身造成极大的压力，同时也会把对于项目扩展性来说也是很大的扩展瓶颈，我们采用了三种方法来解决以上问题：

* 使用Redis来做分布式锁，Redis采用多个来进行分片，其中一个Redis挂了也没关系，重新争抢就可以了。

• 使用主键防重方法，在方法的入口处使用防重表，能够拦截所有重复的订单，当重复插入时数据库会报一个重复错，程序直接返回。
• 使用版本号的机制来防重。

  以上三种方式都必须要有过期时间，当锁定某一资源超时的时候，能够释放资源让竞争重新开始。

2、数据库事务占用时间过长

伪代码示例：

public void test() {
    Transaction.begin  //事务开启
    try {
        dao.insert //插入一行记录
        httpClient.queryRemoteResult()  //请求访问
        dao.update //更新一行记录
        Transaction.commit()  //事务提交
    } catch(Exception e) {
          Transaction.rollFor //事务回滚
    }
}

项目中类似这样的程序有很多，经常把类似httpClient，或者有可能会造成长时间超时的操作混在事务代码中，不仅会造成事务执行时间超长，而且也会严重降低并发能力。

那么我们在用事务的时候，遵循的原则是快进快出，事务代码要尽量小。针对以上伪代码，我们要用httpClient这一行拆分出来，避免同事务性的代码混在一起，这不是一个好习惯。

3、CPU时间被占满分析

下面以我之前分析的一个案例作为问题的起始点，首先看下面的图：

项目在压测的过程中，cpu一直居高不下，那么通过分析得出如下分析：

• 数据库连接池影响

我们针对线上的环境进行模拟，尽量真实的在测试环境中再现，采用数据库连接池为咱们默认的C3P0。

那么当压测到二万批，100个用户同时访问的时候，并发量突然降为零！报错如下：

com.yeepay.g3.utils.common.exception.YeepayRuntimeException: Could not get JDBC Connection; nested exception is java.sql.SQLException: An attempt by a client to checkout a Connection has timed out.

那么针对以上错误跟踪C3P0源码，以及在网上搜索资料：

http://blog.sina.com.cn/s/blog_53923f940100g6as.html

发现C3P0在大并发下表现的性能不佳。

• 线程池使用不当引起

private static final ExecutorService executorService = Executors.newCachedThreadPool();
 /**
 * 异步执行短频快的任务
 * @param task
 */
 public static void asynShortTask(Runnable task){
  executorService.submit(task);
  //task.run();
 }

           CommonUtils.asynShortTask(new Runnable() {
                @Override
                public void run() {
                    String sms = sr.getSmsContent();
                    sms = sms.replaceAll(finalCode, AES.encryptToBase64(finalCode, ConstantUtils.getDB_AES_KEY()));
                    sr.setSmsContent(sms);
                    smsManageService.addSmsRecord(sr);
                }
            });

以上代码的场景是每一次并发请求过来，都会创建一个线程，将DUMP日志导出进行分析发现，项目中启动了一万多个线程，而且每个线程都极为忙碌，彻底将资源耗尽。

那么问题到底在哪里呢？？？就在这一行！

private static final ExecutorService executorService = Executors.newCachedThreadPool();

在并发的情况下，无限制的申请线程资源造成性能严重下降，在图表中显抛物线形状的元凶就是它！！！那么采用这种方式最大可以产生多少个线程呢？？答案是：Integer的最大值！看如下源码：

那么尝试修改成如下代码：

private static final ExecutorService executorService = Executors.newFixedThreadPool(50);

修改完成以后，并发量重新上升到100以上TPS，但是当并发量非常大的时候，项目GC（垃圾回收能力下降），分析原因还是因为Executors.newFixedThreadPool(50)这一行，虽然解决了产生无限线程的问题，但是当并发量非常大的时候，采用newFixedThreadPool这种方式，会造成大量对象堆积到队列中无法及时消费，看源码如下：

可以看到采用的是无界队列，也就是说队列是可以无限的存放可执行的线程，造成大量对象无法释放和回收。

最终线程池技术方案

方案一：

注：因为服务器的CPU只有4核，有的服务器甚至只有2核，所以在应用程序中大量使用线程的话，反而会造成性能影响，针对这样的问题，我们将所有异步任务全部拆出应用项目，以任务的方式发送到专门的任务处理器处理，处理完成回调应用程序器。后端定时任务会定时扫描任务表，定时将超时未处理的异步任务再次发送到任务处理器进行处理。

方案二：

使用AKKA技术框架，下面是我以前写的一个简单的压测情况：

http://www.jianshu.com/p/6d62256e3327

4、日志打印问题

先看下面这段日志打印程序：

QuataDTO quataDTO = null;
        try {
            quataDTO = getRiskLimit(payRequest.getQueryRiskInfo(), payRequest.getMerchantNo(), payRequest.getIndustryCatalog(), cardBinResDTO.getCardType(), cardBinResDTO.getBankCode(), bizName);
        } catch (Exception e) {
            logger.info("获取风控限额异常", e);
        }

像这样的代码是严格不符合规范的，虽然每个公司都有自己的打印要求。

* 首先日志的打印必须是以logger.error或者logger.warn的方式打印出来。

* 日志打印格式：[系统来源] 错误描述 [关键信息]，日志信息要能打印出能看懂的信息，有前因和后果。甚至有些方法的入参和出参也要考虑打印出来。

* 在输入错误信息的时候，Exception不要以e.getMessage的方式打印出来。

合理的日志格式是：

logger.warn("[innersys] - [" + exceptionType.description + "] - [" + methodName + "] - "
                + "errorCode:[" + errorCode + "], "
                + "errorMsg:[" + errorMsg + "]", e);

logger.info("[innersys] - [入参] - [" + methodName + "] - "
                    + LogInfoEncryptUtil.getLogString(arguments) + "]");

logger.info("[innersys] - [返回结果] - [" + methodName + "] - " + LogInfoEncryptUtil.getLogString(result));

我们在程序中大量的打印日志，虽然能够打印很多有用信息帮助我们排查问题，但是更多是日志量太多不仅影响磁盘IO，更多会造成线程阻塞对程序的性能造成较大影响。

在使用Log4j1.2.14版本的时候，使用如下格式：

%d %-5p %c:%L [%t] - %m%n

那么在压测的时候会出现下面大量的线程阻塞，如下图：

再看压测图如下：

原因可以根据log4j源码分析如下：

**注：**Log4j源码里用了synchronized锁，然后又通过打印堆栈来获取行号，在高并发下可能就会出现上面的情况。

于是修改log4j配置文件为：

%d %-5p %c [%t] - %m%n

上面问题解决，线程阻塞的情况很少出现，极大的提高了程序的并发能力，如下图所示：

未完待续，接下来将是“论代码级性能优化变迁之路（二）”敬请期待！