2017年8月24日
処理速度の遅いcurrentTimeMillis() – 前編
(2017-07-23)by Pavel Zemtsov
本記事は、原著者の許諾のもとに翻訳・掲載しております。
今日はJavaライブラリの中でも非常に基本的でよく使われるメソッド、 System.currentTimeMillis() を見ていきましょう。
このメソッドはミリ秒単位の精度で現在時刻を知らせます。このことから、このメソッドの処理能力は重要ではないと思う人もいるかもしれません。計測間隔が100ミリ秒や500ミリ秒なのであれば、現在時刻を取得するのに0.1や0.2ミリ秒かかったからといって誰も気にしないでしょう。しかし、やはり頻繁にこのメソッドを呼び出したいケースがありそうです。下記に例を挙げます。
- 異常に長い実行時間を検知し知らせる場合。例えば、HTTPリクエストを実行するのにかかる時間を計測するケースを考えます。この場合、1ミリ秒以下が計測されると思われることでしょうが、実際にはこのメソッドを使えばゼロが出力されることに注意して下さい。しかし時間が異常に長い（例えば100ミリ秒以上）場合は注意をうながしてほしいですよね。この場合は、毎秒に何千何万、または数百万あるかもしれない全てのリクエストを計測することになります。
- 任意のオブジェクトに紐づくタイムスタンプを取得する場合。例えば、キャッシュされたデータを、ある一定の時間でキャッシュからクリアする場合など。
- 長くて、頻繁に起動される非同期プロセスの継続時間を計測する場合。例えばリモートサーバへのリクエストなど。
- 実社会の出来事のタイムスタンプを取得する場合。例えば、トレーディングシステムでは、受注と処理された取引のタイムスタンプを記録するでしょう。
つまり、やや精度が劣る割にはこのメソッドの出番はなかなか多いのです。さてそれでは、このメソッドの処理速度はどの程度なのでしょうか。
スピードの計測
urrentTimeMillis() の処理速度をテストするのは簡単です。optimized out（最適化されて見えなくなった状態）になっていないか確認しつつ、何度も呼び出せばいいのです。
static void test_milli_speed ()
{
long sum = 0;
int N = 100000000;
long t1 = System.currentTimeMillis ();
for (int i = 0; i < N; i++)
sum += System.currentTimeMillis ();
long t2 = System.currentTimeMillis ();
System.out.println ("Sum = " + sum + "; time = " + (t2 - t1) +
"; or " + (t2 - t1) * 1.0E6 / N + " ns / iter");
}Java 1.8.0_92を使って、Windows（Core i7-6820HQ @2.7GHzを搭載したWindows 10のノート型PC）上で実行すると以下のようになります。
>java Time
Sum = 2276735854871496107; time = 393; or 3.93 ns / iter
Sum = 2276735892808191170; time = 382; or 3.82 ns / iter
Sum = 2276735930338889327; time = 379; or 3.79 ns / iter非常にいい結果です。3.8ナノ秒であれば、どこにでもタイムリクエスト命令を挿入できます。どのような処理でも時間を計測し、どのようなリソースにでもタイムスタンプを追加できます。ほぼ自由自在です。毎秒2億6000万回時刻をクエリすることができます。
ではLinuxで実行してみましょう。この計測は、カーネルバージョンが3.17.4のRHEL系OSが動くPCにおいて、CPUはデュアルXeon® CPU E5-2620 v3 @ 2.40GHzという条件で実行しました。
# java Time
Sum = 1499457980079543330; time = 652; or 652.0 ns / iter
Sum = 1499457980725968363; time = 642; or 642.0 ns / iter
Sum = 1499457981368550493; time = 643; or 643.0 ns / iter今回は反復回数のゼロを2個減らし（100万に）しなくてはなりませんでした。実行時間が200倍長くかかっているからです。Linuxのクエリ時間の平均は640ナノ秒で、これは0.5マイクロ秒以上です。毎秒150万回しか実行できません。
これはショックな結果です。つまり currentTimeMillis() をLinuxで使う場合には注意が必要ということです。シーケンシャルな長い処理の計測には使えますが、上述のタスクにはこのメソッドはあまり使い物にならないと言えます。
理由と対策を考えてみましょう。
Windows版
currentTimeMillis() はネイティブな関数です。コードは OpenJDKディストリビューション にあり、 JVM_CurrentTimeMillis （ファイルは hotspot/src/share/vm/prims/jvm.cpp ）にリンクされていて、これが最終的に os::javaTimeMillis() になります。この呼び出しはOSに依存します。
このコードのWindows版（ hotspot/src/os/windows/vm/jvm.cpp/os_windows.cpp ）は次のようになっています。
jlong os::javaTimeMillis() {
if (UseFakeTimers) {
return fake_time++;
} else {
FILETIME wt;
GetSystemTimeAsFileTime(&wt);
return windows_to_java_time(wt);
}
}
jlong windows_to_java_time(FILETIME wt) {
jlong a = jlong_from(wt.dwHighDateTime, wt.dwLowDateTime);
return (a - offset()) / 10000;
}
static jlong _offset = 116444736000000000;
jlong offset() {
return _offset;
}Java の時刻のベースは GetSystemTimeAsFileTime() で、 FILETIME を返します。この構造体は32ビットシステムの時代からあるもので、2つの32ビットフィールド、すなわち dwHighDateTime と dwLowDateTime から成ります。これらを組み合わせて、エポック秒からの100ナノ秒間隔の64ビット数を定義しています。
MSVCでは、この関数を呼び出し、デバッガで実行状況を追跡できます。32ビットモードに逆アセンブルしたコードはこのようになります。
7691C450 mov edi,edi
7691C452 push ebp
7691C453 mov ebp,esp
7691C455 push ebx
7691C456 push esi
7691C457 push edi
7691C458 mov esi,7FFE0018h
7691C45D mov edi,7FFE0014h
7691C462 mov ebx,7FFE001Ch
7691C467 mov eax,dword ptr [esi]
7691C469 mov edx,dword ptr [edi]
7691C46B mov ecx,dword ptr [ebx]
7691C46D cmp eax,ecx
7691C46F jne 7691C480
7691C471 mov ecx,dword ptr [ebp+8]
7691C474 pop edi
7691C475 pop esi
7691C476 pop ebx
7691C477 mov dword ptr [ecx],edx
7691C479 mov dword ptr [ecx+4],eax
7691C47C pop ebp
7691C47D ret 4
7691C480 pause
7691C482 jmp 7691C467これは大変賢いやり方です。この関数にはシステムコールが含まれていません。全てがユーザ空間で行われるのです。全プロセスのアドレス空間にマップされたメモリ空間があり、バックグラウンドのスレッドが定期的に3つの倍長語を更新します。上位、下位、上位の値の順で格納されています。クライアントは3つ全部をこの順番で読み込み、2つの上位が等しければ、下位がそれらと一致していると判断します（x86の強力なメモリオーダリングがこれを保証します）。違っていれば、処理を再度行わなくてはなりませんが、その可能性はとても低いので、全工程が非常に高速なのです。
64ビットモードではこの関数は更にすっきりします。
00007FF90970CE80 mov eax,7FFE0014h
00007FF90970CE85 mov rax,qword ptr [rax]
00007FF90970CE88 mov dword ptr [rcx],eax
00007FF90970CE8A shr rax,20h
00007FF90970CE8E mov dword ptr [rcx+4],eax
00007FF90970CE91 retバックグラウンドのスレッドはアトミックに値の書き込みができ、クライアントはアトミックに読み込みます。実のところ、コードはもっと良くすることもできました。64ビットの値を1つの命令で書くことができます。
mov eax,7FFE0014h
mov rax,qword ptr [rax]
mov qword ptr [rcx],rax
retしかし、どちらにせよこのコードはどんなシステムコールよりも断然速いのです。
このタイマー解像度はどの程度でしょうか？ 配列に値を入れて出力してみましょう。
#define N 1000000
int values[N];
int main(void)
{
int i;
for (i = 0; i < N; i++) {
FILETIME f;
GetSystemTimeAsFileTime (&f);
values[i] = (int) f.dwLowDateTime;
}
for (i = 1; i < N; i++)
if (values[i-1] != values[i])
printf("%d %d\n", i, values[i] - values[i-1]);
return 0;
}出力値は以下の通りです。
68208 5044
214315 5015
362575 5037
508633 4987
654960 5022
800065 5007
943784 5041タイマーは約0.5ミリ秒（2000Hz）ごとにティックします。これは完璧に currentTimeMillis() のベースとしての役割を果たします。
Linux版
ここまで思ったより長くかかりました。次は hotspot/src/os/linux/vm/os_linux.cpp にある os::javaTimeMillis() の別のバージョンを見てみましょう。
jlong os::javaTimeMillis() {
timeval time;
int status = gettimeofday(&time, NULL);
assert(status != -1, "linux error");
return jlong(time.tv_sec) * 1000 + jlong(time.tv_usec / 1000);
}1000を掛けたり1000で割ったりするのに時間がかかるとは思えませんが、とりあえず gettimeofday の処理速度を計測してみましょう。
volatile uint64_t tt;
int main (void)
{
int i;
int N = 10000000;
struct timeval time;
uint64_t t0 = 0;
for (i = 0; i < N; i++) {
gettimeofday (&time, 0);
tt = time.tv_sec * (uint64_t) 1000000 + time.tv_usec;
if (t0 == 0) t0 = tt;
}
printf ("Time for %d: %f s; %f ns\n",
N, (tt - t0) * 1.0E-6, (tt - t0) * 1.0E3 / N);
return 0;
}実行すると、次の結果が得られます。
Time for 10000000: 6.251108 s; 625.110800 nsこの gettimeofday の呼び出しは本当に遅いですよね。なぜでしょう？ システムコールが関わっているのでしょうか。では gdb 上で実行してみましょう。 gettimeofday の呼び出しをステップイン実行してみると、次のように表示されます。
Dump of assembler code for function gettimeofday@plt:
=> 0x0000000000400460 <+0>: jmpq *0x200bba(%rip) # 0x601020 <gettimeofday@got.plt>
0x0000000000400466 <+6>: pushq $0x1
0x000000000040046b <+11>: jmpq 0x400440最初の jmpq は次の命令（ +6 ）にジャンプし、最終的には _dl_runtime_resolve と呼ばれる関数に行き着きます。
ここで実際には、ユーザアドレス空間にあらかじめマップされた小さくて再配置可能な共有ライブラリ、 vDSO （ 仮想動的共有オブジェクト ）へのリンクが起こっています。リンクは gettimeofday の最初の呼び出しの間に起こります。その後呼び出しは解決され、最初のインダイレクトなジャンプでその関数へと直接到達します。この実行をスキップして、次の gettimeofday の呼び出しの前にブレークしましょう。関数は同じように見えます。
=> 0x0000000000400460 <+0>: jmpq *0x200bba(%rip) # 0x601020 <gettimeofday@got.plt>しかし今回は本当の実装へとジャンプします。以下をご覧ください。コメントも追加しています。
関数gettimeofdayのアセンブラコードのダンプ：
=> 0x00007ffff7ffae50 <+0>: push %rbp
0x00007ffff7ffae51 <+1>: mov %rsp,%rbp
0x00007ffff7ffae54 <+4>: push %r15
0x00007ffff7ffae56 <+6>: push %r14
0x00007ffff7ffae58 <+8>: push %r13
0x00007ffff7ffae5a <+10>: push %r12
0x00007ffff7ffae5c <+12>: push %rbx
0x00007ffff7ffae5d <+13>: sub $0x18,%rsp
0x00007ffff7ffae61 <+17>: test %rdi,%rdi
0x00007ffff7ffae64 <+20>: je 0x7ffff7ffaf45 <gettimeofday+245> ; if (tv == NULL)
; gtod_read_begin
0x00007ffff7ffae6a <+26>: mov -0x2df1(%rip),%r8d # 0x7ffff7ff8080 ; gtod->seq
0x00007ffff7ffae71 <+33>: mov $0x7b,%eax
0x00007ffff7ffae76 <+38>: mov $0xffffffffff7ff000,%r12
0x00007ffff7ffae7d <+45>: lsl %ax,%ebx
0x00007ffff7ffae80 <+48>: xor %r15d,%r15d
0x00007ffff7ffae83 <+51>: mov %ebx,%r11d
0x00007ffff7ffae86 <+54>: test $0x1,%r8b ; if (gtod->seq &1)
0x00007ffff7ffae8a <+58>: jne 0x7ffff7ffb0ed <gettimeofday+669> ; gtod->seq & 1 : cpu_relax and repeat
0x00007ffff7ffae90 <+64>: mov -0x2def(%rip),%rax # 0x7ffff7ff80a8 ; gtod->wall_time_sec
0x00007ffff7ffae97 <+71>: mov -0x2e1a(%rip),%r9d # 0x7ffff7ff8084 ; gtod->vclock_mode
0x00007ffff7ffae9e <+78>: mov %rax,(%rdi) ; ts->tv_sec
0x00007ffff7ffaea1 <+81>: mov -0x2e23(%rip),%edx # 0x7ffff7ff8084 ; gtod->vclock_mode
0x00007ffff7ffaea7 <+87>: mov -0x2e0e(%rip),%r14 # 0x7ffff7ff80a0 ; gtod->wall_time_snsec
0x00007ffff7ffaeae <+94>: cmp $0x1,%edx ; 1 = VCLOCK_TSC
0x00007ffff7ffaeb1 <+97>: je 0x7ffff7ffb090 <gettimeofday+576>
0x00007ffff7ffaeb7 <+103>: cmp $0x2,%edx ; 2 = VCLOCK_HPET
0x00007ffff7ffaeba <+106>: je 0x7ffff7ffb070 <gettimeofday+544>
0x00007ffff7ffaec0 <+112>: xor %eax,%eax
0x00007ffff7ffaec2 <+114>: cmp $0x3,%edx ; 3 = VCLOCK_PVCLOCK
0x00007ffff7ffaec5 <+117>: mov -0x2ebc(%rip),%r13d # 0x7ffff7ff8010
0x00007ffff7ffaecc <+124>: je 0x7ffff7ffaf63 <gettimeofday+275>
0x00007ffff7ffaed2 <+130>: mov -0x2e3c(%rip),%ecx # 0x7ffff7ff809c ; gtod->shift
0x00007ffff7ffaed8 <+136>: mov -0x2e5e(%rip),%edx # 0x7ffff7ff8080 ; gtod->seq
0x00007ffff7ffaede <+142>: cmp %r8d,%edx ; start
0x00007ffff7ffaee1 <+145>: jne 0x7ffff7ffb0cd <gettimeofday+637> ; jne if retry
0x00007ffff7ffaee7 <+151>: lea (%r14,%rax,1),%r8
0x00007ffff7ffaeeb <+155>: shr %cl,%r8
0x00007ffff7ffaeee <+158>: mov (%rdi),%rcx
;__iter_div_u64_rem(ns, NSEC_PER_SEC, &ns);
0x00007ffff7ffaef1 <+161>: cmp $0x3b9ac9ff,%r8 ; 999 999 999
0x00007ffff7ffaef8 <+168>: jbe 0x7ffff7ffb0b5 <gettimeofday+613>
0x00007ffff7ffaefe <+174>: xor %edx,%edx
0x00007ffff7ffaf00 <+176>: sub $0x3b9aca00,%r8 ; 1 000 000 000
0x00007ffff7ffaf07 <+183>: add $0x1,%edx
0x00007ffff7ffaf0a <+186>: cmp $0x3b9ac9ff,%r8 ; 999 999 999
0x00007ffff7ffaf11 <+193>: ja 0x7ffff7ffaf00 <gettimeofday+176>
0x00007ffff7ffaf13 <+195>: add %rcx,%rdx
0x00007ffff7ffaf16 <+198>: test %r9d,%r9d
0x00007ffff7ffaf19 <+201>: mov %r8,0x8(%rdi) ; ts->tv_nsec = ns
0x00007ffff7ffaf1d <+205>: mov %rdx,(%rdi) ; ts->tv_sec = sec
0x00007ffff7ffaf20 <+208>: je 0x7ffff7ffb0fb <gettimeofday+683> ; vdso_fallback_gtod if mode == VCLOCK_NONE ? (never true)
0x00007ffff7ffaf26 <+214>: mov %r8,%rax ; tv->tv_usec /= 1000;
0x00007ffff7ffaf29 <+217>: movabs $0x20c49ba5e353f7cf,%rdx
0x00007ffff7ffaf33 <+227>: sar $0x3f,%r8
0x00007ffff7ffaf37 <+231>: imul %rdx
0x00007ffff7ffaf3a <+234>: sar $0x7,%rdx
0x00007ffff7ffaf3e <+238>: sub %r8,%rdx
0x00007ffff7ffaf41 <+241>: mov %rdx,0x8(%rdi)
0x00007ffff7ffaf45 <+245>: test %rsi,%rsi
0x00007ffff7ffaf48 <+248>: jne 0x7ffff7ffb0d5 <gettimeofday+645>
0x00007ffff7ffaf4e <+254>: xor %eax,%eax
0x00007ffff7ffaf50 <+256>: add $0x18,%rsp
0x00007ffff7ffaf54 <+260>: pop %rbx
0x00007ffff7ffaf55 <+261>: pop %r12
0x00007ffff7ffaf57 <+263>: pop %r13
0x00007ffff7ffaf59 <+265>: pop %r14
0x00007ffff7ffaf5b <+267>: pop %r15
0x00007ffff7ffaf5d <+269>: pop %rbp
0x00007ffff7ffaf5e <+270>: retq
; vread_pvclock ()
0x00007ffff7ffaf5f <+271>: mov -0x40(%rbp),%r13d
0x00007ffff7ffaf63 <+275>: cmp $0x1,%r13d
0x00007ffff7ffaf67 <+279>: mov %ebx,%ecx
0x00007ffff7ffaf69 <+281>: je 0x7ffff7ffb084 <gettimeofday+564>
0x00007ffff7ffaf6f <+287>: mov %ecx,%eax
0x00007ffff7ffaf71 <+289>: and $0xfff,%eax
0x00007ffff7ffaf76 <+294>: mov %eax,%edx
0x00007ffff7ffaf78 <+296>: mov %ecx,%eax
0x00007ffff7ffaf7a <+298>: mov %edx,-0x2c(%rbp)
0x00007ffff7ffaf7d <+301>: shr $0x6,%rdx
0x00007ffff7ffaf81 <+305>: and $0x3f,%eax
0x00007ffff7ffaf84 <+308>: add $0x200,%edx
0x00007ffff7ffaf8a <+314>: cmp $0x20f,%edx
0x00007ffff7ffaf90 <+320>: jg 0x7ffff7ffb107 <gettimeofday+695>
0x00007ffff7ffaf96 <+326>: shl $0xc,%edx
0x00007ffff7ffaf99 <+329>: mov %r12,%r10
0x00007ffff7ffaf9c <+332>: cltq
0x00007ffff7ffaf9e <+334>: movslq %edx,%rdx
0x00007ffff7ffafa1 <+337>: shl $0x6,%rax
0x00007ffff7ffafa5 <+341>: sub %rdx,%r10
0x00007ffff7ffafa8 <+344>: add %rax,%r10
0x00007ffff7ffafab <+347>: mov (%r10),%eax
0x00007ffff7ffafae <+350>: mov %eax,-0x30(%rbp)
0x00007ffff7ffafb1 <+353>: data32 xchg %ax,%ax
0x00007ffff7ffafb4 <+356>: lfence
0x00007ffff7ffafb7 <+359>: rdtsc
0x00007ffff7ffafb9 <+361>: shl $0x20,%rdx
0x00007ffff7ffafbd <+365>: mov %eax,%eax
0x00007ffff7ffafbf <+367>: movsbl 0x1c(%r10),%ecx
0x00007ffff7ffafc4 <+372>: or %rax,%rdx
0x00007ffff7ffafc7 <+375>: sub 0x8(%r10),%rdx
0x00007ffff7ffafcb <+379>: mov 0x18(%r10),%eax
0x00007ffff7ffafcf <+383>: mov %rdx,%r13
0x00007ffff7ffafd2 <+386>: shl %cl,%r13
0x00007ffff7ffafd5 <+389>: test %ecx,%ecx
0x00007ffff7ffafd7 <+391>: js 0x7ffff7ffb0bc <gettimeofday+620>
0x00007ffff7ffafdd <+397>: mov %eax,%edx
0x00007ffff7ffafdf <+399>: mov %r13,%rax
0x00007ffff7ffafe2 <+402>: mul %rdx
0x00007ffff7ffafe5 <+405>: shrd $0x20,%rdx,%rax
0x00007ffff7ffafea <+410>: mov %rax,%r13
0x00007ffff7ffafed <+413>: mov 0x10(%r10),%rax
0x00007ffff7ffaff1 <+417>: mov %rax,-0x38(%rbp)
0x00007ffff7ffaff5 <+421>: movzbl 0x1d(%r10),%eax
0x00007ffff7ffaffa <+426>: mov %al,-0x39(%rbp)
0x00007ffff7ffaffd <+429>: data32 xchg %ax,%ax
0x00007ffff7ffb000 <+432>: lfence
0x00007ffff7ffb003 <+435>: mov -0x2ff9(%rip),%eax # 0x7ffff7ff8010
0x00007ffff7ffb009 <+441>: mov %r11d,%ecx
0x00007ffff7ffb00c <+444>: cmp $0x1,%eax
0x00007ffff7ffb00f <+447>: mov %eax,-0x40(%rbp)
0x00007ffff7ffb012 <+450>: je 0x7ffff7ffb07f <gettimeofday+559>
0x00007ffff7ffb014 <+452>: and $0xfff,%ecx
0x00007ffff7ffb01a <+458>: cmp %ecx,-0x2c(%rbp)
0x00007ffff7ffb01d <+461>: jne 0x7ffff7ffaf5f <gettimeofday+271>
0x00007ffff7ffb023 <+467>: mov (%r10),%eax
0x00007ffff7ffb026 <+470>: test $0x1,%al
0x00007ffff7ffb028 <+472>: jne 0x7ffff7ffaf5f <gettimeofday+271>
0x00007ffff7ffb02e <+478>: cmp %eax,-0x30(%rbp)
0x00007ffff7ffb031 <+481>: jne 0x7ffff7ffaf5f <gettimeofday+271>
0x00007ffff7ffb037 <+487>: testb $0x1,-0x39(%rbp)
0x00007ffff7ffb03b <+491>: mov -0x38(%rbp),%rax
0x00007ffff7ffb03f <+495>: mov -0x2fbe(%rip),%rdx # 0x7ffff7ff8088
0x00007ffff7ffb046 <+502>: cmove %r15d,%r9d
0x00007ffff7ffb04a <+506>: add %r13,%rax
0x00007ffff7ffb04d <+509>: cmp %rdx,%rax
0x00007ffff7ffb050 <+512>: cmovb %rdx,%rax
0x00007ffff7ffb054 <+516>: sub %rdx,%rax
0x00007ffff7ffb057 <+519>: and -0x2fce(%rip),%rax # 0x7ffff7ff8090 ; gtod->mask
0x00007ffff7ffb05e <+526>: mov -0x2fcc(%rip),%edx # 0x7ffff7ff8098 ; gtod->mult
0x00007ffff7ffb064 <+532>: imul %rdx,%rax
; v = (cycles - gtod->cycle_last) & gtod->mask;
; return v * gtod->mult;
0x00007ffff7ffb068 <+536>: jmpq 0x7ffff7ffaed2 <gettimeofday+130>
0x00007ffff7ffb06d <+541>: nopl (%rax)
; mode = VCLOCK_PVCLOCK
0x00007ffff7ffb070 <+544>: mov -0x1f86(%rip),%eax # 0x7ffff7ff90f0 ; HPET_COUNTER
0x00007ffff7ffb076 <+550>: sub -0x2ff5(%rip),%rax # 0x7ffff7ff8088 ; gtod->cycle_last
0x00007ffff7ffb07d <+557>: jmp 0x7ffff7ffb057 <gettimeofday+519>
0x00007ffff7ffb07f <+559>: rdtscp
0x00007ffff7ffb082 <+562>: jmp 0x7ffff7ffb014 <gettimeofday+452>
0x00007ffff7ffb084 <+564>: rdtscp
0x00007ffff7ffb087 <+567>: jmpq 0x7ffff7ffaf6f <gettimeofday+287>
0x00007ffff7ffb08c <+572>: nopl 0x0(%rax)
0x00007ffff7ffb090 <+576>: data32 xchg %ax,%ax ; vread_tsc()
0x00007ffff7ffb093 <+579>: lfence ; rdtsc_barrier()
0x00007ffff7ffb096 <+582>: rdtsc ; __native_read_tsc()
0x00007ffff7ffb098 <+584>: shl $0x20,%rdx
0x00007ffff7ffb09c <+588>: mov %eax,%eax
0x00007ffff7ffb09e <+590>: or %rax,%rdx
0x00007ffff7ffb0a1 <+593>: mov -0x3020(%rip),%rax # 0x7ffff7ff8088 ; gtod->cycle_last
0x00007ffff7ffb0a8 <+600>: cmp %rax,%rdx
0x00007ffff7ffb0ab <+603>: jb 0x7ffff7ffb0c9 <gettimeofday+633>
0x00007ffff7ffb0ad <+605>: sub %rax,%rdx
0x00007ffff7ffb0b0 <+608>: mov %rdx,%rax
0x00007ffff7ffb0b3 <+611>: jmp 0x7ffff7ffb057 <gettimeofday+519>
0x00007ffff7ffb0b5 <+613>: xor %edx,%edx
0x00007ffff7ffb0b7 <+615>: jmpq 0x7ffff7ffaf13 <gettimeofday+195>
0x00007ffff7ffb0bc <+620>: neg %ecx
0x00007ffff7ffb0be <+622>: shr %cl,%rdx
0x00007ffff7ffb0c1 <+625>: mov %rdx,%r13
0x00007ffff7ffb0c4 <+628>: jmpq 0x7ffff7ffafdd <gettimeofday+397>
0x00007ffff7ffb0c9 <+633>: xor %eax,%eax
0x00007ffff7ffb0cb <+635>: jmp 0x7ffff7ffb057 <gettimeofday+519>
0x00007ffff7ffb0cd <+637>: mov %edx,%r8d ; r8d = gtod->seq
0x00007ffff7ffb0d0 <+640>: jmpq 0x7ffff7ffae86 <gettimeofday+54> ; retry
0x00007ffff7ffb0d5 <+645>: mov -0x2ffb(%rip),%eax # 0x7ffff7ff80e0
0x00007ffff7ffb0db <+651>: mov %eax,(%rsi)
0x00007ffff7ffb0dd <+653>: mov -0x2fff(%rip),%eax # 0x7ffff7ff80e4
0x00007ffff7ffb0e3 <+659>: mov %eax,0x4(%rsi)
0x00007ffff7ffb0e6 <+662>: xor %eax,%eax
0x00007ffff7ffb0e8 <+664>: jmpq 0x7ffff7ffaf50 <gettimeofday+256>
0x00007ffff7ffb0ed <+669>: pause
0x00007ffff7ffb0ef <+671>: mov -0x3076(%rip),%r8d # 0x7ffff7ff8080 ; gtod->seq
0x00007ffff7ffb0f6 <+678>: jmpq 0x7ffff7ffae86 <gettimeofday+54>
0x00007ffff7ffb0fb <+683>: mov $0x60,%eax // fallback
0x00007ffff7ffb100 <+688>: syscall
0x00007ffff7ffb102 <+690>: jmpq 0x7ffff7ffaf50 <gettimeofday+256>
0x00007ffff7ffb107 <+695>: ud2アセンブラダンプはここまで。
vDSOは毎回新しいアドレスにマップされます（恐らくは何らかのセキュリティ機能）。しかし、 gdb の下で実行した場合、この関数はいつでも上記と同じアドレス（ 0x00007ffff7ffae50 ）に配置されます（なぜこうなるのかは不明）。この関数は関数自身のコードからあまり遠くないアドレスのメモリ（例えば 0x7ffff7ff8080 や 0x7ffff7ff90f0 など）にアクセスしますが、この時常に「IPに相対的な」アドレッシングモードを使います。このことによってこの関数は完全に再配置可能になるのです。ユーザ空間のどのアドレスにでも、全データとともにマップ可能だからです。
この関数はまた様々なオプションを採用しています。 syscall を生成することも、 rdtsc 命令を実行することも、（Windowsの実装に似た方法で）ただメモリを読み込むことも可能です。私たちのケースには、このうちどのオプションが当てはまるでしょう？
私たちのLinuxカーネル（3.1.7.4）のソースコード を見てみましょう。これは最新のものではないということに留意してください（Linuxのディストリビュータは非常に保守的な人々なのです）。最新のコードは（定数定義も含めて）かなり違います。これが（ arch/x86/vdso/vclock_gettime.c の中にある）そのコードです。
notrace int __vdso_gettimeofday(struct timeval *tv, struct timezone *tz)
{
if (likely(tv != NULL)) {
if (unlikely(do_realtime((struct timespec *)tv) == VCLOCK_NONE))
return vdso_fallback_gtod(tv, tz);
tv->tv_usec /= 1000;
}
if (unlikely(tz != NULL)) {
tz->tz_minuteswest = gtod->tz_minuteswest;
tz->tz_dsttime = gtod->tz_dsttime;
}
return 0;
}残りのコードはここにあります（ gtod は明らかに gettimeofday の略ですね）。 arch/x86/include/asm/vgtod.h の内部は以下の通り。
struct vsyscall_gtod_data {
unsigned seq;
int vclock_mode;
cycle_t cycle_last;
cycle_t mask;
u32 mult;
u32 shift;
/* open coded 'struct timespec' */
u64 wall_time_snsec;
gtod_long_t wall_time_sec;
gtod_long_t monotonic_time_sec;
u64 monotonic_time_snsec;
gtod_long_t wall_time_coarse_sec;
gtod_long_t wall_time_coarse_nsec;
gtod_long_t monotonic_time_coarse_sec;
gtod_long_t monotonic_time_coarse_nsec;
int tz_minuteswest;
int tz_dsttime;
};
static inline unsigned gtod_read_begin(const struct vsyscall_gtod_data *s)
{
unsigned ret;
repeat:
ret = ACCESS_ONCE(s->seq);
if (unlikely(ret & 1)) {
cpu_relax();
goto repeat;
}
smp_rmb();
return ret;
}
static inline int gtod_read_retry(const struct vsyscall_gtod_data *s,
unsigned start)
{
smp_rmb();
return unlikely(s->seq != start);
}arch/x86/include/asm/vvar.h で以下のようなマクロが定義された上で
#define VVAR(name) (vvar_ ## name)また arch/x86/vdso/vclock_gettime.c に戻って見てみると：
#define gtod (&VVAR(vsyscall_gtod_data))
notrace static int __always_inline do_realtime(struct timespec *ts)
{
unsigned long seq;
u64 ns;
int mode;
do {
seq = gtod_read_begin(gtod);
mode = gtod->vclock_mode;
ts->tv_sec = gtod->wall_time_sec;
ns = gtod->wall_time_snsec;
ns += vgetsns(&mode);
ns >>= gtod->shift;
} while (unlikely(gtod_read_retry(gtod, seq)));
ts->tv_sec += __iter_div_u64_rem(ns, NSEC_PER_SEC, &ns);
ts->tv_nsec = ns;
return mode;
}ここで起きていることはWindowsで起きたことと非常によく似ています。vDSOを伴ったデータ構造体があり、各プロセスのアドレス空間にマップされています。これは vvar_vsyscall_gtod_data と呼ばれ、擬似変数 gtod を経由してコードにアドレス指定されます。上記のアセンブリのリストでは、この構造体はアドレス 0x7ffff7ff8080 にあります。
バックグラウンドのスレッドが一定の間隔でこの構造体のフィールドを更新します。フィールドは3つ以上あるので、数値の上位を2回書き込むというWindowsのトリックは使えませんが、似たようなトリックが使えます。書き込み側がこの構造体のデータのバージョン番号を保持するのです（ seq フィールド）。書き込み側が構造体を更新し始めたら、数は1つインクリメントされ、終了した時も1つインクリメントされます（適切な書き込みバリア命令が使われた場合）。結果として、奇数の値であればデータが一致しないということになります。読み込み側は数値を読み込み、偶数であることを確認し（違う場合には pause 命令を使って少し待つ）、構造体から着目したい全ての値を読み込み、もう一度バージョン番号を読み込み、最初と同じであればデータは正しいと考えられます。これが、 gtod_read_begin 関数と gtod_read_retry 関数の機能です。
読み込みバリア命令は、プロセッサが実際のデータの読み込みとともにバージョン番号の読み込みをリオーダーしていないことを確認するために使われなくてはなりません。しかし、Intel x86の強力なメモリオーダリングによってこれは不要になっていますので、読み込みバリア呼び出し（ smp_rnb() ）は私たちのケースでは空になっています。
今回着目する値は wall_time_sec と wall_time_snsec です。前者は昔ながらの time() 呼び出しが返すような、エポックからの正確な秒数です。実際のところ、 time() はまさにこの値をロックやバージョン管理なしで読み込むことによって実装されています。
notrace time_t __vdso_time(time_t *t)
{
/* This is atomic on x86 so we don't need any locks. */
time_t result = ACCESS_ONCE(gtod->wall_time_sec);
if (t)
*t = result;
return result;
}後者の値は、直前の秒から経過したナノ秒時間であり、 gtod->shift で左シフトされています。正確に言えば、何らかの単位で計測されたこの時間を、 gtod->shift によって右シフトするとナノ秒時間になります。今回のケースでは25右シフトします。これは非常に高精度です。1ナノ秒を2 ²⁵ で割ると約30アト秒です。ひょっとすると、Linuxカーネルの設計者ははるか先を見越していて、いつか時間計測でそのような精度が必要になると予想したのかもしれません。
これらの時間値の真の解像度はどうなのでしょうか。ループで値を読み取り、その変化を出力してみましょう。
プログラムを gdb で実行する必要がなければ、まず vDSO の再配置を解決しなくてはなりませんが、それは容易です。
const struct vsyscall_gtod_data * gtod = 0;
void resolve (void)
{
unsigned char * p;
struct timeval time;
gettimeofday (&time, 0);
p = (char *) gettimeofday;
if (p[0] != 0xFF || p[1] != 0x25) {
exit (1);
}
p += 6 + *(int32_t*) (p+2);
p = * (unsigned char **) p;
p -= (unsigned) (intptr_t) p & 0xFFF;
p -= 0x2000;
p += 0x80;
gtod = (const struct vsyscall_gtod_data *) p;
}これで、ループを実行すると wall_time_snsec の変化を検出できます。
void test (void)
{
int i;
uint64_t oldns = 0;
for (i = 0; i < 10000000; i++) {
uint64_t ns = gtod->wall_time_snsec;
if (ns != oldns) {
printf ("%d: sec=%lu ns=%lu diff=%ld ns_shift=%lu diff_shift=%ld\n",
i, gtod->wall_time_sec, ns, ns - oldns, ns >> gtod->shift,
(ns >> gtod->shift) - (oldns >> gtod->shift));
}
oldns = ns;
}
}出力の一部を取り出すと、以下のようになります。
3721507: sec=1499630953 ns=16894552383987602 diff=33554102663246 ns_shift=503496896 diff_shift=999990
4367859: sec=1499630953 ns=16928106486650848 diff=33554102663246 ns_shift=504496886 diff_shift=999990
5014216: sec=1499630953 ns=16961660589326449 diff=33554102675601 ns_shift=505496877 diff_shift=999991wall_time_nsec の値の更新頻度がかなり低いことがわかります。約65万回の繰り返しの間、値は変化せず、そのあと大きく変化しています。 shift でシフトされて999990ナノ秒となっていますので、ほぼ1ミリ秒です。 wall_time_sec が変化する時にも興味深いことが起こります。
249316536: sec=1499631433 ns=33542778622228903 diff=33554096688437 ns_shift=999652702 diff_shift=999990
250511726: sec=1499631434 ns=21900718852443 diff=-33520877903376460 ns_shift=652692 diff_shift=-999000010新しいナノ秒値はゼロから始まっていません。開始値は652692、つまり0.5ミリ秒以上ですが、いつもこれほど大きな値になるわけではありません。200000や300000といった値となることも見たことがあります。要するに、 gtod 構造体で利用できる2つの変数は、解像度が1ミリ秒というかなり粗い時間値に対して非常に高速なアクセスを提供するのです。Windowsの場合と同様の速さです。
しかし、 gettimeofday() はまだ続きがあります。他の方法で精度を上げようとするのです。上記のコードにおいて vgetsns() 関数が担当する部分です。
notrace static inline u64 vgetsns(int *mode)
{
u64 v;
cycles_t cycles;
if (gtod->vclock_mode == VCLOCK_TSC)
cycles = vread_tsc();
#ifdef CONFIG_HPET_TIMER
else if (gtod->vclock_mode == VCLOCK_HPET)
cycles = vread_hpet();
#endif
#ifdef CONFIG_PARAVIRT_CLOCK
else if (gtod->vclock_mode == VCLOCK_PVCLOCK)
cycles = vread_pvclock(mode);
#endif
else
return 0;
v = (cycles - gtod->cycle_last) & gtod->mask;
return v * gtod->mult;
}システムのどこかに高精度タイマーがあり、現在のティック数を問い合わせることができるという考え方です。低精度タイマーの直前のティックで高精度タイマーの値を記録して（ gtod->cycle_last ）、差を取得するのです。 gtod->mask フィールドと gtod->mult フィールドは、そのタイマーの値を30アト秒単位に変換するのを助けます。30アト秒単位が選ばれた理由は、これでわかりました。Linuxの設計者が微小なプロセスの時間を計測したかったわけではなく、この変換中の誤差を減らすために非常に小さな単位が選ばれたのです。
上記のコードは3タイプの高精度タイマーに備えています。 TSC （Intel x86命令セットの RDTSC 命令がベース）、 HPET （外部ハードウェア、HPETチップがベース）、 PVCLOCK （恐らくVM環境での実行と関連）です。
いずれにしても、コードが高精度タイマーを利用するのは、低精度時間とのオフセットを取得するためだけです。タイマーは非常に安定した状態で何年も稼働する必要はありません。低精度タイマーのティック間のオフセットを提供できるだけの安定性があれば十分なのです。更に、その差異がシステムに認識されて mask フィールドと mult フィールドの適切な更新に反映される限り、クロック周波数は可変です。システムは非常に正確な時間を非常に高速に提供するよう、うまく設計されています。では、何が問題だったのでしょうか。
今回のケースでは、 vclock_mode フィールドは2にセットされます。これは、HPET（ 高精度イベントタイマー ）を使うという意味です。このタイマーは、全ての最新式PCに搭載されているハードウェア要素で、かつての8253/8254チップを置き換えるものです。8253/8254チップが実行するカウンタは、ゼロになると割り込みを発生させることができ、 IN 命令を使って直接読み取ることもできました。周波数は1.19318MHzでした。65536クロックごとに失効(expire)するようプログラムされていた場合は、55ミリ秒ごと（18.2Hz）に割り込みを発生させました。これはMS-DOS時代から知られていることです。
HPETはより高い周波数で稼働します。カウントダウンではなくカウントアップし、I/OポートではなくメモリマップされたI/Oを介して利用できます。カウンタを読み取るルーチンは以下のようになっています。
static notrace cycle_t vread_hpet(void)
{
return *(const volatile u32 *)(&hpet_page + HPET_COUNTER);
}これは、ただ1つの32ビットメモリ読み取り命令にコンパイルされます。
0x00007ffff7ffb070 <+544>: mov -0x1f86(%rip),%eax # 0x7ffff7ff90f0HPETタイムソースの場合、 gettimeofday 全体が、一連のメモリ読み取りとシフトと乗算にコンパイルされます。除算などのコストの高い演算はありません。ではなぜ、実行速度がそんなに遅いのでしょうか。
私はテストマシン上で利用できるサンプリングプロファイラを持っていませんでしたが、手軽な方法はあります。ループ内で gettimeofday を実行する稼働中プログラムに gdb をアタッチして、それに割り込みを発生させるのです。私が試したケースでは全て、必ず同じ1カ所で停止しました。前述の命令（ gettimeofdat+550 の部分）のあとです。このことから、その命令だけで実行時間の大部分を占めていることがわかります。これを確認するのは簡単です。 vsyscall_gtod_data の時と似た方法で hpet_page を解決して、ループでこの変数を読み取りましょう。
Time for 1000000: 0.564707 s; ns/iter=564.707000HPETタイマーからデータを読み取るのに0.5マイクロ秒以上かかっており、非常に遅いタイムソースとなっています。このタイマーから読み取る値を出力すれば、 gtod->wall_time_snsec の場合と違って、タイマーにアクセスする度に値が変化することがわかるでしょう。典型的な差は8ですが、これは読み取り中にタイマーが8回ティックするという意味です。タイマーの精度が、パフォーマンスよりはるかに高いのです。粗いナノ秒単位の変化（すでに見たようにミリ秒ごとに発生）の際に計測されたタイマー値間の差は14320なので、HPETの周波数は14.32MHz（1ティック当たり70ナノ秒）となります。
これは大変悲しい状況です。タイマーは高い周波数で稼働しているのに、その周波数で読み取る手段がないのです。約1.8MHzで読み取れるというのは、MS-DOSタイマーの周波数よりわずかに高いにすぎません。
そして最も問題なのは、今回のユースケースにおいて私たちは実のところ、それほどの高精度には関心がないということです。私たちに必要なのは currentTimeMillis() であり、低精度タイマーはそれにうってつけなのです。
低精度タイマー
簡単な方法があります。ユーザAPIを介して利用できる低精度タイマー、 clock_gettime() 関数です。
int clock_gettime(clockid_t clk_id, struct timespec *tp);clk_id について <time.h> で定義されている複数の値のうち、私たちがまさに必要とする CLOCK_REALTIME_COARSE （値は5）があります。この関数のコードは同じvDSO（ vclock_gettime.c ）内にあります。
notrace static void do_realtime_coarse(struct timespec *ts)
{
unsigned long seq;
do {
seq = gtod_read_begin(gtod);
ts->tv_sec = gtod->wall_time_coarse_sec;
ts->tv_nsec = gtod->wall_time_coarse_nsec;
} while (unlikely(gtod_read_retry(gtod, seq)));
}この関数から返されるナノ秒時間は999991ナノ秒（1ミリ秒）間隔で、実行には8.4ナノ秒かかります。
TSCタイムソース
currentTimeMillis() の実行速度が遅いのは、以下の2点が要因となっていることがわかりました。
- JVM は
clock_gettime()ではなくgettimeofday()を使っている。 gettimeofday()は、HPETタイムソースが使われる場合は非常に遅い。
しかし近頃では、HPETが唯一のタイムソースというわけではありません。ひょっとすると、最もポピュラーでさえないかもしれません。TSCを使っているシステムが少なくないのです。そう考えると、この検討全体が的外れなのかもしれません。ですが、今回のプロジェクトでは、ある理由からサーバの設定はHPETタイムソースとなっています。HPETタイムソースはNTPクライアントとうまく連携するので時間調整をスムーズに行えますが、一方のTSCはそれほど安定性がなかったのです（詳細は把握していません。これは地元のLinuxの権威たちが言っていることで、彼らを信じるしかありません）。他の開発者も同じ状況を経験するかもしれませんし、更にJava開発者は、プログラムが稼働するマシン上でどのタイムソースが設定されるかを必ずしも知ることができません。そういう訳で、ここまでで得られた結果はやはり重要だと考えています。
とはいえ、TSCタイムソースを使ったら結果がどう変わるかを明らかにするのも、やはり面白そうです。TSCは「タイムスタンプカウンタ」の意味で、これは単純に、起動時からカウントされたCPUサイクル数を表します（64ビット幅しかないので、2.4GHzのクロックレートなら243年でラップアラウンドします）。この値は rdtsc 命令で読み取ることができます。従来、この値に関しては2つの問題がありました。
- 起動時間はプロセッサによって異なる場合があるので、異なるコアや物理プロセッサから取得された値同士は食い違う可能性がある。
- プロセッサのクロック周波数は、実行中に変化する可能性がある。
1つ目は実際、問題だと思われます。試しに、いくつかのコアから同時に rdtsc の値を取得し、あるメモリ位置への同期書き込みを行ってみましたが、最もうまくいったケースでさえ数千サイクルの違いがあり、もっと大きく違う場合もありました。しかしこれは、プログラマがTSCを手動で使いたい場合の問題にすぎません。そのケースでは、スレッドアフィニティが状況に応じてセットされなければなりません。OSはあるコアから別のコアへとスレッドをスケジュールし直すタイミングを把握していますので、必要な調整は全てOSが行えるのです。
2つ目の問題は過去のものとなったように思われます。Intelのドキュメントでは以下のように書かれています。
プロセッサファミリーによって、タイムスタンプカウンタのインクリメント法が異なります。
* Pentium Mプロセッサ（ファミリー［06H］、モデル［09H、0DH］）、Pentium 4プロセッサ、Intel Xeonプロセッサ（ファミリー［0FH］、モデル［00H、01H、02H］）、P6ファミリープロセッサ：タイムスタンプカウンタは、内部プロセッサのクロックサイクルごとにインクリメントされます。内部プロセッサのクロックサイクルは、その時のコアクロック対バスクロックの比率によって決まります。Intel® SpeedStep®テクノロジの切り替えもプロセッサクロックに影響を与える場合があります。
* Pentium 4プロセッサ、Intel Xeonプロセッサ（ファミリー［0FH］、モデル［03H以上］）、Intel Core SoloおよびIntel Core Duoプロセッサ（ファミリー［06H］、モデル［0EH］）、Intel Xeonプロセッサ5100シリーズおよびIntel Core 2 Duoプロセッサ（ファミリー［06H］、モデル［0FH］）、Intel Core 2およびIntel Xeonプロセッサ（ファミリー［06H］、DisplayModel［17H］）、Intel Atomプロセッサ（ファミリー［06H］、DisplayModel［1CH］）：タイムスタンプカウンタは一定速度でインクリメントされます。
また、以下のようにも書かれています。
不変TSCに対するプロセッサのサポートは、CPUID.80000007H:EDX[8]で示されます。
これは以下でテストできます。
uint32_t __attribute__ ((noinline)) cpuid (void)
{
asm (
"mov $0x80000007, %eax\n"
"cpuid\n"
"mov %edx, %eax\n"
);
}
void test (void)
{
printf ("%X\n", cpuid ());
}出力を見ると、
100これは該当ビットがセットされているという意味です。
確認のため、もう1つテストしてみます。
void __attribute__ ((noinline)) rdtsc (uint64_t * p)
{
asm (
"lfence\n"
"rdtsc\n"
"mov %eax,(%rdi)\n"
"mov %edx, 4(%rdi)\n"
);
}
uint64_t micros (void)
{
struct timeval time;
gettimeofday (&time, 0);
return time.tv_sec * 1000000 + time.tv_usec;
}
void delay (void)
{
int i;
double s = 0;
for (i = 1; i < 1000000000; i++) s += 1.0 / i;
printf ("%f\n", s);
}
void test (void)
{
uint64_t t0, t1;
uint64_t c0, c1;
t0 = micros ();
rdtsc (&c0);
sleep (10);
// delay ();
t1 = micros ();
rdtsc (&c1);
printf ("time: %d; clocks/nano: %f\n", (t1 - t0), (c1 - c0) / 1000.0 / (t1 - t0));
}ターボブーストを有効にして、既知のプロセッサで実行してみましょう。
# taskset 1 ./t
time: 10000102; clocls/nano: 2.399990実行中、プロセッサ0のクロックレートをチェックします。
# cat /proc/cpuinfo | grep MHz |head -n 1
cpu MHz : 1337.156今度は sleep をコメントアウトし、 delay のコメント扱いを解除して、繰り返してみます。
# taskset 1 ./t
time: 8478796; clocls/nano: 2.399991クロックレートは以下の通りです。
# cat /proc/cpuinfo | grep MHz |head -n 1
cpu MHz : 3199.968rdtsc のレートは同一で、プロセッサの公称クロックレートと一致します。これはどちらのケースも、対応するコアの実際のクロックレートとは異なっていました。
つまり、TSCはこれらのプロセッサで安心して使えるということです。これを実行する方法の1つは、前述の関数 clock_gettime を使うことです。これには、TSCに対応するクロックID、 CLOCK_PROCESS_CPUTIME_ID があります。
ですが、クロックレートはあまり良くありません。1呼び出し当たり343ナノ秒です。
より良い方法があります。 gettimeofday は引き続き使いますが、TSCをシステム全体の望ましいタイムソースとしてセットするのです。これは非常に簡単です。
echo tsc > /sys/devices/system/clocksource/clocksource0/current_clocksourceHPETに戻す方法も同様に、「tsc」ではなく「hpet」とします。
なお、この設定は一時的なものです（再起動後は無効）。今回のJavaプログラムに戻り、反復回数を再び2桁上げましょう。素晴らしい結果となりました。
# java Time
Sum = 2414988828092895332; time = 3636; or 36.36 ns / iter
Sum = 2414989192017338494; time = 3628; or 36.28 ns / iter
Sum = 2414989551179770420; time = 3604; or 36.04 ns / iterWindowsでの結果（4ナノ秒未満）には劣りますが、それでも以前よりはずっと良くなっています。恐らく、冒頭で挙げたユースケースに実際使えるでしょう。
gettimeofday() の時間を計測すると、以下のようになりました。
time for 100000000: 3.000262 s; ns/iter=30.002621gettimeofday() は時間をマイクロ秒で返すので、解像度はおのずと1000ナノ秒が上限になりますが、それは実際に達成されています。この関数を何度も呼び出して連続する値と値の差を出力すると、多くはゼロでたまに1という結果が得られます。
clock_gettime (CLOCK_REALTIME) で同じテストを行うと、30ナノ秒が返されます。これは各呼び出しの実行時間と全く同じで、予想通りです。
まとめると、TSCタイムソースは非常に高速かつ非常に高精度ですが、2つの留意点があります。
- システムによっては、使わない方がいい場合もある。
clock_gettime(CLOCK_REALTIME_COARSE)の方が速い。
