關於BenchMark/c++11計時器/Chrome:tracing 的一些筆記

A benchmark is a test of the performance of a computer system. 基準測試是對電腦系統的性能的測試計時器性能的指標就是時間，在c++11後計時十分方便，因為有<chrono>神器在性能測試中，一般依賴堆棧上的生命周期來進行計時 ...

A benchmark is a test of the performance of a computer system.

基準測試是對電腦系統的性能的測試

計時器

性能的指標就是時間，在c++11後計時十分方便，因為有<chrono>神器

在性能測試中，一般依賴堆棧上的生命周期來進行計時

計時器的實現全貌

class InstrumentationTimer {
private:
    chrono::time_point<chrono::steady_clock> start;
    const char *m_hint;

public:
    explicit InstrumentationTimer(const char *hint) : m_hint(hint) {
        start = chrono::steady_clock::now();
    }


    ~InstrumentationTimer() {
        auto end = chrono::steady_clock::now();
        cout << m_hint << ':' << static_cast<double>((end - start).count()) / 1e6 << "ms\n";
        long long llst = chrono::time_point_cast<chrono::microseconds>(start).time_since_epoch().count();
        long long lled = chrono::time_point_cast<chrono::microseconds>(end).time_since_epoch().count();

        //Instrumentor::Get().WriteProfile({m_hint, llst, lled});
    }
};

非常簡單的原理就是應用作用域自動調用析構函數來停止計時

唯一難搞的就是chrono的層層包裝

本文非常功利不深究底層 ~

time_pointer

chrono::time_point<chrono::steady_clock> start;

在chrono命名空間下（std下層）有個神奇的類型叫時間點time_point

在不同的操作環境下有不同的實現所以這是一個模板

模板類型可以有

chrono::high_resolution_clock 高解析度類型不建議使用因為這個可能有移植的問題但好像進度最高？
chrono::steady_clock 穩得一批的鐘我超愛這個因為這個不僅進度不低而且調用的時間短，影響極小（300ns
chrono::system_clock 系統帶的鐘不大行精度因系統而定？ windows是100ns

所以你懂的用steady就好了（也不用太糾結幾納秒

給時間點一個當前時間註意類型一致

start = chrono::steady_clock::now();

duration

auto  dur = end - start;

為啥用auto 因為方便昂（duration 模板具體化寫到頭皮發麻

時間點運算得到的是時間段因為預設的時間點單位時間是納秒（steady_clock），所以得到的時間是內部以longlong存儲的多少納秒

如何調出時間？

(end - start).count()

得到的是longlong ns

如何更改單位時間？

一個是轉換時間段的格式

chrono::duration_cast<chrono::microseconds>(end - start).count())

一個是轉換時間點的格式

chrono::time_point_cast<chrono::microseconds>(start)

如何調出一個時間戳？（系統從我也不知道哪開始算起的時間段 1970.1.1大概？相當於幫你減了一下

start.time_since_epoch().count()

可選格式：

chrono::nanoseconds
chrono::microseconds
chrono::milliseconds
chrono::seconds
chrono::minutes
chrono::hours

回到實現

構造函數沒啥好講的就是開始計時

重點是析構函數

~InstrumentationTimer() {
        auto end = chrono::steady_clock::now();
        cout << m_hint << ':' << static_cast<double>((end - start).count()) / 1e6 << "ms\n";
        long long llst = chrono::time_point_cast<chrono::microseconds>(start).time_since_epoch().count();
        long long lled = chrono::time_point_cast<chrono::microseconds>(end).time_since_epoch().count();

        Instrumentor::Get().WriteProfile({m_hint, llst, lled});
    }

思路：

首先！！！一定先停止計時（你不會還想增大誤差吧）用auto接住省一個成員
然後輸出的是你要計時的位置的註釋（hint）接一個時間段

因為時間段輸出的是longlong 我看多了幾點幾ms覺得非常親切所以用納秒算時間段（預設）後再除1e6得到毫秒
留兩個時間戳後面有用
然後是後面的調用記錄某一段程式運行時間的函數啦這裡傳進去的有hint 開始和結束的時間戳有了這些你就能算出經過的時間

整理輸出部分

Chrome大法好

chromo 自帶了個可視化分析軟體在地址欄上輸入chrome://tracing/就可以看到

它接受的是json文件所以我們要把我們記錄下來的東西打包成json拖到界面上就可以看到精美（並不）的可視化界面

這是打包器+記錄器的全貌

class Instrumentor {
private:
    ofstream m_OutputStream;
    bool m_Fir;

public:
    Instrumentor() : m_Fir(true) {}

    void BeginSession(const string &filepath = "results.json") {
        m_OutputStream.open(filepath);
        WriteHeader();

    }

    void EndSession() {
        WriteFooter();
        m_OutputStream.close();
        m_Fir = true;
    }

    void WriteProfile(const ProfileResult &result) {
        if (!m_Fir) { //not add ',' when first time
            m_OutputStream << ',';
        } else m_Fir = false;

        string name(result.Name);
        replace(name.begin(), name.end(), '"', '\'');
        m_OutputStream << R"({)";
        m_OutputStream << R"("cat":"function",)";
        m_OutputStream << R"("dur":)" << result.end - result.start << ",";
        m_OutputStream << R"("name":")" << name << "\",";
        m_OutputStream << R"("ph":"X",)";
        m_OutputStream << R"("pid":0,)";
        m_OutputStream << R"("tid":0,)";
        m_OutputStream << R"("ts":)" << result.start;
        m_OutputStream << R"(})";
        m_OutputStream.flush();
    }

    void WriteHeader() {
        m_OutputStream << R"({"otherData":{},"traceEvents":[)";
        m_OutputStream.flush();
    }

    void WriteFooter() {
        m_OutputStream << "]}";
        m_OutputStream.flush();
    }

    static Instrumentor &Get() {
        static auto instance = new Instrumentor();
        return *instance;
    }
};

以及我們的目標 Chrome能識別的json文件

{
  "otherData": {},
  "traceEvents": [
    {
      "cat": "function",
      "dur": 2166411,
      "name": "void core1(int)",
      "ph": "X",
      "pid": 0,
      "tid": 0,
      "ts": 19699253339
    },
    {
      "cat": "function",
      "dur": 1649285,
      "name": "void core2()",
      "ph": "X",
      "pid": 0,
      "tid": 0,
      "ts": 19701420118
    },
    {
      "cat": "function",
      "dur": 3816266,
      "name": "void benchMark()",
      "ph": "X",
      "pid": 0,
      "tid": 0,
      "ts": 19699253338
    }
  ]
}

Get( )

首先看到最後的Get( )

static Instrumentor &Get() {
    static auto instance = new Instrumentor();
    return *instance;
}

這個能提供給我們一個單例，就是僅存在一個與我們運行時的對象

static 顯式的指出Get得到的東西是和我們exe文件存在時間一樣長的而且這個定義只執行一次

如果你沒有聽懂就只要記住它返回的永遠是同一個對象要用這個對象的時候就用Get

該這麼用：

Instrumentor::Get().balabala();

初始化

private:
    ofstream m_OutputStream;
    bool m_Fir;

public:
    Instrumentor() : m_Fir(true) {}

    void BeginSession(const string &filepath = "results.json") {
        m_OutputStream.open(filepath);
        WriteHeader();

    }

    void EndSession() {
        WriteFooter();
        m_OutputStream.close();
        m_Fir = true;
    }

ofsteam文件輸出流用於輸出到文件預設是results.json

不要忘記列表中的逗號的處理我們用m_Fir檢測是不是第一個

然後是註意到json開頭和結尾是固定的

void WriteHeader() {
    m_OutputStream << R"({"otherData":{},"traceEvents":[)";
    m_OutputStream.flush();
}

void WriteFooter() {
    m_OutputStream << "]}";
    m_OutputStream.flush();
}

R"( string )"即原始字元串可以輸出字元串裡面的原本的字元感興趣的可以自行拓展更多有關知識這裡用了之後就不用打轉義的雙引號了

每次輸出到文件時記得及時刷新 m_OutputStream.flush();防止之後的線程出現毛病

ok 現在我們可以這麼用了

int main() {
    Instrumentor::Get().BeginSession();
    benchMark(); //測試的函數放這裡
    Instrumentor::Get().EndSession();
}

中間列表的填寫

但是？最最最重要的中間列表的填寫呢？

在這裡

void WriteProfile(const ProfileResult &result) {
    if (!m_Fir) { //not add ',' when first time
        m_OutputStream << ',';
    } else m_Fir = false;

    string name(result.Name);
    replace(name.begin(), name.end(), '"', '\'');
    m_OutputStream << R"({)";
    m_OutputStream << R"("cat":"function",)";
    m_OutputStream << R"("dur":)" << result.end - result.start << ",";
    m_OutputStream << R"("name":")" << name << "\",";
    m_OutputStream << R"("ph":"X",)";
    m_OutputStream << R"("pid":0,)";
    m_OutputStream << R"("tid":0,)";
    m_OutputStream << R"("ts":)" << result.start;
    m_OutputStream << R"(})";
    m_OutputStream.flush();
}

在InstrumentationTimer中的調用：

//m_hint 是計時器註釋  llst 開始時間戳  lled 結束時間戳
Instrumentor::Get().WriteProfile({m_hint, llst, lled});

定義傳進來的參數可以擴展

struct ProfileResult {
    string Name;
    long long start, end;
};

就是簡單的往裡面塞東西啦

值得註意的是 chrome 的tracing 預設時間戳的單位時間是microseconds 即毫秒所以要記得轉換格式哦

long long llst = chrono::time_point_cast<chrono::microseconds>(start).time_since_epoch().count();
long long lled = chrono::time_point_cast<chrono::microseconds>(end).time_since_epoch().count();

考慮到傳進來的函數名字可能會帶有" " 讓json出錯所以退而求其次把它轉成 ' ' (其實在前面加一個轉義字元更好但是實現起來太麻煩了)

string name(result.Name);
replace(name.begin(), name.end(), '"', '\'');

好啦包裝弄好了下一步開始高效插樁

打樁

神說：“我怕麻煩。”

於是就有了巨集

低級打樁

先看

void core1() {
    InstrumentationTimer tt("halo world 0 to 9999");
    for (int i = 0; i < 10000; ++i) {
        cout << "Hello world #" << i << endl;
    }
}

void benchMark() {
    InstrumentationTimer tt("shart benchMark");
    core1();
}

在一個函數的開頭放上計時器計時器就會自動記錄這個作用域自它定義開始到結束所經過的時間和有關的信息

在計時器銷毀前幾微秒它會將它所看到的的東西傳給Instrumentor來記錄所發生的事情

但是！！這未免也太傻了

為什麼還要我手動給一個名字

讓它自動生成獨一無二的名字就行了嘛

中級打樁

有那麼個巨集是所有編輯器都能自動展開的叫 __FUNCTION__ 它會變成它所在的函數的名字的字元串

於是就有了

#define PROFILE_SCOPE(name) InstrumentationTimer tt(name)
#define PROFILE_FUNCTION() PROFILE_SCOPE(__FUNCTION__)

void core1() {
    PROFILE_FUNCTION();
    for (int i = 0; i < 10000; ++i) {
        cout << "Hello world #" << i << endl;
    }
}

void benchMark() {
    PROFILE_FUNCTION();
    core1();
}

好但還不夠好

所有的計時器都是一個名稱萬一不小心重名了那事情就不好整了

又有一個巨集叫 __LINE__ 它會變成所在行號（數字）

而巨集能用神奇的 #將東西黏在一起

就有了

#define PROFILE_SCOPE(name) InstrumentationTimer tt##__LINE__(name)

好但還不夠好

萬一我的函數是重載的輸出的是一樣的函數名字我咋知道調用的是哪個版本的函數

又有一個巨集叫 __PRETTY_FUNCTION__ MSVC是 __FUNCSIG__它能變成完整的函數簽名的字元串就像 "void core1(int)"

#define PROFILE_FUNCTION() PROFILE_SCOPE(__PRETTY_FUNCTION__)

好但還不夠好

這個我可不想把它保留在release下讓用戶也幫我測測時間怎麼才能方便的關掉呢

對還是巨集

高級打樁

#define PROFILING 1
#if PROFILING
#define PROFILE_SCOPE(name) InstrumentationTimer tt##__LINE__(name)
#define PROFILE_FUNCTION() PROFILE_SCOPE(__PRETTY_FUNCTION__)
#else
#define PROFILE_SCOPE(name)
#define PROFILE_FUNCTION()
#endif

void core(int useless) {
    PROFILE_FUNCTION();
    for (int i = 0; i < 10000; ++i) {
        cout << "Hello world #" << i << endl;
    }
}

void core() {
    PROFILE_FUNCTION();
    for (int i = 0; i < 10000; ++i) {
        cout << "Hello world #" << sqrt(i) << endl;
    }
}

void benchMark() {
    PROFILE_FUNCTION();
    core(23333);
    core();
}

這就是了如果我想關掉測試就把profiling設為1 這是所有測試都只是空行而release對於沒有使用的函數則自動刪去了絲毫不影響性能

多線程

擴展

拓展ProfileResult

struct ProfileResult {
    string Name;
    long long start, end;
    uint32_t TheadID;
};

更改輸出

m_OutputStream << R"("tid":)" << result.TheadID << ",";

在Timer中捕獲該線程的id 並用自帶hash轉換成uint32方便輸出

uint32_t threadID = hash<std::thread::id>{}(std::this_thread::get_id());

傳遞id

Instrumentor::Get().WriteProfile({m_hint, llst, lled,threadID});

最後變成了這樣

~InstrumentationTimer() {
    auto end = chrono::steady_clock::now();
    cout << m_hint << ':' << static_cast<double>((end - start).count()) / 1e6 << "ms\n";
    long long llst = chrono::time_point_cast<chrono::microseconds>(start).time_since_epoch().count();
    long long lled = chrono::time_point_cast<chrono::microseconds>(end).time_since_epoch().count();

    uint32_t threadID = hash<std::thread::id>{}(std::this_thread::get_id());

    Instrumentor::Get().WriteProfile({m_hint, llst, lled,threadID});
}

測試

搞一個多線程出來

void benchMark() {
    PROFILE_FUNCTION();
    cout << "Running BenchMarks...\n";
    thread a([]() { core(23333); });
    thread b([]() { core(); });

    a.join();
    b.join();
}

用lamda可以非常簡潔的開多線程重載函數

最後加入2個join函數這樣在這兩個線程都完成它們的工作之前我們不會真正退出這個benchmark函數

完成

好啦我們的工作完成了欣賞一下代碼吧

#include <bits/stdc++.h>
#include <sstream>

using namespace std;

struct ProfileResult {
    string Name;
    long long start, end;
    uint32_t TheadID;
};

class Instrumentor {
private:
    ofstream m_OutputStream;
    bool m_Fir;

public:
    Instrumentor() : m_Fir(true) {}

    void BeginSession(const string &filepath = "results.json") {
        m_OutputStream.open(filepath);
        WriteHeader();

    }

    void EndSession() {
        WriteFooter();
        m_OutputStream.close();
        m_Fir = true;
    }

    void WriteProfile(const ProfileResult &result) {
        if (!m_Fir) { //not add ',' when first time
            m_OutputStream << ',';
        } else m_Fir = false;

        string name(result.Name);
        replace(name.begin(), name.end(), '"', '\'');
        m_OutputStream << R"({)";
        m_OutputStream << R"("cat":"function",)";
        m_OutputStream << R"("dur":)" << result.end - result.start << ",";
        m_OutputStream << R"("name":")" << name << "\",";
        m_OutputStream << R"("ph":"X",)";
        m_OutputStream << R"("pid":0,)";
        m_OutputStream << R"("tid":)" << result.TheadID << ",";
        m_OutputStream << R"("ts":)" << result.start;
        m_OutputStream << R"(})";
        m_OutputStream.flush();
    }

    void WriteHeader() {
        m_OutputStream << R"({"otherData":{},"traceEvents":[)";
        m_OutputStream.flush();
    }

    void WriteFooter() {
        m_OutputStream << "]}";
        m_OutputStream.flush();
    }

    static Instrumentor &Get() {
        static auto instance = new Instrumentor();
        return *instance;
    }
};


class InstrumentationTimer {
private:
    chrono::time_point<chrono::steady_clock> start;
    const char *m_hint;

public:
    explicit InstrumentationTimer(const char *hint) : m_hint(hint) {
        start = chrono::steady_clock::now();
    }


    ~InstrumentationTimer() {
        auto end = chrono::steady_clock::now();
        cout << m_hint << ':' << static_cast<double>((end - start).count()) / 1e6 << "ms\n";
        long long llst = chrono::time_point_cast<chrono::microseconds>(start).time_since_epoch().count();
        long long lled = chrono::time_point_cast<chrono::microseconds>(end).time_since_epoch().count();

        uint32_t threadID = hash<std::thread::id>{}(std::this_thread::get_id());

        Instrumentor::Get().WriteProfile({m_hint, llst, lled,threadID});
    }
};

#define PROFILING 1
#if PROFILING
#define PROFILE_SCOPE(name) InstrumentationTimer tt##__LINE__(name)
#define PROFILE_FUNCTION() PROFILE_SCOPE(__PRETTY_FUNCTION__)
#else
#define PROFILE_SCOPE(name)
#define PROFILE_FUNCTION()
#endif

void core(int useless) {
    PROFILE_FUNCTION();
    for (int i = 0; i < 10000; ++i) {
        cout << "Hello world #" << i << endl;
    }
}

void core() {
    PROFILE_FUNCTION();
    for (int i = 0; i < 10000; ++i) {
        cout << "Hello world #" << sqrt(i) << endl;
    }
}

void benchMark() {
    PROFILE_FUNCTION();
    cout << "Running BenchMarks...\n";
    thread a([]() { core(23333); });
    thread b([]() { core(); });

    a.join();
    b.join();
}


int main() {
    Instrumentor::Get().BeginSession();
    benchMark();
    Instrumentor::Get().EndSession();
}

最後的json

{
  "otherData": {},
  "traceEvents": [
    {
      "cat": "function",
      "dur": 3844575,
      "name": "void core(int)",
      "ph": "X",
      "pid": 0,
      "tid": 1709724944,
      "ts": 24887197644
    },
    {
      "cat": "function",
      "dur": 4039317,
      "name": "void core()",
      "ph": "X",
      "pid": 0,
      "tid": 2740856708,
      "ts": 24887197714
    },
    {
      "cat": "function",
      "dur": 4040539,
      "name": "void benchMark()",
      "ph": "X",
      "pid": 0,
      "tid": 2850328247,
      "ts": 24887196811
    }
  ]
}

細心的小伙伴可以推一推運行這段代碼時間是什麼時候呢~