1。后台Linux时间管理，包括clocksource、clockevent、timer、tick、timekeeper等概念，这些概念有机地组成了一个完整的时间码体系。当然，代码中会有错误。本文从一个bug入手，在实战中加深对理论的理解。得到时间，却坠毁了。2、症状OPPO云内核团队收到连接告警，发现机器被重置：PID:0TASK:ffff8d2b3775b0c0CPU:1COMMAND:"swapper/1"#0[ffff8d597f6489f0]machine_kexecatffffffffa5a63b34#1[ffff8d597f648a50]c__crash_kexeatffffffffa5b1e242#2[ffff8d597f648b20]panicatffffffffa615d85b#3[ffff8d597f648ba0]nmi_panicatffffffffa5a9859f#4[ffff8d597f648bb0]watchdog_overflow_callbackatffffffffa5b4a881#5[ffff8d597f648bc8]__perf_event_overflowatffffffffa5ba26b7#6[ffff8d597f648c00]perf_event_overflowatffffffffa5babd24#7[ffff8d597f648c10]intel_pmu_handle_irqatffffffffa5a0a850#8[ffff8d597f648e38]perf_event_nmi_handleratffffffffa616d031#9[ffff8d597f648e58]nmi_handleatffffffffa616e91c#10[ffff8d597f648eb0]????do_nmiatffffffffa616ebf8#11[ffff8d597f648ef0]end_repeat_nmiatffffffffa616dd89[exceptionRIP:__getnstimeofday64+144]RIP:ffffffffa5b03940RSP:ffff8d597f643c78RFLAGS：00000212RAX：15b5c8320b8602cdRBX：ffff8d597f643cb0RCX：000000005f89ee29RDX:00000000ee4479feRSI:0000012b5478f3b2RDI:0009709c7629b240RBP:ffff8d597f643c90R8:00000000007001deR9:ffff8d596d5c0000R10:000000000000007aR11:000000000000000eR12:ffffffffa662ea80R13:000000003ccbcfb6R14:ffff8d895de08000R15:0000000000000081ORIG_RAX:ffffffffffffffffCS:0010SS:0018------#12[ffff8d597f643c78]__getnstimeofday64atffffffffa5b03940#13[ffff8d597f643c98]getnstimeofday64atffffffffa5b0398e#14[ffff8d597f643ca8]ktime_get_realatffffffffa5b03a45#15[ffff8d597f643cd0]netif_receive_skb_internalatffffffffa603b936#16[ffff8d597f643d00]napi_gro_receiveatffffffffa603c588#17[ffff8d597f643d28]mlx5e_handle_rx_cqe_mpwrqatffffffffc052ef1d[mlx5_core]#18[ffff8d597f643db8]mlx5e_poll_rx_cqatffffffffc052f4b8[mlx5_core]#19[ffff8d597f643e08]mlx5e_napi_pollatffffffffc05304c6[mlx5_core]#20[ffff8d597f643e78]net_rx_actionatffffffffa603bf1f#21[ffff8d597f643ef8]__do_softirqatffffffffa5aa2155#22[ffff8d597f643f68]call_softirqatffffffffa617a32c#23[ffff8d597f643f80]do_softirqatffffffffa5a2e675因为我们分析的包接收进程从栈中获取hardlock的序号在hardlock的过程中之前给了很多。无非就是关闭中断时间长了。具体关闭中断的地方可以看call_softirq函数。三、故障现象分析1）理论知识在处理网络数据包软中断的过程中，会打上时间戳，也就是说对于oppo云机来说，上面的调用栈路径是比较火的成熟路径。成熟路径的问题比较少见，所以有必要分享一下。初始化计时时，很难选择最好的时钟源，因为很可能最好的时钟源还没有初始化。所以策略是使用初始化计时时必须准备好的时钟源，比如基于jiffies的时钟源。一般来说，计时模块在一个tick到来时更新各个系统时钟的时间值。ktime_get调用很可能发生在两个滴答之间。这时，仅仅依靠当前系统时钟的取值精度是不够的。毕竟那个时间值是每个刻度更新的。因此，为了获得高精度，ns值的获取是通过timekeeping_get_ns来完成的。timekeeping_get_ns是本文的主角。此函数获取实时时钟当前时刻的纳秒值，这是最后一次滴答时的实时时间。它是通过将时钟的时间值(xtime_nsec)添加到当前时间和最后一个滴答之间的增量时间值来计算的。系统运行后，realtimeclock+wall_to_monotonic就是系统的正常运行时间，realtimeclock+wall_to_monotonic+sleep时间也是系统的开机时间。2）实战分析根据调用栈，简单看一下，__getnstimeofday64只有一个循环，即读取timekeeper_seq的序列锁，代码分析如下：int__getnstimeofday64(structtimespec64*ts){structtimekeeper*tk=&timekeeper;无符号长序列；s64纳秒=0；做{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:里面有一个循环，/**不要提早退出，以防有调用者仍在使用*该值，即使面对WARN_ON。*/if(unlikely(timekeeping_suspended))return-EAGAIN;return0;}但从汇编的角度来看：0xffffffffa5b0393b<__getnstimeofday64+139>:xor%edx,%edx----clearu32ret=0;0xffffffffa5b0393d<__getnstimeofday64+141>:nopl(%rax)0xffffffffa5b03940<__getnstimeof+144>:sub$0x3b9aca00,%rax--------------------1s是1000000000ns，这里是循环，而栈中的rax为15b5c8320b8602cd0xffffffffa5b03946<__getnstimeofday64+150>:add$0x1,%edx---------ret++;edx为rdx的低32位，rdx为00000000ee4479fe，所以edx为0xee4479fe，即是39974650860xffffffffa5b03949<__getnstimeofday64+153>:cmp$0x3b9ac9ff,%rax----------------------------------------剩余是否小于1ns0xffffffffa5b0394f<__getnstimeofday64+159>:ja0xffffffffa5b03940<__getnstimeofday64+144>/include/linux/time.h:215---对应timespec_add_ns0xffffffffa5b03951del<__getns16-1day>计算6d+--%timeof1addx%rcx,第二个值+之前保存的第二个值就是最新的第二个值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+1440xffffffffa5b03940<__getnstimeofday64+144>:sub$0x3b9aca00,%rax------------------1s就是1000000000ns，循环到这里，栈中的rax为15b5c8320b8602cd原来我们在timespec64_add_ns循环函数：static__always_inlinevoidtimespec64_add_ns(structtimespec64*a,u64ns){a->tv_sec+=__iter_div_u64_rem(a->tv_nsec+ns,NSEC_PER_SEC,&ns);a->tv_nsec=ns;}__iter_div_u64_rem展开如下：static6__always_u64_u64_rem(,u32除数,u64*余数){u32ret=0;while(dividend>=divisor){//thisloop/*下面的asm()阻止编译器将这个循环优化为模运算。*/asm("":"+rm"(红利));股息-=除数；回复++；}*余数=股息；returnret;}我们的条目参数除数为NSEC_PER_SEC，即10的9次方，十六进制为0x3b9aca00。由于是在循环中，所以我们的红利是rax。请注意这个值是：RAX:15b5c8320b8602cdcrash>p0x15b5c8320b8602cd/0x3b9aca00$7=1564376562是按照这个计算出来的，为了完成计算，这么大的值你得循环这么多次1564376562。到猴年我真的不知道怎么骑车了。那么这个值是怎么来的呢？原来这个值是前后两次读取closk_source的周期差计算出来的。静态内联s64timekeeping_get_ns(structtk_read_base*tkr){u64delta;delta=timekeeping_get_delta(tkr);//caq:上次读取和本次读取的差returntimekeeping_delta_to_ns(tkr,delta);//caq:将差转为ns}delta的来源是：staticinlineu64timekeeping_get_delta(structtk_read_base*tkr){u64cycle_now,delta;结构时钟源*时钟；/*读取时钟源：*/clock=tkr->clock;cycle_now=tkr->clock->read(clock);//读取当前值/*计算自上次update_wall_time以来的delta*/delta=clocksource_delta(cycle_now,clock->cycle_last,clock->mask);//计算差值returndelta;}本来delta的获取就是在线读取当前clocksource的cycle值，然后通过clocksource_delta计算出对应的差值。根据上面的代码，我们首先要知道当前的clocksource是哪个：crash>timekeepertimekeeper=$1={tkr_mono={------------------------------timekeeping_get_ns(&tk->tkr_mono)clock=0xffffffffa662ea80,----------这是clocksource，这个值目前是clocksource_tsccycle_last=16728674596502256,mult=7340510,shift=24,XTIME_NSEC=2657092090049088，这个这个并不ns，而而>>tkr->shiftbase={tv64=278453640047242}}，tkr_raw={,base={tv64=2788490058099290}},xtime_sec=1602874921,--------------当前秒数timekeeper选择当前精度最高的clocksource工作：crash>dis-l0xffffffffa662ea800xffffffffa662ea80:addb$0xa5,-0x5d(%rcx)------------是clocksource_tsc,tsc是一个clock_sourcecrash>clocksource_tscclocksource_tsc=$2={read=0xffffffffa5a34180,-----------read_tsccycle_last=16728674596502256,------上次更新walltime时刻取的周期值mask=18446744073709551615,mult=8007931,shift=24,-------------------注意位数max_idle_ns=204347035648,maxadj=880872,archdata={vclock_mode=1},name=0xffffffffa647c1cd"tsc",---名单={下一个=0xffffffffa6633ff8,prev=0xffffffffa665c9b0},rating=300,--------------priority,enable=0x0,disable=0x0,flags=35,---noCLOCK_SOURCE_UNSTABLEflag挂起=0x0,恢复=0x0,owner=0x0}计算分析差异如下：staticinlines64timekeeping_delta_to_ns(structtk_read_base*tkr,u64delta){s64nsec;//注意，这里是有符号数nsec=delta*tkr->mult+tkr->xtime_nsec;nsec>>=tkr->shift;//转换为ns/*如果arch需要，在get_arch_timeoffset()中加入*/returnnsec+arch_gettimeoffset();}timekeeping_delta_to_ns返回值太大，有两种可能：一种是delta太大，delta*tkr->mult溢出了s64的值。这是一个错误。另一种可能是前后直接读取的delta值太大，这涉及到没有及时调用update_wall_time来读取当前clocksource的cycle。4.问题排查这个s64overflowbug已经在社区修复了。-staticinlines64timekeeping_delta_to_ns(structtk_read_base*tkr,+staticinlineu64timekeeping_delta_to_ns(structtk_read_base*tkr,cycle_tdelta){-s64nsec;+u64nsec;查看RedHat的changelog，也是根据upstream修复的，但是我觉得风险还是有的，因为有时候update_wall_time更新的不是那么及时，甚至从s64改成u64也不能解决溢出问题，因为从timekeeping_delta_to_ns函数可以明显看出并不是u64的所有64位都使用循环differenceValue。相信社区最终会有人爆出这个问题。5.故障规避或解决方案可能的解决方案是：增加告警，对于softlocks及时介入，可能会导致update_wall_time更新不及时。关于作者安庆进阶终端工程师目前主要负责linux内核、容器、虚拟机等虚拟化工作，更多精彩内容扫描二维码关注【OPPO数智科技】公众号
