小技巧｜异构计算中C++ host 部分的性能测试（普通C++程序也适用）

​ 在对项目的某个功能模块进行优化的时候，刚开始都是使用封装好的 Timer 类去测试（再最后也放上 Timer 类的代码），但是只有添加了 Timer 的地方才可以记录到时间，这个记录的粒度非常不好控制，比如测试了整个函数体用时的话，函数体之内用时占比就还需要更详细的测试。

FlameGraph

​ 以往在device 端进行测试的时候可以使用 Xilinx 自带的工具查看 timeline，host端优化的时候没有考虑使用类似的工具。这次发现了一个基于 linux profiling工具 perf 的图形化分析工具FlameGraph。下图是我在该项目的FlameGraph输出。

image-20240703154209489

​ 可以看到这个主函数注意包含了三个线程，为什么图中线程是看起来串行的？那是因为火焰图并不包含时序的信息。主要信息如下：

  1. 纵向（Y 轴）高低不平，表示的是函数调用栈的深度。每一层都是一个函数。调用栈越深，火焰就越高，顶部就是正在执行的函数，下方都是它的父函数。
  2. 横向（X 轴）表示该函数执行消耗的时间，横向上会按照字母顺序排序，而且如果是同样的调用会做合并（注意：如果一个函数在 X 轴占据的宽度越宽，就表示它被抽到的次数多，即执行的时间长，所以这里不是严格意义上的执行消耗的时间），所以一个横向宽度越大的函数调用，一般很可能是程序的瓶颈。
  3. 火焰图的颜色是随机分配的，并不是颜色越深就是越瓶颈。因为火焰图表示的是 CPU 的繁忙程度，所以一般都是暖色调。我们需要留意的就是那些比较宽大的火苗。只要有”平顶”，就表示该函数可能存在性能问题。但是更多的可能需要看我们对于这个函数的执行时间是否符合我们的预期，根据提前计算好的预期去规划。

​ 因为目前我只需要分析 host 端的时间，所以只需要输On-CPU 火焰图（device 端有另外的工具）。下面是生成命令

1
2
3
4
5
sudo -E perf record -F 99 -g -- ./run.exe yolov5_v4L32Y7_post.xclbin.u50
sudo perf script > out.perf
cd FlameGraph-master/
./stackcollapse-perf.pl ../out.perf > out.folded
./flamegraph.pl out.folded > flamegraph.svg

​ 可以看到我们在目标路径生成了flamegraph.svg，由于是 svg 所以我们可以同该图进行交互，比如我现在需要清楚 detection 线程做的操作，点击放大相关信息，如下图。

image-20240703155418747

再依次放大到我们的瓶颈函数 detection_yolov5

image-20240703155512018

可以看到我红框圈出来的瓶颈（图中已经不是瓶颈了，被我优化过了）。

Timer

这个 Timer 是我之前从小彭老师那里拿到的，实现的非常好，主要原理是利用 RAII，自动管理对象的生命周期，不需要手动记录开始和结束时间，在构造和析构函数中记录时间，提供了一种方便的方式来测量代码块的执行时间，并且可以收集统计数据，方便开发者分析代码性能瓶颈。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
#pragma once

#include <chrono>
#include <iostream>
#include <vector>
#include <iomanip>
#include <string_view>
#include <map>
#include <set>

class ScopeProfiler {
public:
    using ClockType = std::chrono::high_resolution_clock;

    struct Record {
        const char *tag;
        int us;
    };

private:
    inline thread_local static std::vector<Record> records;

    ClockType::time_point beg;
    ClockType::time_point end;
    const char *tag;

    inline ScopeProfiler(const char *tag, ClockType::time_point beg);
    inline void onDestroy(ClockType::time_point end);

public:
    ScopeProfiler(const char *tag_) : ScopeProfiler(tag_, ClockType::now()) {}
    ~ScopeProfiler() { onDestroy(ClockType::now()); }

    static std::vector<Record> const &getRecords() { return records; }
    inline static void printLog(std::ostream &out = std::cout);
};

ScopeProfiler::ScopeProfiler(const char *tag_, ScopeProfiler::ClockType::time_point beg_)
    : beg(beg_), tag(tag_)
{
}

void ScopeProfiler::onDestroy(ScopeProfiler::ClockType::time_point end) {
    auto diff = end - beg;
    int us = std::chrono::duration_cast<std::chrono::microseconds>(diff).count();
    records.push_back({tag, us});
}

void ScopeProfiler::printLog(std::ostream &out) {
    if (records.size() == 0) {
        return;
    }

    struct Statistic {
        int max_us = 0;
        int min_us = 0;
        int total_us = 0;
        int count_rec = 0;
        const char *tag = nullptr;
    };
    std::map<std::string_view, Statistic> stats;
    for (auto const &[tag, us]: records) {
        auto &stat = stats[tag];
        stat.total_us += us;
        stat.max_us = std::max(stat.max_us, us);
        stat.min_us = !stat.count_rec ? us : std::min(stat.min_us, us);
        stat.count_rec++;
        stat.tag = tag;
    }

    struct StatisticCompare {
        using value_type = std::pair<std::string_view, Statistic>;
        bool operator()(value_type const &lhs, value_type const &rhs) const {
            return lhs.second.total_us > rhs.second.total_us;
        }
    };

    std::multiset<std::pair<std::string_view, Statistic>, StatisticCompare> sortstats(stats.begin(), stats.end());

    auto dump = [&out] (int val, int w) {
        auto tpwv = 1;
        for (int i = 0; i < w - 1; i++) tpwv *= 10;
        if (val > tpwv) {
            if (val / 1000 > tpwv / 10) {
                out << std::setw(w - 1) << val / 1000000 << 'M';
            } else {
                out << std::setw(w - 1) << val / 1000 << 'k';
            }
        } else {
            out << std::setw(w) << val;
        }
    };

    out << "   avg   |   min   |   max   |  total  | cnt | tag\n";
    for (auto const &[tag, stat]: sortstats) {
        dump(stat.total_us / stat.count_rec, 9); out << '|';
        dump(stat.min_us, 9); out << '|';
        dump(stat.max_us, 9); out << '|';
        dump(stat.total_us, 9); out << '|';
        dump(stat.count_rec, 5); out << '|';
        out << ' ' << tag << '\n';
    }
}

#if defined(__GUNC__) || defined(__clang__)
#define DefScopeProfiler ScopeProfiler _scopeProfiler(__PRETTY_FUNCTION__);
#elif defined(_MSC_VER)
#define DefScopeProfiler ScopeProfiler _scopeProfiler(__FUNCSIG__);
#else
#define DefScopeProfiler ScopeProfiler _scopeProfiler(__func__);
#endif

template <class T>
static
#if defined(__GUNC__) || defined(__clang__)
__attribute__((noinline))
#elif defined(_MSC_VER)
__declspec(noinline)
#endif
void doNotOptimize(T volatile const &t) {}

static void printScopeProfiler(std::ostream &out = std::cout) {
    ScopeProfiler::printLog(out);
}