nginx log打印输出精度问题

1、问题：

nginix log默认输出时间打印是到秒级，有时为了查某一个请求花费的时间，一般都在10-20ms毫秒级别，因此就没法更细致的分析哪个步骤耗时时间。

2、问题的分析：

一般服务器对于时间的精度要求不高，内部对时间进行cache，用来减少对gettimeofday（）的调用，对于打印时需要毫秒级就成为一个问题了。

在ngx_times.c中提供了ngx_time_update（）函数来更新时间缓存，另外还有一个在信号处理中用来更新cached_err_log_time的ngx_time_sigsafe_update（）函数，其他地方都是从时间缓存中取得时间。

那么先看一下nginx 对于时间这块是如何处理的？有两种方式：

---

a、ngx_timer_resolution == 0 情况下
即查找ngx_time_update()和ngx_time_sigsafe_update()这两个函数被调用的位置就知道

ngx_time_sigsafe_update() 这个函数很简单，只被ngx_signal_handler() 调用，每次执行信号处理函数时候被调用，且只在主进程中被执行。

ngx_time_update() 主进程中的 ngx_master_process_cycle() 循环中被调用、主进程捕捉到并处理完一个信号返回时被调用更新时间缓存。子进程调用链为ngx_worker_process_cycle() -> ngx_process_events_and_timers() -> ngx_process_events() -> ngx_time_update() 就是在epoll_wait(-1) 返回后调用更新时间缓存。cache_manager 进程也会更新时间缓存，没有本地file这块是被禁止的。

b、ngx_timer_resolution > 0 情况下

先看一段代码：

sigaction(SIGALRM, &sa, NULL);

itv.it_interval.tv_sec = ngx_timer_resolution / 1000;
itv.it_interval.tv_usec = (ngx_timer_resolution % 1000) * 1000;
itv.it_value.tv_sec = ngx_timer_resolution / 1000;
itv.it_value.tv_usec = (ngx_timer_resolution % 1000 ) * 1000;
setitimer(ITIMER_REAL, &itv, NULL) ;

安装SIGALRM根据ngx_timer_resolution精度唤醒、从而唤醒 epoll_wait(-1) 返回并执行时间更新。这会加大cpu的执行频度、对cpu占用率有影响，因为不是由真正的IO端口监听唤醒而是由内部定时信号唤醒的。( SIGALRM信号会产生 errno = EINTR 调用信号被打断)

3、解决问题办法

首先分析一下 ngx_log.c 中打印函数： ngx_log_error_core()、无论哪个级别的打印最后都是调用这个函数：

// 时间信息
p = ngx_cpymem(errstr, ngx_cached_err_log_time.data,
                   ngx_cached_err_log_time.len);
// 打印级别
p = ngx_slprintf(p, last, " [%V] ", &err_levels[level]);

/* pid#tid */
p = ngx_slprintf(p, last, "%P#" NGX_TID_T_FMT ": ",
                    ngx_log_pid, ngx_log_tid);
// 客户端信息
if (log->connection) {
     p = ngx_slprintf(p, last, "*%uA ", log->connection);
}

那么要解决就是这个值 ngx_cached_err_log_time 如何获取的
p1 = &cached_err_log_time[slot][0];
nginx使用了原子变量ngx_time_lock来对时间变量进行写加锁，而且nginx考虑到读时间的操作比较多，出于性能的原因没有对读进行加锁，而是采用维护多个时间slot的方式来尽量减少读访问冲突。

if (slot == NGX_TIME_SLOTS - 1) {
        slot = 0;
    } else {
        slot++;
}

ngx_memory_barrier() 防止读操作混乱，它告诉编译器不要将其后面的语句进行优化，不要打乱其执行顺序。

a、修改 timer_resolution 100ms;
并修改代将毫秒级打印加上。测试会有误差，因为其每次获取的时间是从64个slot中下一个中选取的，后面的时间可能会比前面的时间小。

b、直接针对log打印重新一个时间函数，即每次调用gettimeofday() 调用产生即可。
ps: %xx 打印格式需要看源码 ngx_vslprintf() 函数、对一些标准c格式重定义并实现。

基本实现代码如下：

// 增加一个额外的log时间信息获取函数
u_char *ngx_log_time() {
    u_char*          p;
    ngx_tm_t         tm;
    time_t           sec;
    ngx_uint_t       msec;
    struct timeval   tv;    

    ngx_gettimeofday(&tv);
    sec = tv.tv_sec;
    msec = tv.tv_usec / 1000;

    ngx_localtime(sec, &tm);

    p = &err_log_time[0];

    (void) ngx_sprintf(p, "%4d/%02d/%02d %02d:%02d:%02d:%03d",
                       tm.ngx_tm_year, tm.ngx_tm_mon,
                       tm.ngx_tm_mday, tm.ngx_tm_hour,
                       tm.ngx_tm_min, tm.ngx_tm_sec,msec);
    return p;
}

// 修改一下最后的log输出函数
void
ngx_log_error_core(ngx_uint_t level, ngx_log_t *log, ngx_err_t err, const char *fmt, va_list args){
...
#if 0
    p = ngx_cpymem(errstr, ngx_cached_err_log_time.data,
                   ngx_cached_err_log_time.len);
#else 
    errp = ngx_log_time();
    errlen = ngx_strlen(errp);
    p = ngx_cpymem(errstr, errp, errlen);
#endif
...
}

测试结果：
2017/04/25 09:31:43:252 [error] 19896#19896: [lua] init.lua:
2017/04/25 09:31:43:252 [error] 19896#19896: [lua] init.lua:
2017/04/25 09:31:43:253 [error] 19896#19896: [lua] m_goback_
2017/04/25 09:31:43:258 [error] 19903#19903: [lua] m_goback_
2017/04/25 09:31:43:258 [error] 19902#19902: [lua] m_goback_
2017/04/25 09:31:43:290 [error] 19899#19899: [lua] m_goback_
2017/04/25 09:31:43:293 [error] 19900#19900: [lua] m_goback_