前几天帮同事看问题时，意外的发现了时钟源影响性能的 case, 比较典型，记录一下。网上也有人遇到过，参考虾皮的[Go] Time.Now函数CPU使用率异常 和 Two frequently used system calls are ~77% slower on AWS EC2
本质都是 fallback 系统调用，所以慢了，但是触发这个条件的原因不太一样。我最后的分析也可能理解有误，欢迎一起讨论并指正。
上图是 perf 性能图，可以发现 __clock_gettime 系统调用相关的耗时最多，非常诡异。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 package mainimport ( "fmt" "time" ) func main () for i := 0 ; i < 10 ; i++{ t1 := time.Now() t2 := time.Now() fmt.Printf("Time taken: %v\n" , t2.Sub(t1)) } }
上图是最小复现 demo, 直接查看 time.Now() 函数的耗时。使用 strace -ce 来查看系统调用的统计报表
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 ~# strace -ce clock_gettime go run time_demo.go Time taken: 1.983µs Time taken: 1.507µs Time taken: 2.247µs Time taken: 2.993µs Time taken: 2.703µs Time taken: 1.927µs Time taken: 2.091µs Time taken: 2.16µs Time taken: 2.085µs Time taken: 2.234µs % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.001342 13 105 clock_gettime ------ ----------- ----------- --------- --------- ---------------- 100.00 0.001342 105 total
上面是有问题的机器结果，可以发现大量的系统调用 clock_gettime 产生。
1 2 3 4 5 6 7 8 9 10 11 ~# strace -ce clock_gettime go run time_demo.go Time taken: 138ns Time taken: 94ns Time taken: 73ns Time taken: 88ns Time taken: 87ns Time taken: 83ns Time taken: 93ns Time taken: 78ns Time taken: 93ns Time taken: 99ns
上面是正常性能机器的结果，耗时是纳秒级别的，快了几个量级。并且没有任何系统调用产生。可以想象一下，每个请求，不同模块都要做大量的 P99 统计，如果 time.Now 自身耗时这么大那这个服务基本不可用了。
有问题机器系统调用函数样子如下：
1 clock_gettime(CLOCK_MONOTONIC, {tv_sec=857882, tv_nsec=454310014}) = 0
测试内核是 5.4.0-1038
来看一下 go time.Now 的实现
1 2 3 4 5 6 func time_now () (sec int64 , nsec int32 , mono int64 ) sec, nsec = walltime() return sec, nsec, nanotime() }
time 只暴露了函数的定义，实现是由底层不同平台的汇编实现，暂时只关注 amd64, 来看下汇编代码
1 2 3 4 5 6 7 8 9 10 11 // src/runtime/sys_linux_amd64.s // func walltime1() (sec int64, nsec int32) // non-zero frame-size means bp is saved and restored TEXT runtime·walltime1(SB),NOSPLIT,$8-12 ...... noswitch: SUBQ $16, SP // Space for results ANDQ $~15, SP // Align for C code MOVQ runtime·vdsoClockgettimeSym(SB), AX ......
那么问题来了，vdso 是什么？
首先说，大家都知道系统调用慢，涉及陷入内核，上下文开销。但是到底多慢呢？
上图是系统调用和普通函数调用的开销对比，参考 [Measurements of system call performance and overhead](http://arkanis.de/weblog/2017-01-05-measurements-of-system-call-performance-and-overhead , Measurements of system call performance and overhead), 可以看到，getpid 走系统调用的开销远大于通过 vdso 的方式，而且也远大于普通函数调用。
vdso (virtual dynamic shared object) 参考 vdso man7 , 本质上来说，还是因为系统调用太慢，涉及到上下文切换，少部分频繁使用的系统调用贡献了大部份时间。所以把这部份，不涉及安全的从内核空间，映射到用户空间。
1 2 3 4 5 6 7 8 9 10 x86-64 functions The table below lists the symbols exported by the vDSO. All of these symbols are also available without the "__vdso_" prefix, but you should ignore those and stick to the names below. symbol version ───────────────────────────────── __vdso_clock_gettime LINUX_2.6 __vdso_getcpu LINUX_2.6 __vdso_gettimeofday LINUX_2.6 __vdso_time LINUX_2.6
上面就是 x86 支持 vdso 的函数，一共 4 个？不可能这么少吧？来看一下线上真实情况的
1 2 3 4 ~# uname -a Linux 5.4.0-1041-aws #43~18.04.1-Ubuntu SMP Sat Mar 20 15:47:52 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux ~# cat /proc/self/maps | grep -i vdso 7fff2edff000-7fff2ee00000 r-xp 00000000 00:00 0 [vdso]
内核版本是 5.4.0, 通过 maps 找到当前进程的vdso, 权限是r-xp，可读可执行但不可写，我们可以直接把他dump出来看看。先在另一个 session 执行 cat, 等待输入，然后用 gdb attach
1 2 3 ~# ps aux | grep cat root 9869 0.0 0.0 9360 792 pts/1 S+ 02:18 0:00 cat root 9931 0.0 0.0 16152 1100 pts/0 S+ 02:18 0:00 grep --color=auto cat
1 2 3 4 5 6 ~# cat /proc/9869/maps | grep -i vdso 7ffe717e6000-7ffe717e7000 r-xp 00000000 00:00 0 [vdso] ~# gdb /bin/cat 9869 ........... (gdb) dump memory /tmp/vdso.so 0x7ffe717e6000 0x7ffe717e7000 (gdb) quit
再查看符号表
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 ~# file /tmp/vdso.so /tmp/vdso.so: ELF 64-bit LSB shared object, x86-64, version 1 (SYSV), dynamically linked, BuildID[sha1]=17d65245b85cd032de7ab130d053551fb0bd284a, stripped ~# objdump -T /tmp/vdso.so /tmp/vdso.so: file format elf64-x86-64 DYNAMIC SYMBOL TABLE: 0000000000000950 w DF .text 00000000000000a1 LINUX_2.6 clock_gettime 00000000000008a0 g DF .text 0000000000000083 LINUX_2.6 __vdso_gettimeofday 0000000000000a00 w DF .text 000000000000000a LINUX_2.6 clock_getres 0000000000000a00 g DF .text 000000000000000a LINUX_2.6 __vdso_clock_getres 00000000000008a0 w DF .text 0000000000000083 LINUX_2.6 gettimeofday 0000000000000930 g DF .text 0000000000000015 LINUX_2.6 __vdso_time 0000000000000930 w DF .text 0000000000000015 LINUX_2.6 time 0000000000000950 g DF .text 00000000000000a1 LINUX_2.6 __vdso_clock_gettime 0000000000000000 g DO *ABS* 0000000000000000 LINUX_2.6 LINUX_2.6 0000000000000a10 g DF .text 000000000000002a LINUX_2.6 __vdso_getcpu 0000000000000a10 w DF .text 000000000000002a LINUX_2.6 getcpu
为什么这么麻烦呢？因为这个 vdso.so 是在内存中维护的，并不像其它 so 动态库一样有对应的文件。
说了这么多，所以问题来了，为什么有了 vdso, 获取时间还要走系统调用呢？？？
关于时钟源，下面的引用来自于 muahao
内核在启动过程中会根据既定的优先级选择时钟源。优先级的排序根据时钟的精度与访问速度。
正常来说，TSC的频率很稳定且不受CPU调频的影响（如果CPU支持constant-tsc）。内核不应该侦测到它是unstable的。但是，计算机系统中存在一种名为SMI（System Management Interrupt）的中断，该中断不可被操作系统感知和屏蔽。如果内核校准TSC频率的计算过程quick_ pit_ calibrate ()被SMI中断干扰，就会导致计算结果偏差较大（超过1%），结果是tsc基准频率不准确。最后导致机器上的时间戳信息都不准确，可能偏慢或者偏快。
当内核认为TSC unstable时，切换到HPET等时钟，不会给你的系统带来过大的影响。当然，时钟精度或访问时钟的速度会受到影响。通过实验测试，访问HPET的时间开销为访问TSC时间开销的7倍左右。如果您的系统无法忍受这些，可以尝试以下解决方法： 在内核启动时，加入启动参数：tsc=reliable
参考 linux insides timers 一节，可以看到各个时钟源调用 clocksource_register_khz 进行注册，分别看 tsc 和 xen
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 static int __init init_tsc_clocksource (void ) ...... if (boot_cpu_has(X86_FEATURE_TSC_KNOWN_FREQ)) { if (boot_cpu_has(X86_FEATURE_ART)) art_related_clocksource = &clocksource_tsc; clocksource_register_khz(&clocksource_tsc, tsc_khz); ...... } static struct clocksource clocksource_tsc = .name = "tsc" , .rating = 300 , .read = read_tsc, .mask = CLOCKSOURCE_MASK(64 ), .flags = CLOCK_SOURCE_IS_CONTINUOUS | CLOCK_SOURCE_VALID_FOR_HRES | CLOCK_SOURCE_MUST_VERIFY, .archdata = { .vclock_mode = VCLOCK_TSC }, .resume = tsc_resume, .mark_unstable = tsc_cs_mark_unstable, .tick_stable = tsc_cs_tick_stable, .list = LIST_HEAD_INIT(clocksource_tsc.list ), };
查看 clocksource_tsc 时钟源的 vclock_mode 是 VCLOCK_TSC
1 2 3 4 5 6 7 8 9 10 11 12 static void __init xen_time_init (void ) ...... clocksource_register_hz(&xen_clocksource, NSEC_PER_SEC); ...... } static void xen_setup_vsyscall_time_info (void ) ...... xen_clocksource.archdata.vclock_mode = VCLOCK_PVCLOCK; }
查看 xen 时钟源的 vclock_mode 是 VCLOCK_PVCLOCK
那么问题来了，clocksource 是如何与 vdso_data 关联的呢？这里面比较复杂，参考 linux内核中的定时器和时间管理 和 vdso段数据更新 , 定位到 /kernel/time/tick-common.c 的 timekeeping_update 函数，由它负责将定时器更新到用户层的 vdso 区。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 static void timekeeping_update (struct timekeeper *tk, unsigned int action) ...... update_vsyscall(tk); update_pvclock_gtod(tk, action & TK_CLOCK_WAS_SET); ...... } void update_vsyscall (struct timekeeper *tk) struct vdso_data *vdata = struct vdso_timestamp *vdso_ts ; s32 clock_mode; u64 nsec; vdso_write_begin(vdata); clock_mode = tk->tkr_mono.clock->vdso_clock_mode; vdata[CS_HRES_COARSE].clock_mode = clock_mode; vdata[CS_RAW].clock_mode = clock_mode; vdso_ts = &vdata[CS_HRES_COARSE].basetime[CLOCK_REALTIME]; vdso_ts->sec = tk->xtime_sec; vdso_ts->nsec = tk->tkr_mono.xtime_nsec; vdso_ts = &vdata[CS_HRES_COARSE].basetime[CLOCK_REALTIME_COARSE]; vdso_ts->sec = tk->xtime_sec; vdso_ts->nsec = tk->tkr_mono.xtime_nsec >> tk->tkr_mono.shift; vdso_ts = &vdata[CS_HRES_COARSE].basetime[CLOCK_MONOTONIC_COARSE]; vdso_ts->sec = tk->xtime_sec + tk->wall_to_monotonic.tv_sec; nsec = tk->tkr_mono.xtime_nsec >> tk->tkr_mono.shift; nsec = nsec + tk->wall_to_monotonic.tv_nsec; vdso_ts->sec += __iter_div_u64_rem(nsec, NSEC_PER_SEC, &vdso_ts->nsec); WRITE_ONCE(vdata[CS_HRES_COARSE].hrtimer_res, hrtimer_resolution); if (clock_mode != VDSO_CLOCKMODE_NONE) update_vdso_data(vdata, tk); __arch_update_vsyscall(vdata, tk); vdso_write_end(vdata); __arch_sync_vdso_data(vdata); } static void update_pvclock_gtod (struct timekeeper *tk) struct pvclock_gtod_data *vdata = u64 boot_ns; boot_ns = ktime_to_ns(ktime_add(tk->tkr_mono.base, tk->offs_boot)); write_seqcount_begin(&vdata->seq); vdata->clock.vclock_mode = tk->tkr_mono.clock->archdata.vclock_mode; vdata->clock.cycle_last = tk->tkr_mono.cycle_last; vdata->clock.mask = tk->tkr_mono.mask; vdata->clock.mult = tk->tkr_mono.mult; vdata->clock.shift = tk->tkr_mono.shift; vdata->boot_ns = boot_ns; vdata->nsec_base = tk->tkr_mono.xtime_nsec; vdata->wall_time_sec = tk->xtime_sec; write_seqcount_end(&vdata->seq); } static void update_pvclock_gtod (struct timekeeper *tk) struct pvclock_gtod_data *vdata = u64 boot_ns; boot_ns = ktime_to_ns(ktime_add(tk->tkr_mono.base, tk->offs_boot)); write_seqcount_begin(&vdata->seq); vdata->clock.vclock_mode = tk->tkr_mono.clock->archdata.vclock_mode; vdata->clock.cycle_last = tk->tkr_mono.cycle_last; vdata->clock.mask = tk->tkr_mono.mask; vdata->clock.mult = tk->tkr_mono.mult; vdata->clock.shift = tk->tkr_mono.shift; vdata->boot_ns = boot_ns; vdata->nsec_base = tk->tkr_mono.xtime_nsec; vdata->wall_time_sec = tk->xtime_sec; write_seqcount_end(&vdata->seq); }
anatony-of-the-vDSO-on-arm64.png
上面的截图来自 arm vdso 实现，和 x86 的类似。
然后再看一下 timekeeper 和 clocksource 是如何对应的呢？在 timekeeping_init 函数里
1 2 3 4 5 6 7 8 9 10 11 12 void __init timekeeping_init (void ) struct timespec64 wall_time , boot_offset , wall_to_mono ; struct timekeeper *tk = struct clocksource *clock ; ...... clock = clocksource_default_clock(); if (clock->enable) clock->enable(clock); tk_setup_internals(tk, clock); ... }
这是初始化时的函数，每当时钟源变更时，会调用 change_clocksource 切换。
1 2 3 4 5 6 7 8 9 10 static __maybe_unused int __cvdso_clock_gettime(clockid_t clock, struct __kernel_timespec *ts) { int ret = __cvdso_clock_gettime_common(clock, ts); if (unlikely(ret)) return clock_gettime_fallback(clock, ts); return 0 ; }
1 2 3 4 5 6 7 8 9 10 11 static __always_inlinelong clock_gettime_fallback (clockid_t _clkid, struct __kernel_timespec *_ts) long ret; asm ("syscall" : "=a" (ret), "=m" (*_ts) : "0" (__NR_clock_gettime), "D" (_clkid), "S" (_ts) : "rcx" , "r11" ); return ret; }
先直接看 fallback 逻辑，好嘛，直接是汇编的 syscall 调用，注意这里汇编是和平台相关的，这个代码是 x86. 这里 unlikely 是做分支预测的，后面的事情大概率不会发生，如果 ret 不为 0, 说明 vdso 获取时间失败，那么来看下什么时候 __cvdso_clock_gettime_common 会失败。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 static __maybe_unused int __cvdso_clock_gettime_common(clockid_t clock, struct __kernel_timespec *ts) { const struct vdso_data *vd = u32 msk; if (unlikely((u32) clock >= MAX_CLOCKS)) return -1 ; msk = 1U << clock; if (likely(msk & VDSO_HRES)) { return do_hres(&vd[CS_HRES_COARSE], clock, ts); } else if (msk & VDSO_COARSE) { do_coarse(&vd[CS_HRES_COARSE], clock, ts); return 0 ; } else if (msk & VDSO_RAW) { return do_hres(&vd[CS_RAW], clock, ts); } return -1 ; }
这里只看 do_hres 实现
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 static int do_hres (const struct vdso_data *vd, clockid_t clk, struct __kernel_timespec *ts) const struct vdso_timestamp *vdso_ts = u64 cycles, last, sec, ns; u32 seq; do { seq = vdso_read_begin(vd); cycles = __arch_get_hw_counter(vd->clock_mode); ns = vdso_ts->nsec; last = vd->cycle_last; if (unlikely((s64)cycles < 0 )) return -1 ; ns += vdso_calc_delta(cycles, last, vd->mask, vd->mult); ns >>= vd->shift; sec = vdso_ts->sec; } while (unlikely(vdso_read_retry(vd, seq))); ts->tv_sec = sec + __iter_div_u64_rem(ns, NSEC_PER_SEC, &ns); ts->tv_nsec = ns; return 0 ; }
__arch_get_hw_counter 会根据 clock_mode 求出 cycles 值，这是一个 u64 类型，如果转成 s64 为负数，那就返回 -1, 此时会触发 fallback 系统调用逻辑。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 static inline u64 __arch_get_hw_counter(s32 clock_mode){ if (clock_mode == VCLOCK_TSC) return (u64)rdtsc_ordered(); #ifdef CONFIG_PARAVIRT_CLOCK if (clock_mode == VCLOCK_PVCLOCK) { barrier(); return vread_pvclock(); } #endif #ifdef CONFIG_HYPERV_TIMER if (clock_mode == VCLOCK_HVCLOCK) { barrier(); return vread_hvclock(); } #endif return U64_MAX; }
1 2 3 4 5 6 7 8 9 10 11 12 13 14 static u64 vread_pvclock (void ) ...... do { version = pvclock_read_begin(pvti); if (unlikely(!(pvti->flags & PVCLOCK_TSC_STABLE_BIT))) return U64_MAX; ret = __pvclock_read_cycles(pvti, rdtsc_ordered()); } while (pvclock_read_retry(pvti, version)); return ret; }
这里判断如果 flags 里没有 PVCLOCK_TSC_STABLE_BIT 标记，则返回 U64_MAX, 来看一下什么时候没有这个标记
1 2 3 4 5 6 7 8 9 10 11 12 13 14 static int kvm_guest_time_update (struct kvm_vcpu *v) ...... u64 tsc_timestamp, host_tsc; struct kvm_arch *ka = u8 pvclock_flags; bool use_master_clock; ...... use_master_clock = ka->use_master_clock; ...... if (use_master_clock) pvclock_flags |= PVCLOCK_TSC_STABLE_BIT; }
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 static void pvclock_update_vm_gtod_copy (struct kvm *kvm) ...... ka->use_master_clock = host_tsc_clocksource && vcpus_matched && !ka->backwards_tsc_observed && !ka->boot_vcpu_runs_old_kvmclock; ...... }
也就是说，如果宿主机使用了 tsc clocksource, 并且没有观察到时钟回退现象，那么就设置 use_master_clock 为 true, 否则为 false.
所以问题来了，我们这台机器是机器学习 aws p3.2xlarge, 怀疑是和宿主机有关，试了下其它 c5 系列的都己经不支持 xen clocksource 了(仅支持 tsc kvm-clock acpi_pm)，同时 kvm-clock 源测试也支持 vdso, 同时参考 官方玩转GPU实例 blog , 最新的虚拟化技术 Nitro 己经没有这个问题了。
分析来分析去，分析个寂寞。。。
当然对于老的硬件，或是内核还是有必要修复的
1 2 3 4 ~# cat /sys/devices/system/clocksource/clocksource0/available_clocksource xen tsc hpet acpi_pm ~# cat /sys/devices/system/clocksource/clocksource0/current_clocksource xen
查看当前时钟源是 xen, 只需要将 tsc 写入即可。
1 ~# echo tsc > /sys/devices/system/clocksource/clocksource0/available_clocksource
所以需要有任务来检测，如果内核将时钟源修改了，就需要更改为 tsc. 我们 prd 为什么没有这个问题呢？？？ 从 dmesg 输出看，是有任务将 clocksource 切回 tsc 的操作，可能有脚本在检测。
但是还有种情况，就是内核将 tsc 标记为不可信 Clocksource tsc unstable, 这时只能重启内核了。或是在启动内核时，指定 tsc=reliable, 参考 manage-ec2-linux-clock-source
1 GRUB_CMDLINE_LINUX="console=tty0 crashkernel=auto console=ttyS0,115200 clocksource=tsc tsc=reliable"
然后用 grub2-mkconfig -o /boot/grub2/grub.cfg 生成 grub.cfg 配置文件
这次分享就这些，以后面还会分享更多的内容，如果感兴趣，可以关注并点击左下角的分享转发哦(:
