EDA365电子论坛网

标题: 这是一个诡异的时间问题追查 [打印本页]

作者: mutougeda 时间: 2020-3-9 10:17
标题: 这是一个诡异的时间问题追查

问题引入：
问题是我们重装了一台电脑之后，发现apache
的日志里突然增加了很多服务时间超长的请求，如下面两条：
** - - 4913229 11227 [29/Mar/2012:09:59:58 +0800] "GET*****
** - - 4793564 9846 [29/Mar/2012:09:59:58 +0800] "GET *****
请求服务时间都在4s以上！这绝对无法忍受啊！

分析过程：

但是，当我们：
* 手动访问这台服务器之后，发现基本上请求都是正常响应的；
* 从前端反向代理的日志来看，服务时间也是正常的；
那这样推断，真相只有一个，那就是apache的日志时间记录有问题！

什么问题呢?不清楚，但是apache
的时间记录不外乎是在收到请求时记个时间，请求处理完成之后再记一个时间，既然是时?
涞奈侍猓敲淳涂纯聪低呈奔浒桑幼罴虻サ?date 开始，多执行几次：
apache2 # date
Wed Mar 28 17:25:08 CST 2012
apache2 # date
Wed Mar 28 17:25:04 CST 2012  时间减少了？
apache2 # date
Wed Mar 28 17:25:06 CST 2012
apache2 # date
Wed Mar 28 17:25:12 CST 2012
apache2 # date
Wed Mar 28 17:25:13 CST 2012
apache2 # date
Wed Mar 28 17:25:09 CST 2012 时间减少了？
apache2 # date
Wed Mar 28 17:25:09 CST 2012
apache2 # date
Wed Mar 28 17:25:15 CST 2012
那么第一个怀疑就是系统里有进程在自己不断的调时间，比如ntpdate, ntpd
，那么我们首先把 ntpd给停掉；然后系统也没有任何地方会调用ntpdate；
继续观察，发现停掉ntpd后，现象依旧！
还有什么可能呢？ date
程序是从内核里面读取时间还是说需要读取硬件时间？到底是怎么计算的呢？
请教下同事们，据说 sys_time 是读的kernel里的时间，而 sys_gettimeofday
是需要读硬件时钟的。
那么就测试一把吧：
先写个程序调用 time(), 然后打印结果，结果是这样的：
1332986690
1332986692
1332986693
1332986693
1332986694
1332986694
1332986695
1332986695
1332986696
1332986696
1332986697
1332986697
1332986698
1332986698
1332986699
确实没有问题了！看来有可能是硬件问题了，再看看clock_gettime 的调用：
{
      struct timespec ts;
      int ret = 0;
      ret = clock_gettime(CLOCK_REALTIME, ts);
      printf("ret: %d, time: %d %d", ts.tv_sec, ts.tv_ns
}
编译:       gcc -g -o clock_gettime getdate.c -lrt

~ # ./clock_gettime
ret: 1332991087, time: 594076000 -1
ret: 1332991088, time: 379009000 -1
ret: 1332991089, time: 68561000 -1
ret: 1332991089, time: 714013000 -1
ret: 1332991086, time: 511250000 -1 时间在跳
ret: 1332991091, time: 945626000 -1
ret: 1332991092, time: 650479000 -1
ret: 1332991088, time: 734780000 -1
ret: 1332991094, time: 506114000 -1时间在跳
看来果然有可能是硬件问题！
那么，检查一下，直接调用一下 hwclock --show ，看看是不是可以验证这个问题：
~ # hwclock --show
Thu 29 Mar 2012 10:22:21 AM CST  -0.948923 seconds
~ # hwclock --show
Thu 29 Mar 2012 10:22:22 AM CST  -0.188950 seconds
~ # hwclock --show
Thu 29 Mar 2012 10:22:23 AM CST  -0.244766 seconds
~ # hwclock --show
Thu 29 Mar 2012 10:22:24 AM CST  -0.336868 seconds
~ # hwclock --show
Thu 29 Mar 2012 10:22:25 AM CST  4.237159 seconds
~ # hwclock --show
Thu 29 Mar 2012 10:22:26 AM CST  4.238672 seconds
~ # hwclock --show
Thu 29 Mar 2012 10:22:27 AM CST  -0.379418 seconds
时间居然都是正确的！显然问题没有那么简单。。。那到底是怎么回事？？还是从date
开始查起吧：
date是一个glibc里面的程序，那它的时间源是从哪里来的？查看一下glibc
的源码，它的时间从这里来：
// glibc coreutils gettime.c
/* Get the system time into *TS.  */
void
gettime (struct timespec *ts)
{
#if HAVE_NANOTIME
  nanotime (ts);
#else

# if defined CLOCK_REALTIME && HAVE_CLOCK_GETTIME
  if (clock_gettime (CLOCK_REALTIME, ts) == 0)
return;
# endif

# if HAVE_GETTIMEOFDAY
  {
struct timeval tv;
gettimeofday (&tv, NULL);
ts->tv_sec = tv.tv_sec;
ts->tv_nsec = tv.tv_usec * 1000;
  }
# else
  ts->tv_sec = time (NULL);
  ts->tv_nsec = 0;
# endif

#endif
}
按照 nanotime, clock_gettime, gettimeofday的顺序去读取，我们这个系统中就是
clock_gettime，从上面的小程序中也可以看到clock_gettime的时间是有问题的，那么
clock_gettime的时间源是怎么来的呢？
// linux kernel 2.6.18 arch/x86_64/kernel/time.c
void do_gettimeofday(struct timeval *tv)
{
unsigned long seq, t;
unsigned int sec, usec;

do {
seq = read_seqbegin(&xtime_lock);

sec = xtime.tv_sec;
usec = xtime.tv_nsec / NSEC_PER_USEC;
t = (jiffies - wall_jiffies) * USEC_PER_TICK +
do_gettimeoffset();
usec += t;

} while (read_seqretry(&xtime_lock, seq));

tv->tv_sec = sec + usec / USEC_PER_SEC;
tv->tv_usec = usec % USEC_PER_SEC;
}
反正就是一通计算，其中比较重要的是 do_gettimeoffset
，这个函数的目的是计算上一次更新 xtime
到当前执行这一段时间的偏移量，然后用这个偏移量去加到 xtime
上去，就是当前的时间（因为xtime的精度不够，clock_gettime
的精度要求更高，所以必须计算一个偏移量）。
那么，这个 do_gettimeoffset又是从哪来的？同样的文件里面有：
static inline unsigned int do_gettimeoffset_tsc(void)
{
unsigned long t;
unsigned long x;
t = get_cycles_sync();
if (t < vxtime.last_tsc)
t = vxtime.last_tsc; /* hack */
x = ((t - vxtime.last_tsc) * vxtime.tsc_quot) >> US_SCALE;
return x;
}

static inline unsigned int do_gettimeoffset_hpet(void)
{
/* cap counter read to one tick to avoid inconsistencies */
unsigned long counter = hpet_readl(HPET_COUNTER) - vxtime.last;
return (min(counter,hpet_tick) * vxtime.quot) >> US_SCALE;
}

unsigned int (*do_gettimeoffset)(void) = do_gettimeoffset_tsc;
也就是说，go_gettimeoffset 是从 tsc寄存器从拿到的，这又是神马玩意呢？
参考一下下面的几篇文章【1】【2】【3】，基本就明白了：
tsc是一个cpu内的寄存器，用来累加从系统启动到目前，所有的时钟周期数，全称是
Timestamp Counter；
而且，最重要的是我们发现了一个重要的线索，那就是：
在多核cpu的架构中，tsc寄存器是很有可能不一致的，特别是在intel的比较老的多核CPU
中！坑爹....
很多文章提到过这个问题，比如【1】【2】【4】，显然如果不同cpu
读到的值不同的话，多次执行，显然时间是不一致的。
看起来就是这个问题了，那么就来验证一把：
#include<stdlib.h>
#include<stdio.h>
#include<sys/types.h>
#include<sys/sysinfo.h>
#include<unistd.h>
#include<time.h>

#define __USE_GNU
#include<sched.h>
#include<ctype.h>
#include<string.h>

int main(int argc, char **argv){

      cpu_set_t cs;
      CPU_ZERO(&cs);
      CPU_SET(0, &cs);

      sched_setaffinity(0, sizeof(cpu_set_t), &cs);

      struct timespec ts;
      int ret = 0;
      ret = clock_gettime(CLOCK_REALTIME, &ts);
      printf("ret: %d, time: %lld %lld", ret,  ts.tv_sec, ts.tv_nsec);

}

gcc -g -o cpu0_clock_gettime cpu_getdate.c -lrt

ret: 0, time: 1332992815 537481000
ret: 0, time: 1332992816 506704000
ret: 0, time: 1332992817 9910000
ret: 0, time: 1332992817 480431000
ret: 0, time: 1332992817 936965000
ret: 0, time: 1332992818 416634000
ret: 0, time: 1332992818 850319000
ret: 0, time: 1332992819 305075000
ret: 0, time: 1332992819 729108000
ret: 0, time: 1332992820 164726000
ret: 0, time: 1332992820 577573000
ret: 0, time: 1332992820 985025000
ret: 0, time: 1332992821 394070000
ret: 0, time: 1332992821 816708000
ret: 0, time: 1332992822 216811000
ret: 0, time: 1332992822 616901000
ret: 0, time: 1332992823 18564000w
ret: 0, time: 1332992823 727585000
通过把程序的调度固定在某一个具体的cpu中，那么clock_gettime的结果也是正确的！
经过几次测试，很容易找到两个cpu时间不一致的情况，具体这个例子来说就是 cpu0和
cpu5，把上面的程序修改一下，可以看到结果基本上每次都会跳一把。
问题解决：
那么，tsc在多核cpu中的值不同，应该怎么解决呢？如【4】所示，在高版本的linux
内核中，有人提交了补丁，可以在内核启动时检查并且同步一把，那么升级一下内核到 2
.6.38。
重新启动到新内核之后，问题解决！
总结一下：
1. apache的时间统计方式，没具体看实现，但是显然前后的两个时间可能是在不同的cpu
核上计算出来的。
2. tsc的值，并不能保证是同步的，特别是在某些Intel cpu
的情况下；但是新的内核会做一些检查和resync的工作；
3. time()调用直接读取内核的xtime值，不会触及硬件；但是 gettimeofday()，
clock_gettime() 在 x86_64下都会读取tsc值；
4. hwclock读的硬件时钟显然不是 tsc，应该是实时时钟RTC；
【1】 http://en.wikipedia.org/wiki/Time_Stamp_Counter
【2】 http://juliusdavies.ca/posix_clocks/clock_realtime_linux_faq.html
【3】http://www.linuxforum.net/forum/gshowflat.php?Cat=&Board=driver&Number=
385219&page=0&view=collapsed&sb=5&o=all&fpart ， linux时钟中断机制，Copyright
2003 by 詹荣开
【4】http://lwn.net/Articles/211051/ x86: unify/rewrite SMP TSC sync code

作者: CCxiaom 时间: 2020-3-9 17:20
时间问题追查，牛逼了

欢迎光临 EDA365电子论坛网 (https://bbs.eda365.com/)