我们该怎么结合日志做优化

1.前言

　　在日常工作中，我们常常会遇到随着业务的发展，系统的性能逐渐无法满足业务需求，这个时候就需要系统进行技术改造或者性能调优。技改可能会包括系统的重构甚至重写，功能的重新划分，但是只要是找了性能的瓶颈点，也许只是一些jvm参数或者常量的调优。

2.优化

　　为了寻找系统的性能瓶颈点，如果有一套完整图形化的监控系统固然是好事，但是很多情况都可能无法满足这个要求，更多的是通过日志来完成。因此，在合理的地方打印日志尤为重要。

　　上周某日下午，一个线上系统开始打印大量错误日志，查看日志发现错误基本为数据库唯一键冲突，通过分析发现日志发现该系统（下面以系统A称呼）的奖励发放功能在上一个奖罚发放还没有完成的情况下，又触发了新的奖励发放调用，奖励发放未半小时触发一次。因为奖励发放逻辑没有做并发同步处理，导致数据落库的时候发生唯一键冲突。因为是离线发放逻辑不考虑实时性，而且当前的数据量可以通过单机多线程并发处理，所以一方面通过redis锁保证同一时间只有一个奖励发放在处理，另一方面通过进行系统优化，尽可能的降低一次奖励发放的耗时。

　　系统A的处理逻辑为，系统A会定时收到系统B的调用，一次消息代表一次奖励发放任务，一次任务包含多个司机，需要分别对多个司机进行奖励发放。基本的处理逻辑是系统A在被调用后，获取任务所需基本信息，分批获取相关司机，多线程执行发放任务，每一次submit任务后都会sleep50毫秒，最后通过countdown同步等待异步任务处理完成，在整个任务的开始和结束的时候都会打印日志。为了确认单个任务的耗时，实现了下面的wrapper类

public class MarketingRunnableWrapper implements Runnable {
    private static final ILog logger = LogFactory.getLog("threadLogger");
    //任务名
    private String            taskName;
    //任务创建时间
    private Long              taskCreateTime;
    //日志flag
    private String            flag;
　　
　　 private Runnable runnable;


    public MarketingRunnableWrapper(Runnable runnable) {
        this(runnable, "");
    }

    public MarketingRunnableWrapper(Runnable runnable, String taskName) {
        this.runnable = runnable;this.taskName = taskName;
        this.taskCreateTime = System.nanoTime();
        this.flag = LogFactory.getFlag();
    }

    @Override
    public void run() {
        Long beginTime = System.nanoTime();
        try {
            runnable.run();
        } catch (Exception e) {
            String msg = "task: " + taskName + " run throw exception";
            msgLog(msg, e);
        } finally {
            String msg = String.format(
                    "task: %s executed, thread name = %s, delay time = %s ms, executing time = %s ms", taskName,
                    Thread.currentThread().getName(), (beginTime - taskCreateTime) / 1000000,
                    (System.nanoTime() - beginTime) / 1000000);
            msgLog(msg, null);
        }
    }

    private void msgLog(String msg, Exception e) {
        LogFactory.setFlag(flag);
        if (e == null) {
            logger.info(msg);
        } else {
            logger.error(msg, e);
        }
        LogFactory.removeFlag();
    }
}

　　该wrapper类实现了Runnable接口，打印一次task的执行的等待耗时和执行耗时。

　　根据日志打印和程序常量得到如下数据表：

	总耗时 Ttotal（s）	任务数Nt	总耗时 Ttotal/任务数Nt(ms)	任务总耗时Ttt（ms，相加耗时）	平均Taver/最大任务耗时Tmax（ms）	核心Ntcore/最大线程数Ntm	平均Taver/核心Ntcore(ms)
任务奖励(奖励)	126.000	2437	51.72	27344	11.22/43	10/10	1.1

 　　

　　上述表格中Ttt和Taver、Tmax都是从单线程的角度来说明的

1. 数据计算

　　　　任务添加等待时长Tw = 50ms

　　　　如果满线程跑的话，平均单个任务执行实际耗时Tstrt = Taver/Ntcore = 1.1ms

　　　　Tw远远大于Tstrt说明，基本只有一个线程在跑，而且还是跑跑停停，没有发挥多线程的优势

2. 分析

　　　　因为Twt大于Tstrt，说明添加等待限制了线程池的性能

　　　　平均每个任务执行实际耗时Trorign = Ttotal/Nt = 126000/2437 = 51.72ms ~ Tw(这也说明主要花在了等待上面)

3. 优化方案

　　　　将等待时间Tw修改为5ms

 

　　等待时间优化后，数据如下：

	总耗时 Ttotal（s）	任务数Nt	实际平均任务耗时Trtapt (总耗时 Ttotal/任务数Nt(ms))	Tw	任务总耗时Ttt（ms，相加耗时）	平均Taver/最大任务耗时Tmax（ms）	核心Ntcore/最大线程数Ntm	理论平均任务耗时Tctapt (平均Taver/核心Ntcore(ms))
任务奖励(奖励)	415.088	36259	11.5	10	1253473	34.56/147	10/10(公用)	3.5

 　　

　　从上面这个表可以看出Trtapt比Tctapt大，但是与Tw相近，说明现在主要的耗时还是由Tw，任务插入等待决定，所以还有一定的优化空间，但是相比之前的的吞吐量，提高了接近五倍。

　　那是否可以去掉插入等待的时间，直接将任务插入到队列中呢。由于为了保证内存空间不会OOM，一般会设置一个相对合理的队列长度，这样的话就是需要保证队列长度足够长，使得任务可以大批量的插入而不会block，或者设置合理的队列满的处理逻辑，而且较大的队列长度存在对内存空间的压力以及fullgc的风险。因此设置一个合理的任务插入等待时间和一个合理的队列长度（不用太大），可以保证相对较高的吞吐量。