写点什么

我就获取个时间,机器就 down 了

  • 2021 年 11 月 18 日
  • 本文字数:5287 字

    阅读完需:约 17 分钟

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为 15b5c8320b8602cd0xffffffffa5b03946 <__getnstimeofday64+150>:    add    $0x1,%edx---------ret++;edx is the lower 32 bit of rdx,rdx为00000000ee4479fe,所以edx为 0xee4479fe,也就是39974650860xffffffffa5b03949 <__getnstimeofday64+153>:    cmp    $0x3b9ac9ff,%rax-------------------------------------剩余是否小于1ns0xffffffffa5b0394f <__getnstimeofday64+159>:    ja     0xffffffffa5b03940 <__getnstimeofday64+144> /include/linux/time.h: 215---对应 timespec_add_ns0xffffffffa5b03951 <__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_sec0xffffffffa5b0395b <__getnstimeofday64+171>:    cmpl   $0x1,0xc55702(%rip)        # 0xffffffffa6759064----if(timekeeping_suspended) /kernel/time/timekeeping.c: 5120xffffffffa5b03962 <__getnstimeofday64+178>:    pop    %rbx0xffffffffa5b03963 <__getnstimeofday64+179>:    pop    %r120xffffffffa5b03965 <__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> timekeepertimekeeper = $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 0xffffffffa662ea800xffffffffa662ea80 <clocksource_tsc>:   addb   $0xa5,-0x5d(%rcx)--------------就是 clocksource_tsc ,tsc就是一个clock_source

crash> clocksource_tscclocksource_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 数智技术]公众号

发布于: 2021 年 11 月 18 日阅读数: 8
用户头像

还未添加个人签名 2019.12.23 加入

OPPO数智技术干货及技术活动分享平台

评论

发布
暂无评论
我就获取个时间,机器就down了