easylogging++的那些事(四)源码分析(七)性能跟踪

在上一篇我们介绍了 VERBOSE日志信息管理，今天我们开始介绍性能跟踪的实现。
easylogging++的性能跟踪可以分为两种： 代码块整体的跟踪 以及基于代码块整体的跟踪基础上的 代码块内的某个标记点的跟踪 。

在 easylogging++的 功能介绍 中我们介绍过性能跟踪宏的使用：
1、代码块整体的跟踪对应的宏: TIMED_SCOPE_IF 宏、TIMED_SCOPE 宏、TIMED_FUNC_IF 宏、TIMED_FUNC 宏、TIMED_BLOCK 宏。
2、代码块内的某个标记点的跟踪对应的宏：PERFORMANCE_CHECKPOINT 宏、PERFORMANCE_CHECKPOINT_WITH_ID 宏。

我们就从性能跟踪宏开始今天的分析。

宏展开

TIMED_SCOPE_IF 宏

    TIMED_SCOPE_IF 宏定义如下：

#define TIMED_SCOPE_IF(obj, blockname, condition) el::base::type::PerformanceTrackerPtr obj( condition ? \
    new el::base::PerformanceTracker(blockname, ELPP_MIN_UNIT) : nullptr )

    用个具体的例子就一目了然了:

TIMED_SCOPE_IF(timerObj, "TIMED_SCOPE_IF", true);

    展开后为:

el::base::type::PerformanceTrackerPtr timerObj( true ? new el::base::PerformanceTracker("TIMED_SCOPE_IF", ELPP_MIN_UNIT) : nullptr );

    PerformanceTrackerPtr 定义如下：

typedef std::unique_ptr<el::base::PerformanceTracker> PerformanceTrackerPtr;

    最终展开后的结果就相当于：创建了一个 el::base::PerformanceTracker 类型的独占型智能指针(std::unique_ptr<el::base::PerformanceTracker>)对象。当这个智能指针对象离开其作用域后，自身就会被销毁，进而自动删除其管理的对象，最终调用 el::base::PerformanceTracker 类的析构函数，而这个析构函数执行了真正的性能跟踪统计。
    el::base::PerformanceTracker 类后面源码分析的时候回详细说明。

TIMED_SCOPE 宏

    TIMED_SCOPE 宏定义如下：

#define TIMED_SCOPE(obj, blockname) TIMED_SCOPE_IF(obj, blockname, true)

    TIMED_SCOPE_IF 宏前面已经介绍了，这里就不多说了。

TIMED_FUNC_IF 宏

    TIMED_FUNC_IF 宏定义如下：

#define TIMED_FUNC(obj) TIMED_SCOPE(obj, ELPP_FUNC)

    TIMED_SCOPE 宏前面已经介绍了，这里就不多说了。

TIMED_FUNC 宏

    TIMED_FUNC 宏定义如下：

#define TIMED_FUNC(obj) TIMED_SCOPE(obj, ELPP_FUNC)

    TIMED_SCOPE 宏前面已经介绍了，这里就不多说了。

TIMED_BLOCK 宏

    TIMED_BLOCK 宏定义如下：

#define TIMED_BLOCK(obj, blockName) for (struct { int i; el::base::type::PerformanceTrackerPtr timer; } obj = { 0, \
    el::base::type::PerformanceTrackerPtr(new el::base::PerformanceTracker(blockName, ELPP_MIN_UNIT)) }; obj.i < 1; ++obj.i)

    从 TIMED_BLOCK 宏定义上来看，这个宏只是定义了 for 循环语句的开头部分，循环体空着，真正使用时需要加上循环体才能正常使用。
    用个具体的例子就一目了然了:

TIMED_BLOCK(timerBlkObj, "TIMED_BLOCK")
{
    //实际要性能测试的代码
}

    展开后为：

for (struct { int i; el::base::type::PerformanceTrackerPtr timer; } timerBlkObj = {0, ::base::type::PerformanceTrackerPtr(new el::base::PerformanceTracker("TIMED_BLOCK", ELPP_MIN_UNIT))};
     timerBlkObj.i < 1; ++timerBlkObj.i)
{
}

    最终展开后的结果就相当于创建了仅仅执行一次的 for 循环语句，而这个循环语句的循环体内部，创建了一个 el::base::PerformanceTracker 类型的独占型智能指针对象。和 TIMED_SCOPE_IF 宏一样，这里就不多说了。

PERFORMANCE_CHECKPOINT 宏

    PERFORMANCE_CHECKPOINT 宏定义如下：

#define PERFORMANCE_CHECKPOINT(obj) obj->checkpoint(std::string(), __FILE__, __LINE__, ELPP_FUNC)

    用个具体的例子就一目了然了:

PERFORMANCE_CHECKPOINT(timerObj);

    展开后为：

timerObj->checkpoint(std::string(), __FILE__, __LINE__, ELPP_FUNC);

    最后展开后的结果相当于调用了某个对象的 checkpoint 接口。

PERFORMANCE_CHECKPOINT_WITH_ID 宏

    PERFORMANCE_CHECKPOINT_WITH_ID 宏定义如下：

#define PERFORMANCE_CHECKPOINT_WITH_ID(obj, id) obj->checkpoint(id, __FILE__, __LINE__, ELPP_FUNC)

    用个具体的例子就一目了然了:

PERFORMANCE_CHECKPOINT_WITH_ID(timerObj, "PERFORMANCE_CHECKPOINT");

    展开后为：

timerObj->checkpoint("PERFORMANCE_CHECKPOINT", __FILE__, __LINE__, ELPP_FUNC);

    与 PERFORMANCE_CHECKPOINT 宏一样，最后展开后的结果相当于调用了某个对象的 checkpoint 接口。
    而这个对象的类型实际上就是 el::base::PerformanceTracker 类。后面源码分析时我们会清楚的看到这一点。

源码剖析

    从上面性能跟踪宏的最终展开结果可以看出来，最终都与 el::base::PerformanceTracker 这个类有关。下面我们就来分析下这个类的实现。

成员变量

std::string m_blockName;             // 性能跟踪的代码块的自定义名称
base::TimestampUnit m_timestampUnit; // 性能跟踪的时间精度
std::string m_loggerId;              // 性能跟踪对应的日志记录器的ID
bool m_scopedLog;                    // 开启性能跟踪宏后，默认进行代码块的性能跟踪
Level m_level;                       // 日志级别
bool m_hasChecked;                   // 默认为false，进行一次跟踪点统计后置为true
std::string m_lastCheckpointId;      // 最近完成性能跟踪点对应的ID
bool m_enabled;                      // 对应日志记录器的指定日志级别是否启用性能跟踪
struct timeval m_startTime;          // 性能跟踪的开始时间
struct timeval m_endTime;            // 性能跟踪的结束时间
struct timeval m_lastCheckpointTime; // 最近完成性能跟踪点的时间

成员函数

构造函数

PerformanceTracker::PerformanceTracker(const std::string &blockName, base::TimestampUnit timestampUnit, const std::string &loggerId, bool scopedLog, Level level)
    : m_blockName(blockName), m_timestampUnit(timestampUnit), m_loggerId(loggerId), m_scopedLog(scopedLog), m_level(level), m_hasChecked(false), m_lastCheckpointId(std::string()), m_enabled(false)
{
#if !defined(ELPP_DISABLE_PERFORMANCE_TRACKING) && ELPP_LOGGING_ENABLED
    // We store it locally so that if user happen to change configuration by the end of scope
    // or before calling checkpoint, we still depend on state of configuration at time of construction
    // 获取日志记录器对象
    el::Logger *loggerPtr = ELPP->registeredLoggers()->get(loggerId, false);
    // 对应日志记录器的指定日志级别是否启用性能跟踪
    m_enabled = loggerPtr != nullptr && loggerPtr->m_typedConfigurations->performanceTracking(m_level);
    if (m_enabled)
    {
        // 启用性能跟踪则记录当前时间为性能跟踪的开始时间
        base::utils::DateTime::gettimeofday(&m_startTime);
    }
#endif // !defined(ELPP_DISABLE_PERFORMANCE_TRACKING) && ELPP_LOGGING_ENABLED
}

析构函数

    析构函数用于执行真正的性能跟踪统计

PerformanceTracker::~PerformanceTracker(void)
{
#if !defined(ELPP_DISABLE_PERFORMANCE_TRACKING) && ELPP_LOGGING_ENABLED
    if (m_enabled)
    {
        base::threading::ScopedLock scopedLock(lock());
        // PerformanceTracker仅仅提供了一个构造函数的实现，其中提供了默认值true,性能跟踪宏使用的是默认值
        // 开启性能跟踪宏后，默认进行代码块的性能跟踪
        if (m_scopedLog)
        {
            // 记录当前时间为性能跟踪的结束时间
            base::utils::DateTime::gettimeofday(&m_endTime);
            // 将时间根据需要调整为合适的格式后，以字符串形式返回
            base::type::string_t formattedTime = getFormattedTimeTaken();
            // 性能跟踪回调数据对象的初始化，交给性能跟踪回调处理(比如默认DefaultPerformanceTrackingCallback进行性能跟踪的时长统计)
            // PerformanceTrackingData::DataType::Complete表示当前性能跟踪完成
            PerformanceTrackingData data(PerformanceTrackingData::DataType::Complete);
            data.init(this);
            data.m_formattedTimeTaken = formattedTime;
            PerformanceTrackingCallback *callback = nullptr;
            // 遍历注册的所有性能跟踪回调
            for (const std::pair<std::string, base::type::PerformanceTrackingCallbackPtr> &h : ELPP->m_performanceTrackingCallbacks)
            {
                callback = h.second.get();
                if (callback != nullptr && callback->enabled())
                {
                    callback->handle(&data);
                }
            }
        }
    }
#endif // !defined(ELPP_DISABLE_PERFORMANCE_TRACKING)
}

    在 easylogging++的 主流程 中我们介绍过，日志库初始化的时候，默认会注册 DefaultPerformanceTrackingCallback。其主要职责就是执行 easylogging++默认的性能跟踪统计。DefaultPerformanceTrackingCallback 的实现稍后会详细分析。

checkpoint 接口

    checkpoint 接口主要用于跟踪点的性能统计。

void PerformanceTracker::checkpoint(const std::string &id, const char *file, base::type::LineNumber line, const char *func)
{
#if !defined(ELPP_DISABLE_PERFORMANCE_TRACKING) && ELPP_LOGGING_ENABLED
    // 是否启用性能跟踪
    if (m_enabled)
    {
        base::threading::ScopedLock scopedLock(lock());
        // 记录当前时间为性能跟踪点的结束时间
        base::utils::DateTime::gettimeofday(&m_endTime);
        // 将时间根据需要调整为合适的格式后，以字符串形式返回
        base::type::string_t formattedTime = m_hasChecked ? getFormattedTimeTaken(m_lastCheckpointTime) : ELPP_LITERAL("");
        // 性能跟踪回调数据对象的初始化，交给性能跟踪回调处理(比如默认DefaultPerformanceTrackingCallback进行性能跟踪的时长统计)
        // PerformanceTrackingData::DataType::Checkpoint表示单个跟踪点的性能跟踪
        PerformanceTrackingData data(PerformanceTrackingData::DataType::Checkpoint);
        data.init(this);
        data.m_checkpointId = id;
        data.m_file = file;
        data.m_line = line;
        data.m_func = func;
        // 经过调整后的时间戳的字符串形式。
        data.m_formattedTimeTaken = formattedTime;
        PerformanceTrackingCallback *callback = nullptr;
        // 遍历注册的所有性能跟踪回调
        for (const std::pair<std::string, base::type::PerformanceTrackingCallbackPtr> &h : ELPP->m_performanceTrackingCallbacks)
        {
            callback = h.second.get();
            if (callback != nullptr && callback->enabled())
            {
                callback->handle(&data);
            }
        }
        // 更新最后的性能跟踪点的时间为当前跟踪点的结束时间
        base::utils::DateTime::gettimeofday(&m_lastCheckpointTime);
        // 默认为false，进行一次跟踪点统计后置为true
        m_hasChecked = true;
        m_lastCheckpointId = id;
    }
#endif // !defined(ELPP_DISABLE_PERFORMANCE_TRACKING) && ELPP_LOGGING_ENABLED
    ELPP_UNUSED(id);
    ELPP_UNUSED(file);
    ELPP_UNUSED(line);
    ELPP_UNUSED(func);
}

getFormattedTimeTaken 接口

    getFormattedTimeTaken 接口用于获取经过调整后的时间戳的字符串形式。

const base::type::string_t PerformanceTracker::getFormattedTimeTaken(struct timeval startTime) const
{
    // 保留时间格式，不将其转换为秒、小时等（仅限性能跟踪）
    if (ELPP->hasFlag(LoggingFlag::FixedTimeFormat))
    {
        base::type::stringstream_t ss;
        // 求timeval结构体之间的时间差（以毫秒或者微秒为单位）,以m_timestampUnit为统计单位，默认性能跟踪单位为毫秒
        ss << base::utils::DateTime::getTimeDifference(m_endTime, startTime, m_timestampUnit)
           << " "
           << base::consts::kTimeFormats[static_cast<base::type::EnumType>(m_timestampUnit)].unit;
        return ss.str();
    }
    // 将指定的时间戳转化为指定时间单位的字符串形式,以m_timestampUnit为统计单位
    return base::utils::DateTime::formatTime(base::utils::DateTime::getTimeDifference(m_endTime, startTime, m_timestampUnit), m_timestampUnit);
}

相关类介绍

PerformanceTrackingData 类

    PerformanceTrackingData 类主要作为性能跟踪回调的参数，传递性能跟踪统计需要的一些信息。

class PerformanceTrackingData
{
public:
    enum class DataType : base::type::EnumType
    {
        Checkpoint = 1,  //性能跟踪点的统计
        Complete = 2     //整个代码块的性能跟踪统计
    };
    // Do not use constructor, will run into multiple definition error, use init(PerformanceTracker*)
    explicit PerformanceTrackingData(DataType dataType)
        : m_performanceTracker(nullptr), m_dataType(dataType), m_firstCheckpoint(false), m_file(""), m_line(0), m_func("")
    {
    }
    inline const std::string *blockName(void) const;
    inline const struct timeval *startTime(void) const;
    inline const struct timeval *endTime(void) const;
    inline const struct timeval *lastCheckpointTime(void) const;
    inline const base::PerformanceTracker *performanceTracker(void) const
    {
        return m_performanceTracker;
    }
    inline PerformanceTrackingData::DataType dataType(void) const
    {
        return m_dataType;
    }
    inline bool firstCheckpoint(void) const
    {
        return m_firstCheckpoint;
    }
    inline std::string checkpointId(void) const
    {
        return m_checkpointId;
    }
    inline const char *file(void) const
    {
        return m_file;
    }
    inline base::type::LineNumber line(void) const
    {
        return m_line;
    }
    inline const char *func(void) const
    {
        return m_func;
    }
    inline const base::type::string_t *formattedTimeTaken() const
    {
        return &m_formattedTimeTaken;
    }
    inline const std::string &loggerId(void) const;

private:
    base::PerformanceTracker *m_performanceTracker; // 性能跟踪统计类
    base::type::string_t m_formattedTimeTaken;      // 经过调整后的时间戳的字符串形式。
    PerformanceTrackingData::DataType m_dataType;   // 性能跟踪统计的类型
    bool m_firstCheckpoint;                         // 暂时未用上
    std::string m_checkpointId;                     // 当前进行的性能跟踪点的ID
    const char *m_file;                             // 进行性能跟踪的源文件
    base::type::LineNumber m_line;                  // 进行性能跟踪的行号
    const char *m_func;                             // 进行性能跟踪的函数
    inline void init(base::PerformanceTracker *performanceTracker, bool firstCheckpoint = false)
    {
        m_performanceTracker = performanceTracker;
        m_firstCheckpoint = firstCheckpoint;
    }

    friend class el::base::PerformanceTracker;
};

DefaultPerformanceTrackingCallback 类

    DefaultPerformanceTrackingCallback 类是默认性能跟踪回调类，其主要职责就是执行 easylogging++默认的性能跟踪统计。其实现如下:

class DefaultPerformanceTrackingCallback : public PerformanceTrackingCallback
{
protected:
    void handle(const PerformanceTrackingData *data)
    {
        m_data = data;
        base::type::stringstream_t ss;
        // 代码块性能跟踪结束
        if (m_data->dataType() == PerformanceTrackingData::DataType::Complete)
        {
            ss << ELPP_LITERAL("Executed [") << m_data->blockName()->c_str() << ELPP_LITERAL("] in [") << *m_data->formattedTimeTaken() << ELPP_LITERAL("]");
        }
        else
        {
            // 性能跟踪点
            ss << ELPP_LITERAL("Performance checkpoint");
            if (!m_data->checkpointId().empty())
            {
                ss << ELPP_LITERAL(" [") << m_data->checkpointId().c_str() << ELPP_LITERAL("]");
            }
            ss << ELPP_LITERAL(" for block [") << m_data->blockName()->c_str() << ELPP_LITERAL("] : [") << *m_data->performanceTracker();
            // 未禁用性能跟踪点的对比统计并且已经进行过跟踪点统计
            if (!ELPP->hasFlag(LoggingFlag::DisablePerformanceTrackingCheckpointComparison) && m_data->performanceTracker()->m_hasChecked)
            {
                // 输出上一次跟踪点统计结束的时间
                ss << ELPP_LITERAL(" ([") << *m_data->formattedTimeTaken() << ELPP_LITERAL("] from ");
                if (m_data->performanceTracker()->m_lastCheckpointId.empty())
                {
                    ss << ELPP_LITERAL("last checkpoint");
                }
                else
                {
                    ss << ELPP_LITERAL("checkpoint '") << m_data->performanceTracker()->m_lastCheckpointId.c_str() << ELPP_LITERAL("'");
                }
                ss << ELPP_LITERAL(")]");
            }
            else
            {
                ss << ELPP_LITERAL("]");
            }
        }
        // 要输出的性能跟踪信息汇总后，使用el::base::Writer最终进行日志输出。
        el::base::Writer(m_data->performanceTracker()->level(), m_data->file(), m_data->line(), m_data->func()).construct(1, m_data->loggerId().c_str()) << ss.str();
    }

private:
    const PerformanceTrackingData *m_data;
};

    el::base::Writer 类我们在 CLOG 宏 Writer对象的创建以及初始化、日志输出、日志信息保存 已经仔细介绍过了，这里就不多说了。

至此，性能跟踪的实现就介绍完了，下一篇我们开始分析崩溃处理的实现。