pg_test_timing — 测量计时开销
pg_test_timing [option...]
pg_test_timing 是一个用于测量系统上的计时开销并确认 系统时间不会倒退的工具。它会在指定时长内以尽可能快的速度反复读取受支持的时钟源, 然后打印相邻时钟读数之间观测到的差异统计,以及将使用哪个时钟源。
更小(但不为零)的差异更好,因为这意味着时钟硬件更精确,收集一次时钟读数的开销 也更小。收集计时数据较慢的系统,可能会给出不够精确的 EXPLAIN ANALYZE结果。
该工具还有助于判断 track_io_timing 配置参数是否可能产生有用结果, 以及 TSC 时钟源(参见 timing_clock_source) 是否可用并会默认使用。
pg_test_timing接受下列命令行选项:
-d duration--duration=duration #指定测试持续时间,以秒为单位。持续时间越长,精度会略有提高,也更可能发现 系统时钟倒退的问题。默认测试持续时间为 3 秒。
-c cutoff--cutoff=cutoff #指定精确观测计时持续时间列表的 cutoff 百分比(也就是系统时钟值从一次读数到下一次读数的变化)。 当累计百分比达到或超过该值时,列表就会结束,不过始终会打印观测到的最大持续时间。 默认 cutoff 为 99.99。
-V--version #打印pg_test_timing版本并退出。
-?--help #显示有关pg_test_timing命令行参数的帮助信息并退出。
第一块输出有四列,其中的各行展示了按位移一位的 log2(ns) 计时持续时间直方图 (也就是连续时钟读数之间的差值)。这不是传统的 log2(n+1) 直方图,因为它会 单独统计零值,然后从值 1 开始切换到 log2(ns)。
各列含义如下:
第二块输出会给出更详细的信息,显示观测到的精确计时差异。为简洁起见, 当累计百分比超过用户可选的 cutoff 值时,这个列表就会截断。不过,始终会显示 观测到的最大差异。
在支持 TSC 时钟源的平台上,还会显示额外的输出部分, 分别对应 RDTSCP 指令(用于一般计时需求,例如 track_io_timing)和 RDTSC 指令 (用于 EXPLAIN ANALYZE)。在输出末尾,还会显示 TSC 频率,它可能直接来自 CPU 信息,也可能来自替代校准机制, 以及 TSC 时钟源是否会默认使用。
下面的示例结果显示,系统时钟计时中有 99.99% 的循环耗时介于 16 到 63 纳秒之间。 在第二块中,可以看到典型循环时间为 40 纳秒,读数看起来具有完整的纳秒精度。 在系统时钟结果之后,以同样方式显示了 TSC 时钟源结果。 RDTSCP 指令显示大多数循环在 20-30 纳秒内完成,而 RDTSC 指令最快,平均循环时间为 20 纳秒。在这个示例中, TSC 时钟源会默认使用,但可以通过将 timing_clock_source 设为 system 来禁用。
System clock source: clock_gettime (CLOCK_MONOTONIC)
Testing timing overhead for 3 seconds.
Average loop time including overhead: 44.67 ns
Histogram of timing durations:
<= ns % of total running % count
0 0.0000 0.0000 0
1 0.0000 0.0000 0
3 0.0000 0.0000 0
7 0.0000 0.0000 0
15 0.0000 0.0000 0
31 24.0606 24.0606 5385707
63 75.8342 99.8948 16974658
127 0.0900 99.9848 20143
255 0.0069 99.9917 1542
511 0.0014 99.9932 322
1023 0.0003 99.9935 68
2047 0.0001 99.9936 23
4095 0.0036 99.9972 813
8191 0.0018 99.9990 402
16383 0.0005 99.9995 120
32767 0.0001 99.9997 32
65535 0.0001 99.9998 24
Observed timing durations up to 99.9900%:
ns % of total running % count
29 3.6921 3.6921 826442
30 16.6755 20.3676 3732628
31 3.6930 24.0606 826637
40 75.7761 99.8368 16961658
41 0.0019 99.8387 431
...
190 0.0003 99.9901 65
...
29657159 0.0000 100.0000 1
Clock source: RDTSCP
Average loop time including overhead: 37.32 ns
Histogram of timing durations:
<= ns % of total running % count
0 0.0000 0.0000 0
1 0.0000 0.0000 0
3 0.0000 0.0000 0
7 0.0000 0.0000 0
15 0.0000 0.0000 0
31 99.9499 99.9499 26782299
63 0.0381 99.9880 10220
127 0.0008 99.9889 224
255 0.0052 99.9941 1403
511 0.0013 99.9954 340
1023 0.0001 99.9954 17
2047 0.0000 99.9955 7
4095 0.0021 99.9976 569
8191 0.0013 99.9989 357
16383 0.0005 99.9994 128
32767 0.0003 99.9996 70
65535 0.0001 99.9997 19
Observed timing durations up to 99.9900%:
ns % of total running % count
20 16.9064 16.9064 4530201
29 41.5214 58.4279 11125972
30 41.5220 99.9499 11126126
40 0.0089 99.9587 2374
...
130 0.0007 99.9902 181
...
18501572 0.0000 100.0000 1
Fast clock source: RDTSC
Average loop time including overhead: 27.12 ns
Histogram of timing durations:
<= ns % of total running % count
0 0.0000 0.0000 0
1 0.0000 0.0000 0
3 0.0000 0.0000 0
7 0.0000 0.0000 0
15 1.2247 1.2247 456231
31 98.7566 99.9813 36789785
63 0.0109 99.9921 4049
127 0.0029 99.9951 1087
255 0.0008 99.9959 305
511 0.0007 99.9966 279
1023 0.0000 99.9966 7
2047 0.0001 99.9967 22
4095 0.0018 99.9985 673
8191 0.0010 99.9995 383
16383 0.0003 99.9998 94
32767 0.0001 99.9999 38
65535 0.0000 99.9999 9
Observed timing durations up to 99.9900%:
ns % of total running % count
9 0.6316 0.6316 235290
10 0.5931 1.2247 220941
20 91.4328 92.6574 34061442
29 3.6427 96.3001 1357007
30 3.6811 99.9813 1371336
40 0.0089 99.9902 3325
...
61594291 0.0000 100.0000 1
TSC frequency in use: 2449228 kHz
TSC frequency from calibration: 2448603 kHz
TSC clock source will be used by default, unless timing_clock_source is set to 'system'.