我就获取个时间，机器就down了 linux后端

1. 背景 linux 时间管理，包含clocksource，clockevent，timer，tick，timekeeper等等概念，这些概念有机地组成了完整的时间代码体系。当然，是代码就会有bug，本文通过一个bug入手，在实战中加深对理论的认识。获取时间，但是crash了。
2. 故障现象 OPPO云内核团队接到连通性告警报障，发现机器复位：

PID: 0TASK: ffff8d2b3775b0c0CPU: 1COMMAND: "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: ffffffffa5b03940RSP: ffff8d597f643c78RFLAGS: 00000212 RAX: 15b5c8320b8602cdRBX: ffff8d597f643cb0RCX: 000000005f89ee29 RDX: 00000000ee4479feRSI: 0000012b5478f3b2RDI: 0009709c7629b240 RBP: ffff8d597f643c90R8: 00000000007001deR9: ffff8d596d5c0000 R10: 000000000000007aR11: 000000000000000eR12: ffffffffa662ea80 R13: 000000003ccbcfb6R14: ffff8d895de08000R15: 0000000000000081 ORIG_RAX: ffffffffffffffffCS: 0010SS: 0018 --- --- #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

【我就获取个时间，机器就down了】从堆栈看，我们的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>:ja0xffffffffa5b03940 <__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: 15b5c8320b8602cdcrash> 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 :addb$0xa5,-0x5d(%rcx)--------------就是 clocksource_tsc ，tsc就是一个clock_sourcecrash> 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 = https://www.it610.com/article/{ 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数智技术]公众号