BUG分析方法（1）LOG时间处理方法以及版本编译时间排查法

前言

在项目开发的过程中，发现测试提的某些刚上电时候的问题，会出现日志时间错误的问题。故写此文章，记录问题原因与对策。同时总结部分日志优化逻辑以、与时间相关的多线程问题调查方法以及代码运行速度计算方法。愿与君共勉。

问题原因

原因是系统的日志时间用的是系统时间，在刚上电的时候时间为00:00:00，然后网络连通之后会同步到当前的真实世界时间。导致记录的时间由00:00:00运行几秒钟后直接跳变到真实世界时间。导致记录异常。而且部分日志系统记录的时间并非真实代码中日志触发的时间，而是触发后，储存在日志系统的缓冲区，当缓冲区满了之后，日志系统通过write的方式写入日志文件中的时间。同时此处调用write接口还涉及到中断问题，一般的日志系统使用的都是同步IO的方式，很少有异步IO，若是日志系统中有较多的write可能还涉及到IO中断，在刚开机启动，CPU较为繁忙的时候，还会导致LOG系统进程获取不到CPU的问题。

如果测试同学提出这种刚起开机时候的问题，时间变化跳跃并且对时间要求很高的代码部分，可能会不好排查此类问题。故记录此文，分享出来。

处理策略

处理方法，在代码日志中添加CPU运行时间，而非真实世界时间。
下面提供我个人经常用的CPU时间计时器。适用于日志中添加的时间标识，可满足不同情况下的对时间参考的需求。
定时器的用法不局限于计算代码执行时间或者排查问题，同时也可以控制显示帧率，控制while(1)线程运行密度等等…需要使用者设计使用方法，已达到正优化的效果，使用不当可能适得其反，因为定时器的使用也会影响到代码执行时间，对于部分时间精度要求较高的程序也可能会造成影响。
注意：建议该定时器只用于debug排查问题阶段，正式release版本建议不要嵌入定时器逻辑，可能会涉及到代码反汇编安全问题。
定时器原理：不同的定时器相关函数的原理均为CPU时钟中断，时钟中断的精度就决定定时器精度的极限。

1. 单例类定时器

单例类计时器使用与全局代码使用同一个计时器，该计时器一般用于排查多线程问题。在多线程的代码架构下，对于线程间的执行时间，执行情况可以统一一个起始点，所有时间点都相对于当前起点而言。

#ifndef  MY_TIMER_H_
#define  MY_TIMER_H_

#include<chrono>
using namespace std;
using namespace std::chrono;

#define MY_TIMEER_INSTANCE_REF_ MyTimer::GetInstance()

class MyTimer
{
public:
    static MyTimer &GetInstance()
    {
    	static MyTimer timer;
    	return timer;
    }

	//reset接口可重设时间起始点
    void reset()
    { 
    	m_begin = high_resolution_clock::now(); 
    }

    //默认输出毫秒
    int64_t elapsed() const
    {
        return duration_cast<chrono::milliseconds>(high_resolution_clock::now() - m_begin).count();
    }

    //默认输出秒
    double elapsed_second() const
    {
        return duration_cast<duration<double>>(high_resolution_clock::now() - m_begin).count();
    }

    //微秒
    int64_t elapsed_micro() const
    {
        return duration_cast<chrono::microseconds>(high_resolution_clock::now() - m_begin).count();
    }

    //纳秒
    int64_t elapsed_nano() const
    {
        return duration_cast<chrono::nanoseconds>(high_resolution_clock::now() - m_begin).count();
    }

    //秒
    int64_t elapsed_seconds() const
    {
        return duration_cast<chrono::seconds>(high_resolution_clock::now() - m_begin).count();
    }

    //分
    int64_t elapsed_minutes() const
    {
        return duration_cast<chrono::minutes>(high_resolution_clock::now() - m_begin).count();
    }

    //时
    int64_t elapsed_hours() const
    {
        return duration_cast<chrono::hours>(high_resolution_clock::now() - m_begin).count();
    }

private:
    MyTimer() : m_begin(high_resolution_clock::now()) {}
    time_point<high_resolution_clock> m_begin;

};

#endif

使用实例：

#include "MyTimer.hpp"
#incldue <iostream>

int main()
{
	MY_TIMEER_INSTANCE_REF_; //初始化定时器
	printf("time: %ld", MY_TIMEER_INSTANCE_REF_.elapsed());
	sleep(1);
	printf("time: %ld", MY_TIMEER_INSTANCE_REF_.elapsed());
	return 0;
}

2. 非单例定时器

非单例定时器可以将定时器copy多份，一般用于一些需要计算多部分分开计时的代码段。需要注意区别不同定时间的时间起始点，管理不好的话，可能会对排查问题起到负作用。

#ifndef  MY_TIMER_H_
#define  MY_TIMER_H_

#include<chrono>
using namespace std;
using namespace std::chrono;

class MyTimer
{
public:
    MyTimer() : m_begin(high_resolution_clock::now()) {}
    void reset() { m_begin = high_resolution_clock::now(); }

    //默认输出毫秒
    int64_t elapsed() const
    {
        return duration_cast<chrono::milliseconds>(high_resolution_clock::now() - m_begin).count();
    }

    //默认输出秒
    double elapsed_second() const
    {
        return duration_cast<duration<double>>(high_resolution_clock::now() - m_begin).count();
    }

    //微秒
    int64_t elapsed_micro() const
    {
        return duration_cast<chrono::microseconds>(high_resolution_clock::now() - m_begin).count();
    }

    //纳秒
    int64_t elapsed_nano() const
    {
        return duration_cast<chrono::nanoseconds>(high_resolution_clock::now() - m_begin).count();
    }

    //秒
    int64_t elapsed_seconds() const
    {
        return duration_cast<chrono::seconds>(high_resolution_clock::now() - m_begin).count();
    }

    //分
    int64_t elapsed_minutes() const
    {
        return duration_cast<chrono::minutes>(high_resolution_clock::now() - m_begin).count();
    }

    //时
    int64_t elapsed_hours() const
    {
        return duration_cast<chrono::hours>(high_resolution_clock::now() - m_begin).count();
    }

private:
    time_point<high_resolution_clock> m_begin;
};

#endif

3. 系统时间

系统时间接口也同样存在启动的时候从00:00:00运行几秒钟后直接跳变到真实世界时间的问题。建议使用该接口的时候放在系统完全启动之后使用。

#include <sys/time.h>
#include <unistd.h>
#include <iostream>
int main()
{
	timeval time;
	gettimeofday(&time, NULL);
	printf("s: %ld, ms: %ld \n", time.tv_sec, (time.tv_sec*1000 + time.tv_usec/1000));
	
	gettimeofday(&time, NULL);
	printf("time ms: %ld \n", (time.tv_sec*1000 + time.tv_usec/1000));
	//这个是系统时间，当程序刚启动的时候时间未同步，仍然表示1970年的时间。当开机时该时间不好用。
	return 0;
}

4. 编译时间

我曾经有遇到过，由于集成错误，或者image文件的sparse格式与raw格式转化错误，导致升级后的版本，个别分区并非当前集成编译的版本。比如集成发布3.1日的镜像版本，但是我们代码中的版本却是2.1日的提交。遇到此类问题排查需要在代码中加入编译时间的日志。
编译时间通过利用C++编译器提供的预定于宏来实现，一般情况C/C++编译器会内置几个宏，这些宏定义不仅可以帮助我们完成跨平台的源码编写，灵活使用也可以巧妙地帮我们输出非常有用的调试信息。
通过下面的方法可以在代码日志中查看到你的模块编译的版本。

printf("compile time: %s %s", __DATE__, __TIME__);

ANSI C标准中还有几个标准预定义宏（也是常用的）：

__LINE__：在源代码中插入当前源代码行号
__FILE__：在源文件中插入当前源文件名
__DATE__：在源文件中插入当前的编译日期
__TIME__：在源文件中插入当前编译时间
__STDC__：当要求程序严格遵循ANSI C标准时该标识被赋值为1
__cplusplus：当编写C++程序时该标识符被定义

上述预定义宏可以用于代码的调试，以及提供so库或静态库的控制方法。

总结

定时器的合理使用，会对我们排查问题有帮助，但如果使用方法错误，或异常使用可能会对排查问题起到负作用。建议定时器的使用仅用于debug阶段。