Problem Introduction: After we re-installed a computer, we found that the Apache Log suddenly added a lot of requests with long service time, such as the following two: **--4913229 11227 [29/MAR/2012: 09: 59: 58 + 0800] "Get ********-4793564 9846 [29/MAR/2012: 09: 59: 58 + 0800] "Get ***** request service time is above 4s! This is absolutely intolerable! Analysis process: however, when we: * manually access this server, we find that basically all requests respond normally. * from the log of the front-end reverse proxy, the service time is normal; in this way, we can infer that there is only one truth, that is, there is a problem with Apache's log time record! What's the problem? It is not clear, but the Apache time record is nothing more than a time when the request is received, and a time after the request processing is completed? Yanaishi moyun tu chuncong low was Ben sang young Chen? Start date and run it multiple times: apache2 # datewed Mar 28 17:25:08 CST 2012apache2 # datewed Mar 28 17:25:04 CST 2012 time is reduced? Apache2 # datewed Mar 28 17:25:06 CST 2012apache2 # datewed Mar 28 17:25:12 CST 2012apache2 # datewed Mar 28 17:25:13 CST 2012apache2 # datewed Mar 28 17:25:09 CST 2012 time is reduced? Apache2 # datewed Mar 28 17:25:09 CST 2012apache2 # datewed Mar 28 17:25:15 CST 2012 so the first suspect is that there are processes in the system that are constantly tuning their own time, such as ntpdate, ntpd, the ntpd will be stopped first, and the system will call ntpdate in no place. Continue to observe and find that after ntpd is stopped, the problem persists! What is the possibility? Date Program Is the read time from the kernel or the hardware time required? How is it calculated? Ask colleagues, it is said that sys_time is the time in the read kernel, and sys_gettimeofday is the hardware clock. Let's test it. First, write a program to call time () and then print the result. The result is as follows: 133298669013329866921332986693133298669313329866941332986694133298669513329866951332986696133298669613329866971332986697133298669813329866981332986699 is correct! It seems that there may be hardware problems. Let's look at the clock_gettime call: {struct timespec ts; int ret = 0; ret = clock_gettime (clock_realtime, TS); printf ("RET: % d, time: % d ", ts. TV _sec, ts. TV _ns} Compilation: gcc-g-o clock_gettime getdate. c-LRT ~ #. /Clock_gettime RET: 1332991087, time: 594076000-1 RET: 1332991088, time: 379009000-1ret: 1332991089, time: 68561000-1ret: 1332991089, time: 714013000-1ret: 1332991086, time: 511250000-1: Ret: 1332991091, time: 945626000-1ret: 1332991092, time: 650479000-1ret: 1332991088, time: 734780000-1ret: 1332991094, time: 506114000-1 time in the jump seems to be a hardware problem! Then, check and call hwclock -- show to check whether the problem can be verified :~ # 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 time is correct! Obviously the problem is not that simple... So what is going on ?? Start with date: date is a program in glibc. Where does the time source come from? Check the glibc source code. The time is from here: // glibc coreutils gettime. c/* Get the system time into * ts. */voidgettime (struct timespec * TS) {# If have_nanotime nanotime (TS); # else # If defined clock_realtime & have_clock_gettime if (clock_gettime (clock_realtime, TS) =) 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} reads data in the order of nanotime, clock_gettime, and gettimeofday. In our system, clock_gettime is used, from the above small program, we can see that there is a problem with clock_gettime. How does clock_gettime come from? // Linux kernel 2.6.18 ARCH/x86_64/kernel/time. cvoid 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;} is a one-pass calculation, of which do_gettimeoffset is important. The purpose of this function is to calculate the offset of the last update xtime to the current execution time, then add the offset to the xtime, that is, the current time (because the xtime precision is not enough, clock_gettime has a higher precision requirement, so an offset must be calculated ). So where does the do_gettimeoffset come from? The same file contains: 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 evaluate (void) {/* cap counter read to one tick to avoid inconsistencies */unsigned long counter = hpet_readl (hpet_count Er)-vxtime. last; Return (min (counter, hpet_tick) * vxtime. quot)> us_scale;} unsigned int (* do_gettimeoffset) (void) = do_gettimeoffset_tsc; that is to say, the go_gettimeoffset is obtained from the TSC register. What about this? Refer to the following articles in workshop Article [1] [2] [3]: TSC is a register in the CPU used to accumulate the number of clock cycles from the system startup to the present, the full name is timestamp counter. The most important thing is that we have found an important clue: In the multi-core CPU architecture, TSC registers are likely to be inconsistent, especially in Intel's old multi-core CPU! Potholes .... this problem has been mentioned in many articles, such as [1] [2] [4]. Obviously, if the values read by different CPUs are different, the execution time is obviously inconsistent. This seems to be the problem, so let's verify it: # 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", RET, ts. TV _sec, ts. TV _nsec);} gcc-g-o cpu0_clock_gettime cpu_getdate.c-LRT RET: 0, time: 1332992815 537481000ret: 0, time: 1332992816 506704000ret: 0, time: 1332992817 991_ret: 0, time: 1332992817 480431000ret: 0, time: 1332992817 942565000ret: 0, time: 1332992818 416634000ret: 0, time: 1332992818 850319000ret: 0, time: 1332992819 305075000ret: 0, time: 1332992819 7290000000ret: 0, time: 1332992820 164726000ret: 0, time: 1332992820 577573000ret: 0, time: 1332992820 985025000ret: 0, time: 1332992821 394070000ret: 0, time: 1332992821 816708000ret: 0, time: 1332992822 216811000ret: 0, time: 1332992822 616901000ret: 0, time: 1332992823 18564000 wret: 0, time: 1332992823 727585000 schedule the program to a specific CPU, the clock_gettime result is correct! After several tests, it is easy to find the time inconsistency between the two CPUs. In this example, the CPU 0 and CPU 5 are used. Modify the above program, we can see that the results will jump every time. Solution: How can TSC be solved if its values in multi-core CPUs are different? As shown in [4], Someone submitted a patch in the high version of Linux kernel to check and synchronize the patch during kernel startup. Then, upgrade the kernel to 2.6.38. After restarting to the new kernel, the problem is solved! Summary: 1. the Apache time statistics method is not specific, but it is clear that the two time periods may be calculated on different CPU cores. 2. the TSC value cannot be synchronized, especially when some intel CPUs are used. However, the new Kernel performs some checks and resync. the time () call directly reads the kernel's xtime value without hitting the hardware. However, gettimeofday () and clock_gettime () both read the TSC value in x86_64; 4. the hardware clock read by hwclock is obviously not TSC. It should be RTC. [1] http://en.wikipedia.org/wiki/time_stamp_counter%2] clock? Cat = & board = driver & number = 385219 & page = 0 & view = collapsed & SB = 5 & O = All & fpart, Linux clock interruption mechanism, copyright 2003 by Zhan Rongkai [4] http://lwn.net/Articles/211051/ x86: unify/Rewrite smp tsc sync code
Article: http://hi.baidu.com/imedal/blog/item/103b1554e2d91b003b293568.html
