1. 背景
linux 時間管理，包含clocksource，clockevent，timer，tick，timekeeper等等概念 ，這些概念有機地組成了完整的時間程式碼體系。當然，是程式碼就會有bug，本文通過一個bug入手，在實戰中加深對理論的認識。獲取時間，但是crash了。
2. 故障現象
OPPO雲核心團隊接到連通性告警報障，發現機器復位：
PID: 0 TASK: ffff8d2b3775b0c0 CPU: 1 COMMAND: "swapper/1"
#0 [ffff8d597f6489f0] machine_kexec at ffffffffa5a63b34
#1 [ffff8d597f648a50] __crash_kexec at ffffffffa5b1e242
#2 [ffff8d597f648b20] panic at ffffffffa615d85b
#3 [ffff8d597f648ba0] nmi_panic at ffffffffa5a9859f
#4 [ffff8d597f648bb0] watchdog_overflow_callback at ffffffffa5b4a881
#5 [ffff8d597f648bc8] __perf_event_overflow at ffffffffa5ba26b7
#6 [ffff8d597f648c00] perf_event_overflow at ffffffffa5babd24
#7 [ffff8d597f648c10] intel_pmu_handle_irq at ffffffffa5a0a850
#8 [ffff8d597f648e38] perf_event_nmi_handler at ffffffffa616d031
#9 [ffff8d597f648e58] nmi_handle at ffffffffa616e91c
#10 [ffff8d597f648eb0] do_nmi at ffffffffa616ebf8
#11 [ffff8d597f648ef0] end_repeat_nmi at ffffffffa616dd89
[exception RIP: __getnstimeofday64+144]
RIP: ffffffffa5b03940 RSP: ffff8d597f643c78 RFLAGS: 00000212
RAX: 15b5c8320b8602cd RBX: ffff8d597f643cb0 RCX: 000000005f89ee29
RDX: 00000000ee4479fe RSI: 0000012b5478f3b2 RDI: 0009709c7629b240
RBP: ffff8d597f643c90 R8: 00000000007001de R9: ffff8d596d5c0000
R10: 000000000000007a R11: 000000000000000e R12: ffffffffa662ea80
R13: 000000003ccbcfb6 R14: ffff8d895de08000 R15: 0000000000000081
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
--- <NMI exception stack> ---
#12 [ffff8d597f643c78] __getnstimeofday64 at ffffffffa5b03940
#13 [ffff8d597f643c98] getnstimeofday64 at ffffffffa5b0398e
#14 [ffff8d597f643ca8] ktime_get_real at ffffffffa5b03a45
#15 [ffff8d597f643cd0] netif_receive_skb_internal at ffffffffa603b936
#16 [ffff8d597f643d00] napi_gro_receive at ffffffffa603c588
#17 [ffff8d597f643d28] mlx5e_handle_rx_cqe_mpwrq at ffffffffc052ef1d [mlx5_core]
#18 [ffff8d597f643db8] mlx5e_poll_rx_cq at ffffffffc052f4b8 [mlx5_core]
#19 [ffff8d597f643e08] mlx5e_napi_poll at ffffffffc05304c6 [mlx5_core]
#20 [ffff8d597f643e78] net_rx_action at ffffffffa603bf1f
#21 [ffff8d597f643ef8] __do_softirq at ffffffffa5aa2155
#22 [ffff8d597f643f68] call_softirq at ffffffffa617a32c
#23 [ffff8d597f643f80] do_softirq at ffffffffa5a2e675從堆疊看，我們的0號程式在處理軟中斷收包的過程中，因為獲取個時間，導致了crash。hardlock的分析之前已經給出了很多了，無非是關中斷時間長了，具體關中斷的地方，可以看call_softirq函式即可。
3. 故障現象分析
1）理論知識
在處理網路包的軟中斷過程中，會打時間戳，也就是說，對於oppo雲的機器來說，以上的呼叫棧路徑是一個熱點且成熟的路徑。成熟的路徑出問題比較少見，所以有必要分享一下。在timekeeping初始化的時候，很難選擇一個最好的clock source，因為很有可能最好的那個還沒有初始化呢。因此，策略就是採用一個在timekeeping初始化時一定是ready的clock source，比如基於jiffies 的那個clocksource。
一般而言，timekeeping模組是在tick到來的時候更新各種系統時鐘的時間值，ktime_get呼叫很有可能發生在兩次tick之間，這時候，僅僅依靠當前系統時鐘的值精度就不夠了，畢竟那個時間值是per tick更新的。因此，為了獲得高精度，ns值的獲取是通過timekeeping_get_ns完成的，timekeeping_get_ns就是本文的主角，該函式獲取了real time clock的當前時刻的納秒值，而這是通過上一次的tick時候的real time clock的時間值（xtime_nsec）加上當前時刻到上一次tick之間的delta時間值計算得到的。系統執行之後，real time clock+ wall_to_monotonic是系統的uptime，而real time clock+ wall_to_monotonic + sleep time也就是系統的boot time。
2）實戰分析
根據呼叫堆疊，簡單地看，__getnstimeofday64只有一個迴圈，那就是讀取timekeeper_seq的順序鎖，程式碼分析如下：
int __getnstimeofday64(struct timespec64 *ts)
{
struct timekeeper *tk = &timekeeper;
unsigned long seq;
s64 nsecs = 0;
do {
seq = read_seqcount_begin(&timekeeper_seq);
ts->tv_sec = tk->xtime_sec;//caq:秒值賦值
nsecs = timekeeping_get_ns(&tk->tkr_mono);
} while (read_seqcount_retry(&timekeeper_seq, seq));
ts->tv_nsec = 0;
timespec64_add_ns(ts, nsecs);//caq:這裡面還有個迴圈呢，
/*
* Do not bail out early, in case there were callers still using
* the value, even in the face of the WARN_ON.
*/
if (unlikely(timekeeping_suspended))
return -EAGAIN;
return 0;
}但是從彙編展開來看：
0xffffffffa5b0393b <__getnstimeofday64+139>: xor %edx,%edx----清零 u32 ret = 0;
0xffffffffa5b0393d <__getnstimeofday64+141>: nopl (%rax)
0xffffffffa5b03940 <__getnstimeofday64+144>: sub $0x3b9aca00,%rax---------------------1s就是1000000000 ns，循壞在這，而棧中的rax為 15b5c8320b8602cd
0xffffffffa5b03946 <__getnstimeofday64+150>: add $0x1,%edx---------ret++;edx is the lower 32 bit of rdx，rdx為00000000ee4479fe，所以edx為 0xee4479fe,也就是3997465086
0xffffffffa5b03949 <__getnstimeofday64+153>: cmp $0x3b9ac9ff,%rax-------------------------------------剩餘是否小於1ns
0xffffffffa5b0394f <__getnstimeofday64+159>: ja 0xffffffffa5b03940 <__getnstimeofday64+144>
/include/linux/time.h: 215---對應 timespec_add_ns
0xffffffffa5b03951 <__getnstimeofday64+161>: add %rcx,%rdx---delta算出的秒值+之前儲存的秒值，就是最新的秒值
0xffffffffa5b03954 <__getnstimeofday64+164>: mov %rax,0x8(%rbx)----剩餘的ns，賦值給a->tv_nsec = ns;
0xffffffffa5b03958 <__getnstimeofday64+168>: mov %rdx,(%rbx)---加完delta秒值的最新的秒值，賦值給a->tv_sec
0xffffffffa5b0395b <__getnstimeofday64+171>: cmpl $0x1,0xc55702(%rip) # 0xffffffffa6759064----if(timekeeping_suspended)
/kernel/time/timekeeping.c: 512
0xffffffffa5b03962 <__getnstimeofday64+178>: pop %rbx
0xffffffffa5b03963 <__getnstimeofday64+179>: pop %r12
0xffffffffa5b03965 <__getnstimeofday64+181>: pop %r13從堆疊看出，我們迴圈在__getnstimeofday64+144
0xffffffffa5b03940 <__getnstimeofday64+144>: sub $0x3b9aca00,%rax---------------------1s就是1000000000 ns，循壞在這，而棧中的rax為 15b5c8320b8602cd原來我們迴圈在timespec64_add_ns 函式裡面：
static __always_inline void timespec64_add_ns(struct timespec64 *a, u64 ns)
{
a->tv_sec += __iter_div_u64_rem(a->tv_nsec + ns, NSEC_PER_SEC, &ns);
a->tv_nsec = ns;
}
__iter_div_u64_rem展開如下：
static __always_inline u32
__iter_div_u64_rem(u64 dividend, u32 divisor, u64 *remainder)
{
u32 ret = 0;
while (dividend >= divisor) {//這個迴圈
/* The following asm() prevents the compiler from
optimising this loop into a modulo operation. */
asm("" : "+rm"(dividend));
dividend -= divisor;
ret++;
}
*remainder = dividend;
return ret;
}我們的入參divisor是 NSEC_PER_SEC，也就是10的9次方，16進製為0x3b9aca00，既然在迴圈，那麼我們的dividend是rax，請注意看值為：
RAX: 15b5c8320b8602cd
crash> p 0x15b5c8320b8602cd/0x3b9aca00
$7 = 1564376562按照這樣計算，要計算完畢，還得迴圈 1564376562 這麼多次。
這麼大的一個值，確實不知道迴圈到猴年馬月去。
那麼這個值怎麼來的呢？原來這個值是前後兩次讀取closk_source的cycle差值計算出來的。
static inline s64 timekeeping_get_ns(struct tk_read_base *tkr)
{
u64 delta;
delta = timekeeping_get_delta(tkr);//caq:上次讀取與本次讀取之間的差值
return timekeeping_delta_to_ns(tkr, delta);//caq:差值轉換為ns
}
delta的來源是：
static inline u64 timekeeping_get_delta(struct tk_read_base *tkr)
{
u64 cycle_now, delta;
struct clocksource *clock;
/* read clocksource: */
clock = tkr->clock;
cycle_now = tkr->clock->read(clock);//當前值是通過讀取來的
/* calculate the delta since the last update_wall_time */
delta = clocksource_delta(cycle_now, clock->cycle_last, clock->mask);//計算差值
return delta;
}原來，delta的獲取是線讀取當前clocksource的cycle值，然後通過clocksource_delta 計算對應的差值，根據以上程式碼，首先我們得知道當前的clocksource是哪個：
crash> timekeeper
timekeeper = $1 = {
tkr_mono = {------------------------------timekeeping_get_ns(&tk->tkr_mono)
clock = 0xffffffffa662ea80, ------------這個就是 clocksource，這個值當前就是 clocksource_tsc
cycle_last = 16728674596502256,
mult = 7340510,
shift = 24,
xtime_nsec = 2657092090049088, 這個值並不是ns，而是要 >>tkr->shift
base = {
tv64 = 2788453640047242
}
},
tkr_raw = {
clock = 0xffffffffa662ea80,
cycle_last = 16728674596502256,
mult = 8007931,
shift = 24,
xtime_nsec = 0,
base = {
tv64 = 2788490058099290
}
},
xtime_sec = 1602874921, ------------------當前的秒數timekeeper是選擇當前精度最高的clocksource來工作的：
crash> dis -l 0xffffffffa662ea80
0xffffffffa662ea80 <clocksource_tsc>: addb $0xa5,-0x5d(%rcx)--------------就是 clocksource_tsc ，tsc就是一個clock_source
crash> clocksource_tsc
clocksource_tsc = $2 = {
read = 0xffffffffa5a34180, -----------read_tsc
cycle_last = 16728674596502256, ------上次更新牆上時間的時刻取的cycle值
mask = 18446744073709551615,
mult = 8007931,
shift = 24, ----------------------注意位數
max_idle_ns = 204347035648,
maxadj = 880872,
archdata = {
vclock_mode = 1
},
name = 0xffffffffa647c1cd "tsc", ---名稱
list = {
next = 0xffffffffa6633ff8,
prev = 0xffffffffa665c9b0
},
rating = 300, --------------優先順序，
enable = 0x0,
disable = 0x0,
flags = 35, ---沒有CLOCK_SOURCE_UNSTABLE標誌
suspend = 0x0,
resume = 0x0,
owner = 0x0
}差值的計算分析如下：
static inline s64 timekeeping_delta_to_ns(struct tk_read_base *tkr,
u64 delta)
{
s64 nsec;//注意，這裡是帶符號數
nsec = delta * tkr->mult + tkr->xtime_nsec;
nsec >>= tkr->shift;//換算成ns
/* If arch requires, add in get_arch_timeoffset() */
return nsec + arch_gettimeoffset();
}timekeeping_delta_to_ns返回值過大，有兩種可能：
一種是delta的偏大，delta * tkr->mult 對s64的值產生溢位，這個算是個bug。還有一種可能是，直接前後讀取的delta值太大，這涉及到 update_wall_time 並沒有及時呼叫去讀取當前clocksource的cycle。
4. 故障復現
這個s64溢位的bug，在社群已經修復了。
-static inline s64 timekeeping_delta_to_ns(struct tk_read_base *tkr,
+static inline u64 timekeeping_delta_to_ns(struct tk_read_base *tkr,
cycle_t delta)
{
- s64 nsec;
+ u64 nsec;而且檢視紅帽的changelog，也按照上游這樣修復，但是我覺得風險還在的，因為 update_wall_time 有時候更新就不是那麼及時，而哪怕從s64改到u64，並沒有解決溢位問題，因為 timekeeping_delta_to_ns函式中明顯可以看到，u64的64位並沒有全部用到cycle的差值上。我相信社群最終應該會有人爆這個問題的。
5. 故障規避或解決
可能的解決方案是：
增加告警，對於softlock的要及時介入，有可能導致update_wall_time 更新不及時。
作者簡介
Anqing 高階後端工程師
目前主要負責linux核心及容器，虛擬機器等虛擬化方面的工作。
獲取更多精彩內容，掃碼關注[OPPO數智技術]公眾號
