在 C++ 中记录代码执行答案

【问题标题】：Logging code execution in C++在 C++ 中记录代码执行
【发布时间】：2011-04-14 13:46:08
【问题描述】：

在多次使用 gprof 和 callgrind 之后，我得出了一个（明显的）结论，即在处理大型（如在 CAD 程序中加载整车）程序。我在想也许，我可以使用一些 C/C++ MACRO 魔法并以某种方式构建一个简单（但很好）的日志记录机制。例如，可以使用以下宏调用函数：

#define CALL_FUN(fun_name, ...) \
    fun_name (__VA_ARGS__);

我们可以在函数调用之前和之后添加一些时钟/计时的东西，这样每个用 CALL_FUN 调用的函数都会被计时，例如

#define CALL_FUN(fun_name, ...) \
   time_t(&t0);                 \
   fun_name (__VA_ARGS__);      \
   time_t(&t1);

变量 t0, t1 可以在全局日志对象中找到。该日志记录对象还可以保存通过 CALL_FUN 调用的每个函数的调用图。之后，可以将该对象写入（特定格式的）文件中，并从其他程序中解析。

所以我的（第一个）问题来了：你觉得这种方法容易处理吗？如果是，如何增强它，如果不是，您能否提出一种更好的方法来测量时间和记录调用图？

一位同事提出了另一种解决此问题的方法，即使用特定注释注释每个函数（我们关心记录）。然后，在 make 过程中，必须运行一个特殊的预处理器，解析每个源文件，为我们要记录的每个函数添加日志逻辑，使用新添加的（解析）代码创建一个新的源文件，然后构建该代码。我想到处阅读 CALL_FUN... 宏（我的建议）并不是最好的方法，他的方法可以解决这个问题。那么您对这种方法有何看法？

PS：我不太了解 C/C++ 宏的陷阱，所以如果可以使用其他方法开发，请说出来。

谢谢。

【问题讨论】：

换句话说：您正在重新发明轮子。您收集的数据将不会包含来自 callgrind 的更多信息（如果不是更少）
是的，他的问题不是信息量，而是开销。

标签： c++ logging gprof callgrind

【解决方案1】：

你可以做一些 C++ 魔法来嵌入一个日志对象。像

class CDebug 
{
CDebug() { ... log somehow ... }
~CDebug() { ... log somehow ... }

};

在您的函数中，然后您只需编写

void foo()
{
   CDebug dbg;
    ...

   you could add some debug info


   dbg.heythishappened()

   ...
}  // not dtor is called or if function is interrupted called from elsewhere.

【讨论】：

这是一个不错的方法。谢谢。
+1 这或多或少是我所做的，除了我的构造函数采用字符串或我想要记录的东西。

【解决方案2】：

我有点晚了，但这是我正在做的：

在 Windows 上，有一个 /Gh compiler switch，它使编译器在每个函数的开头插入一个隐藏的 _penter 函数。在每个函数的末尾还有一个用于获取_pexit call 的开关。

您可以利用它来获取每个函数调用的回调。这是一篇包含更多详细信息和示例源代码的文章：

http://www.johnpanzer.com/aci_cuj/index.html

我在我的自定义日志系统中使用这种方法将最后几千个函数调用存储在一个环形缓冲区中。事实证明，这对于崩溃调试很有用（与 MiniDumps 结合使用）。

对此的一些说明：

性能影响很大程度上取决于您的回调代码。您需要使其尽可能简单。
只需要在日志文件中保存函数地址和模块基地址即可。然后，您可以稍后使用Debug Interface Access SDK 从地址中获取函数名称（通过 PDB 文件）。

这一切对我来说都非常好。

【讨论】：

【解决方案3】：

许多不错的工业库都将函数的声明和定义包装在 void 宏中，以防万一。如果您的代码已经是这样 - 继续使用一些简单的异步跟踪记录器来调试您的性能问题。如果没有 - 后插入此类宏可能会非常耗时。

我可以理解在 valgrind 下运行 1Mx1M 矩阵求解器的痛苦，所以我建议从所谓的“蒙特卡洛分析方法”开始——启动该过程并重复并行运行 pstack，例如每秒。结果，您将有 N 个堆栈转储（N 可能非常重要）。然后，数学方法将是计算每个堆栈的相对频率，并对最频繁的堆栈做出结论。在实践中，您要么立即看到瓶颈，要么如果没有，则切换到二分法、gprof，最后切换到 valgrind 的工具集。

【讨论】：

+1 表示 pstack。 lsstack 应该会更好。 N 不需要很大。 bisection 和 gprof 为布朗克斯欢呼:)
对，gprof 应该仅在您可以解释结果时使用（事实上，请确保您不会误解它们:)），但是让您不喜欢 bisection ?
我认为您所说的 bisection 就像“二分法”，您尝试通过细分逐步免除部分代码。将其与 pstack 进行比较就像将二进制搜索与哈希搜索进行比较。每个堆栈样本向您显示问题的概率等于问题花费的时间分数。立即发现大问题。相比之下，二分法既胆小又费力。通过堆栈采样，您可以获得有关问题所在位置的完整信息，而不仅仅是一点点信息。
... 如果问题在调用树中扩散，二等分将找不到它，但 pstack 会。
我不同意你对二等分的看法，如果你的问题在代码中均匀分布（比如，你在 C++ 中系统地按值传递字符串），使用二等分减少测试用例代码库会让你最后一页代码，然后'valgrind --tool = callgrind'类型的分析器会指出明显的问题。我知道大多数此类问题会以 90+% 的概率显示在 pstack 转储中，因此关于二分的讨论更多是一个理论主题

【解决方案4】：

让我假设您这样做的原因是您想找出任何性能问题（瓶颈），以便您可以修复它们以获得更高的性能。

与测量速度或获取覆盖信息相反。

您似乎正在考虑这样做的方法是记录函数调用的历史记录并测量每次调用需要多长时间。

有一种不同的方法。它基于程序主要走一个大调用树的想法。如果时间被浪费了，那是因为调用树比必要的更茂密，在被浪费的时间里，正在浪费的代码在堆栈上是可见的。它可以是终端指令，但更可能是函数调用，几乎在堆栈的任何级别。只需在调试器下暂停程序几次，最终将显示它。你看到它在不止一个堆栈样本上所做的任何事情，如果你能改进它，将加速程序。无论时间是否花在 CPU、I/O 或其他任何消耗挂钟时间的东西上，它都有效。它没有向你展示的是大量你不需要知道的东西。它不向您显示瓶颈的唯一方法是，如果它们非常小，在这种情况下，代码非常接近最优。

Here's more of an explanation.

【讨论】：

+1 表示香脆的精华，gprof 的输出确实应该在上面突出显示的范围内解释

【解决方案5】：

虽然我认为很难做比 gprof 更好的事情，但您可以创建一个特殊的类 LOG 例如并在您要记录的每个函数的开头实例化它。

class LOG {
    LOG(const char* ...) {
        // log time_t of the beginning of the call
    }
    ~LOG(const char* ...) {
        // calculate the total time spent,
        //by difference between current time and that saved in the constructor
    }
};

void somefunction() {
    LOG log(__FUNCTION__, __FILE__, ...);
    .. do other things
}

现在您可以将此方法与您提到的预处理方法集成。只需在要记录的每个函数的开头添加类似这样的内容：

// ### LOG

然后在调试版本中自动替换字符串（应该不难）。

【讨论】：

很难比 gprof 做得更好？ You must be kidding.

【解决方案6】：

也许您应该使用分析器。 AQTime 对于 Visual Studio 来说是比较好的一个。（如果你有 VS2010 Ultimate，你已经有一个分析器。）

【讨论】：