咱們該怎麼結合日誌作優化

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的風險。所以設置一個合理的任務插入等待時間和一個合理的隊列長度（不用太大），能夠保證相對較高的吞吐量。