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

Satar07發表於2022-05-01

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
    }
  ]
}

細心的小夥伴可以推一推執行這段程式碼時間是什麼時候呢~

相關文章