程序運算性能測量

定量分析是一切優化過程當中最重要的過程之一。在性能優化和分析中，咱們如何來描述一段代碼的執行效率呢？這裏，我將這一過程分爲2步。

第一步：咱們要找到一個客觀的、相對穩定的單位，來描述一個程序的運行時間；

第二步：構造合理的、更接近起初狀況的測試用例來進行測量。

這樣，最終獲得的結果，就是對於一段代碼執行效率的客觀描述。

1、單位肯定

首先，咱們要肯定下來描述單位。一般來講，時間差被普遍地用作描述計算能力的單位。顧名思議，就是在代碼前記下一個時間T1，在執行後記下一個時間T2。而後經過計算∆ = T2 - T1便可獲得執行的時長。這種方法方便、快捷，並且也較爲準確。它被普遍地用於對計算能力的約束上。如，暴力破解某某密碼要幾小時等等。相信你們都熟悉下面一段話：

「1976年9月，美國數學家阿佩爾和哈肯利用IBM360計算機工做了1200多個小時，終於證實了四色問題是正確的，轟動了世界。今後四色問題變成了四色定理。」

細心的讀者必定已經發現，單純的「1200多個小時」是不可以描述四色問題的驗證過程時間的，它每每要跟上一個前提，在IBM360機器，要求有同型號、子型號、同頻率、同批次的CPU，才能夠獲得相同的結果。那麼，是否有更加客觀的單位能夠描述代碼的執行能力呢？這個單位必定符合5個條件。

1）精度高——它不可能比時間精度低，經過gettimeofday獲得的時間能夠精確至「」；

2）時間相關——咱們能夠從它通過計算轉換爲相對時間：秒；

3）低耦合——儘可能不要與CPU的主頻等主要參數有過多的關係，換一臺機器後它的值變化不會很大；

4）相對穩定——不會致使先後2次測量的變化過大。

CPU時鐘週期，咱們想到了這個基礎單位。它的單位是Tick，對於主流的0.5GHz-2.0GHz的機器上，它分別能夠精確至「」。咱們能夠將它與CPU主頻進行相乘來獲得相對時間。對於支持Pipeline、L1/L2 Cache，指令集相同的CPU，它的差異並不大。因爲CPU週期是由硬件晶振控制的，在硬件不出故障狀況下，它相對穩定。它徹底符合精度高、時間相關、低耦合以及相對穩定4個特色。本文後續的討論將所有基於CPU時間週期來進行討論。

2、測量方法

咱們已經肯定了用納秒級的計量單位「CPU時鐘週期」。如何才能得到系統當前的CPU時鐘週期呢？INTEL® CPU提供了一個64位的寄存器TSC來存儲自開機來的週期值。並可經過指令「rdtsc」將其寫入edx:eax。因此，咱們能夠在代碼中插入這樣的語句。

 

 

#define rdtscll_64(val) do {\
unsigned int __a,__d; \
__asm__ __volatile__("rdtsc" : "=a" (__a), "=d" (__d)); \
(val) = (((unsigned long long)__d)<<32) | (__a); \
} while(0);

 

經過調用rdtscll便可以獲得64位的CPU時鐘週期數。

3、測量偏差

在瞭解測量方法以後，一樣咱們要了解到這個測量方法在哪些狀況下會產生偏差。

從TSC自己來講，最多見的偏差即是多核的影響。CPU並不會對多個核的tsc進行同步，因此，咱們首先要保證測量過程是在同一個核上進程的。若是被測代碼段執行過程當中存在進程切換，則測量值必定不會很準。因此若是咱們在測量的過程當中要保證被測量函數不要進行進程切換。也就是說若是被測函數有異步IO調用，咱們則須要將進程綁定在一個核上。

因爲cache的存在，致使咱們在對訪問密集型的代碼進行測量的時候，先後2次測量的結果可能相差5-10倍，因此當咱們但願得到單次非cache內內存得到開銷的時候，咱們須要須要取構造一個複雜的case。

時下很是流行的虛擬機技術也會影響測量的結果，由於有些虛擬機本身模擬了這個TSC這樣咱們拿到的值就是物理機硬件的tsc。由於在對虛擬機進行統計的時候須要關注它是如何得到TSC的。

固然，TSC自己也是有開銷的，雖然它很小。大概在20-40個週期。

4、基本操做測量

1. 連續內存寫操做

很是簡單，只要memset一個大內存就OK了

2. 隨機內存寫操做

咱們須要構造一個大的block_list，每2個相信節點間的距離都要大於 cache大小，且並不相等，前、後關係也不盡相同。同時，咱們經過 memset一個和cache相同大小的buff來清空cache。即可以測量出隨機內存寫操做的開銷。

3. 一些基本操做的開銷

操做	平均週期數	操做	平均週期數
連續內存訪問(4byte)	10	浮點數值運算（+、-、*)	10-12
隨機內存訪問(4byte)	208	浮點數值運算（/）	14
整數數值運算	7	系統隨機	46
		三角函數（sin/cos）	135

5、範例：函數耗時分析

測試使用的CPU信息以下：

範例分別用CTscStat和CTimeStat類來測量funcA，funcB和funcC，用usleep來模擬真實函數的耗時。

代碼說明：

#include <unistd.h>  
#include <stdlib.h>  
#include <stdio.h>  
#include <string.h>  
#include <errno.h>  
#include <fcntl.h>
#include <sys/time.h>
#include <string>
#include <vector>
#include <stdint.h>

#define rdtscll_64(val) do {\
unsigned int __a,__d; \
__asm__ __volatile__("rdtsc" : "=a" (__a), "=d" (__d)); \
(val) = (((unsigned long long)__d)<<32) | (__a); \
} while(0);

class CTscStat
{
public:
    CTscStat(const std::string& sCallerName)
    : m_sCallerName(sCallerName)
    {
        rdtscll_64(m_start);
        rdtscll_64(m_lastcall);
    }

    ~CTscStat()
    {
        uint64_t end;
        rdtscll_64(end);
        uint64_t totalConsumeTsc = end - m_start;
        printf("TscStat---TOTAL:func=[%s] tsc_cost=[%lu]\n", m_sCallerName.c_str(), totalConsumeTsc);
    }

    void AddCall(const std::string& sCall)
    {
        AddCall(sCall, GetTscSub());
    }

private:
    void AddCall(const std::string& sCallerName, uint64_t consumeTsc)
    {
        printf("TscStat---SubCall:func=[%s] sub_func=[%s] tsc_cost=[%lu]\n",
            m_sCallerName.c_str(), sCallerName.c_str(), consumeTsc);
        rdtscll_64(m_lastcall);
    }

    uint64_t GetTscSub()
    {
        uint64_t now;
        rdtscll_64(now);
        
        return now - m_lastcall;
    }

private:
    struct SCall
    {
        std::string sCallerName;
        uint64_t    consumeTsc;
    };

private:
    std::string         m_sCallerName;  // 統計接口
    std::vector<SCall>  m_vecCall;      // 請求列表

    uint64_t            m_start;        // 開始TSC
    uint64_t            m_lastcall;     // 上次TSC
};

#define TSC_START(sCn) CTscStat oTscS(sCn);
#define TSC_APICALL(API) \
        do { \
            oTscS.AddCall(API); \
        } while(0)

class CTimeStat
{
public:
    CTimeStat(const std::string& sCallerName)
    : m_sCallerName(sCallerName)
    {
        gettimeofday(&m_start, 0);
        gettimeofday(&m_lastcall, 0);
    }

    ~CTimeStat()
    {
        struct timeval end;
        struct timeval subresult;

        gettimeofday(&end, 0);
        timersub(&end, &m_start, &subresult);
        uint32_t dwTotalConsumeTime = subresult.tv_sec * 1000 + subresult.tv_usec / 1000;

        printf("TimeStat---TOTAL:func=[%s] time_cost=[%u]\n", m_sCallerName.c_str(), dwTotalConsumeTime);
    }

    void AddCall(const std::string& sCall)
    {
        AddCall(sCall, GetTimeSub());
    }

private:
    void AddCall(const std::string& sCallerName, uint32_t dwConsumeTime)
    {
        printf("TimeStat---SubCall:func=[%s] sub_func=[%s] time_cost=[%u]\n",
            m_sCallerName.c_str(), sCallerName.c_str(), dwConsumeTime);
        gettimeofday(&m_lastcall, 0);
    }

    uint32_t GetTimeSub()
    {
        struct timeval now;
        struct timeval subresult;
        gettimeofday(&now, 0);

        timersub(&now, &m_lastcall, &subresult);

        return subresult.tv_sec * 1000 + subresult.tv_usec / 1000;
    }

private:
    struct SCall
    {
        std::string sCallerName;
        uint32_t    dwConsumeTime;
    };

private:
    std::string         m_sCallerName;  // 統計接口
    std::vector<SCall>  m_vecCall;      // 請求列表

    struct timeval      m_start;        // 開始時間
    struct timeval      m_lastcall;     // 上次請求時間
};

#define TS_START(sCn) CTimeStat oTimeS(sCn);
#define TS_APICALL(API) \
        do { \
            oTimeS.AddCall(API); \
        } while(0)

void funcA()
{
    usleep(1000); // 1ms
}

void funcB()
{
    usleep(100000); // 100ms
}

void funcC()
{
    sleep(1); // 1s
}

void TestTsc()
{
    TSC_START("TestTsc");
    funcA();
    TSC_APICALL("funcA");
    funcB();
    TSC_APICALL("funcB");
    funcC();
    TSC_APICALL("funcC");
}

void TestTime()
{
    TS_START("TestTsc");
    funcA();
    TS_APICALL("funcA");
    funcB();
    TS_APICALL("funcB");
    funcC();
    TS_APICALL("funcC");
}

int main(int argc, char** argv)  
{ 
    ////////// tsc ///////////
    TestTsc();
    
    ///////// time ///////////
    TestTime();
    
    return 0;
}

結果說明：

[root@rocket linux_programming]# ./module_perform

TscStat---SubCall:func=[TestTsc] sub_func=[funcA] tsc_cost=[6391184]

TscStat---SubCall:func=[TestTsc] sub_func=[funcB] tsc_cost=[362433912]

TscStat---SubCall:func=[TestTsc] sub_func=[funcC] tsc_cost=[3595441050]

TscStat---TOTAL:func=[TestTsc] tsc_cost=[3964662011]

TimeStat---SubCall:func=[TestTsc] sub_func=[funcA] time_cost=[2]

TimeStat---SubCall:func=[TestTsc] sub_func=[funcB] time_cost=[100]

TimeStat---SubCall:func=[TestTsc] sub_func=[funcC] time_cost=[1000]

TimeStat---TOTAL:func=[TestTsc] time_cost=[1104]

能夠看到，當sleep 1ms的時候，測試結果與預期有較大差距，這個跟系統的精度有關。

當sleep 1s 和100ms的時候用Tsc測量的結果分別是主頻和主頻的1/10。