咱们该怎么结合日志作优化

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的风险。所以设置一个合理的任务插入等待时间和一个合理的队列长度（不用太大），能够保证相对较高的吞吐量。