背景
我们始终渴望了解模块的调用、时序逻辑，每个人都会轻易地想到在函数的入口打印一条进入 enter相关的日志，在函数的出口打印一条离开 leave 相关的日志。不能有遗漏，我们会复制这条日志到所有关心的函数中，为了表明是哪个模块，哪个类和哪个函数我们需要逐个将这些参数写入。
这样不可避免地出现第一个问题，每个函数至少添加两条日志，第二个问题当一个函数有多个出口(return)，我们将要打印多条 leave用以区分。
如果碰到复杂模块，我们仍然简单地这样操作，工作量会让你崩溃，这根本不是一个开发者的追求。有什么简单易行、以逸待劳的好办法？
一、打印函数进出日志的原理
如何在函数的入口只打印一条日志，出口不用打印，却自动产生进入、离开两条日志？我们知道函数内部变量的生命周期遵循的是先进后出原则。进入函数首先就定义一个局部对象，在离开这个函数的时刻自动释放这个对象。如果这个对象是类对象，则在定义时会进入构造函数，离开时进入析构函数。于是在构造函数和析构函数分别打印进出日志，测试结果表明的确是这样。
如何区分来自哪个模块、哪个类、哪个函数？很简单，将模块的id、类名称Tag作为参数传入，函数名则用系统宏 __FUNCTION__即可。
经过一番操作，发现所有的进出函数日志名称、参数写的一模一样，低级重复不是一个开发者的追求，能不能不写参数。于是用一个宏去代替这条日志函数，参数仅写一次，最终效果达到预期......
如果能够管控不同级别的进出日志，就更加完美了。神奇的std::bind()函数就能实现原函数的二次封装，在重新包装原函数成新接口（新规范）能力方面，这个功能特别有用。下面将对原理提及的知识点逐步进行讲解。
二、实现函数进出打印功能
第一步，日志类在共用头文件里面实现
例如，sensors模块就在 utils\common 目录下的sensors_errors.h文件
.\base\sensors\miscdevice\utils\common\include\sensors_errors.h
第二步，实现一个简易的只包含构造和析构函数的类
里面会调用HiviewDFX日志模块HiLog::Debug()函数，包含 #include "hilog/log.h"
#include "hilog/log.h"
class InnerFunctionTracer {
public:
InnerFunctionTracer(const OHOS::HiviewDFX::HiLogLabel &label, const char *func)
: label_ { label }, func_ { func }
{
OHOS::HiviewDFX::HiLog::Debug(label_, "wyyxiu in %{public}s, enter_func", func_);
}
~InnerFunctionTracer()
{
OHOS::HiviewDFX::HiLog::Debug(label_, "wyyxiu in %{public}s, leave_func", func_);
}
private:
const OHOS::HiviewDFX::HiLogLabel &label_;
const char *func_ { nullptr };
};
第三步，InnerFunctionTracer的构造函数参数是通过下面定义对象时将参数传入的
define CALL_LOG_ENTER InnerFunctionTracer ___innerFuncTracer___ { LABEL, __FUNCTION__ }
LABEL: 是通过宏CALL_LOG_ENTER替换时传入的
__FUNCTION__: 是通过宏CALL_LOG_ENTER替换时传入的
第四步，调用 CALL_LOG_ENTER 宏就会打印出这个函数进出日志
LABEL: 需要按照给定格式声明，最后一个字符串一般为该类名
__FUNCTION__: 是调用者的函数名称
// 首先，包含声明宏的头文件 sensors_errors.h；
#include "sensors_errors.h"
namespace Sensors {
using namespace OHOS::HiviewDFX;
namespace {
// 其次，声明 LABEL；
constexpr HiLogLabel LABEL = { LOG_CORE, MISC_LOG_DOMAIN, "MiscdeviceServiceStub" };
} // namespace
// 最后，将 CALL_LOG_ENTER放置在需要打印进出日志的那个函数开头；
int32_t MiscdeviceServiceStub::PlayPatternStub(MessageParcel &data, MessageParcel &reply)
{
CALL_LOG_ENTER;
// ......
return PlayPattern(pattern.value(), usage, parameter.value());
}
三、现在，看一个更加复杂一点的进出日志函数实现
参考示例的头文件如下
.\base\msdp\device_status\utils\common\include\fi_log.h，或者
.\foundation\multimodalinput\input\util\common\include\mmi_log.h
有两个显著不同点
- 在构造和析构函数中可以打印任意级别的日志，它是将日志函数作为参数传入的，赋值给 logfn_
- 通过日志系统函数HiLogIsLoggable()，过滤允许级别的日志
class InnerFunctionTracer {
public:
using HilogFunc = std::function<int(const char *)>;
public:
InnerFunctionTracer(HilogFunc logfn, const char* tag, LogLevel level)
: logfn_ { logfn }, tag_ { tag }, level_ { level }
{
if (HiLogIsLoggable(OHOS::MMI::MMI_LOG_DOMAIN, tag_, level_)) {
if (logfn_ != nullptr) {
logfn_("wyyxiu in %{public}s, enter_func");
}
}
}
~InnerFunctionTracer()
{
if (HiLogIsLoggable(OHOS::MMI::MMI_LOG_DOMAIN, tag_, level_)) {
if (logfn_ != nullptr) {
logfn_("wyyxiu in %{public}s, leave_func");
}
}
}
private:
HilogFunc logfn_ { nullptr };
const char* tag_ { nullptr };
LogLevel level_ { LOG_LEVEL_MIN };
};
奇妙的地方是采用了 std::bind()函数，将不同级别日志函数作为参数传入类中
需要过滤将日志级别LogLevel传入，关于 std::bind() 用法如后所述
#define CALL_DEBUG_ENTER ::OHOS::MMI::InnerFunctionTracer ___innerFuncTracer_Debug___ \
{ std::bind(&::OHOS::HiviewDFX::HiLog::Debug, LABEL, std::placeholders::_1, __FUNCTION__), LABEL.tag, LOG_DEBUG }
#define CALL_INFO_TRACE ::OHOS::MMI::InnerFunctionTracer ___innerFuncTracer_Info___ \
{ std::bind(&::OHOS::HiviewDFX::HiLog::Info, LABEL, std::placeholders::_1, __FUNCTION__), LABEL.tag, LOG_INFO }
HiLogIsLoggable()函数的系统实现
- 只有系统使能了模块DEBUG 日志，这类 CALL_DEBUG_ENTER 才被打印输出。
- 以多模输入为例，需要在 hdc shell 窗口输入
hilog -b I -D 0xD002800，使能 DEBUG级别，0xD002800 代表 OHOS::MMI::MMI_LOG_DOMAIN。[hdc 的使用参照这个链接]()。
- 如果有编译环境，有一个省事的方法，将HiLog::Debug改为 HiLog::Info，LOG_DEBUG修改为LOG_INFO，该日志一般都会被打印出来，如 CALL_INFO_TRACE 所示。
- HiLogIsLoggable()函数的实现在这个文件： .\base\hiviewdfx\hilog\frameworks\libhilog\hilog_printf.cpp
.\base\hiviewdfx\hilog\frameworks\libhilog\hilog_printf.cpp
/**
* @brief Check whether log of a specified domain, tag and level can be printed.
*
* @param domain macro:LOG_DOMAIN
* @param tag macro:LOG_TAG
* @param level enum:LogLevel
*/
bool HiLogIsLoggable(unsigned int domain, const char *tag, LogLevel level)
{
if ((level <= LOG_LEVEL_MIN) || (level >= LOG_LEVEL_MAX) || (tag == nullptr) || (domain >= DOMAIN_OS_MAX)) {
return false;
}
if (level < GetFinalLevel(domain, tag)) {
return false;
}
return true;
}
四、std::bind()函数的用法
c++11 及以上支持 std::bind
包含头文件 #include <functional>
使用示例
- std::bind 就是一个对原函数和函数参数的重新绑定。
- std::placeholders 是新函数的占位符标记。
- std::placeholders::_n 中的，_n表示的是新函数的第n个参数，将代替原函数声明位置时的参数。
- 未出现 std::placeholders 的原函数位置，必须有默认值。
#include <iostream>
#include <functional>
using namespace std;
int TestFunc(int i, char c, float f)
{
cout << i << endl;
cout << c << endl;
cout << f << endl;
return i;
}
int main()
{
auto bindFunc1 = bind(TestFunc, std::placeholders::_1, 'A', 999.9);
bindFunc1(16);
auto bindFunc2 = bind(TestFunc, std::placeholders::_2, std::placeholders::_1, 999.9);
bindFunc2('B', 16);
auto bindFunc3 = bind(TestFunc, std::placeholders::_2, std::placeholders::_3, std::placeholders::_1);
auto ret = bindFunc3(999.9, 32, 'C');
cout << ret << endl;
return 0;
}
五、预期效果
为了方便查找进出日志，加入了特别字段，例如 "_func" 和 "wyyxiu"。
- 首先出现 enter_func, 然后出现 leave_func, enter_func 和 leave_func 成对出现，打印出的日志片段如下：
- 如果止步于看到日志，还有一点可惜。按照日志名称、出现规律，经过一番操作，很容易从日志文件整理出函数调用的时序图。
- 如何快速将日志文件整理出函数调用的时序图，关注我、等待后续文章。
六、总结
本文巧妙使用了三个知识点完成了函数进出日志打印。首先利用函数局部类对象实现在函数的入口只打印一条日志，出口不用打印，却自动产生进入、离开两条日志的目的；其次利用宏替换将模块id、类名称Tag、函数名称写在宏函数中，实现了所有参数只写一次的目的；最后利用 std::bind()函数管控不同级别进出日志打印。
七、相关链接
【TOOLS使用】用IPOP调试 OpenHarmony 内核 https://forums.openharmony.cn/forum.php?mod=viewthread&tid=1532
【TOOLS使用】(一) OpenHarmony hilog组件在交互时应用指南 https://forums.openharmony.cn/forum.php?mod=viewthread&tid=1470
【TOOLS使用】OpenHarmony命令行工具hdc安装应用指南 https://forums.openharmony.cn/forum.php?mod=viewthread&tid=1458
发布问题
发布文章
