Shogo's Blog

たぶんプログラミングとかについて書いていくブログ

Go1.9から使える Monotonic Clocks を試してみた

先日Go1.9beta1がリリースされました。

型エイリアスのサポート、math/bitsパッケージ、 sync.Map型など、 今回のアップデートでも便利そうな機能が追加されます。 詳しくはtenntennさんのGopher Fest 2017参加レポートをどうぞ。

今回のリリースノートを見て、個人的に注目しているのはMonotonic Clocksのサポートです。 他の機能追加はTwitterとかで見かけるけど、 Monotonic Clocksはなぜかあまり見ない・・・。 beta1がでて手軽に試せるようになったので、試してみました。

Monotonic Clocks

Go1.8以前で取得していた時刻は「wall clock」といい、現在の正しい時刻を知るために使います。 一方「monotonic clock」は、時間を計るために使うものです。 Go1.9からはtime.Nowで取得できる時刻に「wall clock」と「monotonic clock」が含まれるようになります。

timeパッケージのドキュメントから コード片を引用します。

1
2
3
4
t := time.Now()
... operation that takes 20 milliseconds ...
u := time.Now()
elapsed := t.Sub(u)

上のコードで elapsed は 20ms となるはずですが、 実際はそうはならないケースがあります。 具体的には以下のようなケースです。

  • ntpdなどによってOSの時刻が変更された場合
  • うるう秒が挿入・削除された場合

Go1.9からはこのようなケースでも正しく時間を計ることができます。

うるう秒を入れてみた

うるう秒が入ったときの挙動が気になったので実際にやってみました。 セットアップが簡単になるようNICTのPerl版SNTPのGolangポートを作ったので、 それを使って偽物のうるう秒を挿入してみます。

インストールはいつものようにgo getです。 -pオプションで正のうるう秒挿入、-nオプションで負のうるう秒削除です(ほんとうは月末だけだけど、雑な実装のため毎日その日の終わりに挿入・削除されます)。 引数にRFC3339形式で日時を指定すると、その日時を起動時の日時として扱います。

たとえば今月末に正のうるう秒を挿入するには以下のように指定します。

1
2
3
# 上位ntpd側
$ go get github.com/shogo82148/fakentpd
$ sudo fakentpd -p 2017-06-30T23:00:00Z # well known portを使うのでroot権限が必要

このSNTPサーバーを上位ntpdとして参照したクライアントを用意し、dateコマンドで様子を確認してみましょう。 (ntpdの設定などの詳細はtkuchikiさんのうるう秒検証記事 を参照)

1
2
# 下位ntpd側
$ while :; do date +'%Y-%m-%d %H:%M:%S.%3N'; usleep 100000; done
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
(前略)
2017-06-30 23:59:59.040
2017-06-30 23:59:59.141
2017-06-30 23:59:59.243
2017-06-30 23:59:59.344
2017-06-30 23:59:59.445
2017-06-30 23:59:59.547
2017-06-30 23:59:59.648
2017-06-30 23:59:59.749
2017-06-30 23:59:59.851
2017-06-30 23:59:59.952 #
2017-06-30 23:59:59.053 # うるう秒挿入!
2017-06-30 23:59:59.155
2017-06-30 23:59:59.256
2017-06-30 23:59:59.357
2017-06-30 23:59:59.458
2017-06-30 23:59:59.559
2017-06-30 23:59:59.661
2017-06-30 23:59:59.762
2017-06-30 23:59:59.863
2017-06-30 23:59:59.964
2017-07-01 00:00:00.066

うるう秒が挿入されたため、59.952から59.053へ時間が巻き戻っていることが確認できます。

これと同等のプログラムをGoで書いて挙動を確認します。 monotonic clockの確認をするために、一緒に起動時からの経過時間も表示するようにしました。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
package main

import (
  "fmt"
  "time"
)

func main() {
  start := time.Now()
  for {
      now := time.Now()
      fmt.Println(now, now.Sub(start))
      time.Sleep(100 * time.Millisecond)
  }
}

dateコマンドで検証したときと同様の条件で、 このプログラムをGo1.8で実行すると以下のような結果になりました。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
(前略)
2017-06-30 23:59:59.038281905 +0000 UTC 32m42.970735711s
2017-06-30 23:59:59.138469005 +0000 UTC 32m43.070922811s
2017-06-30 23:59:59.238662875 +0000 UTC 32m43.171116681s
2017-06-30 23:59:59.338835875 +0000 UTC 32m43.271289681s
2017-06-30 23:59:59.439025825 +0000 UTC 32m43.371479631s
2017-06-30 23:59:59.539213666 +0000 UTC 32m43.471667472s
2017-06-30 23:59:59.63940551 +0000 UTC 32m43.571859316s
2017-06-30 23:59:59.739603502 +0000 UTC 32m43.672057308s
2017-06-30 23:59:59.839783301 +0000 UTC 32m43.772237107s
2017-06-30 23:59:59.939980591 +0000 UTC 32m43.872434397s #
2017-06-30 23:59:59.043820722 +0000 UTC 32m42.976274528s # うるう秒挿入!
2017-06-30 23:59:59.143987505 +0000 UTC 32m43.076441311s
2017-06-30 23:59:59.244160716 +0000 UTC 32m43.176614522s
2017-06-30 23:59:59.344336707 +0000 UTC 32m43.276790513s
2017-06-30 23:59:59.444546067 +0000 UTC 32m43.376999873s
2017-06-30 23:59:59.544717014 +0000 UTC 32m43.47717082s
2017-06-30 23:59:59.644876123 +0000 UTC 32m43.577329929s
2017-06-30 23:59:59.745050732 +0000 UTC 32m43.677504538s
2017-06-30 23:59:59.845230425 +0000 UTC 32m43.777684231s
2017-06-30 23:59:59.945421532 +0000 UTC 32m43.877875338s
2017-07-01 00:00:00.045595155 +0000 UTC 32m43.978048961s

うるう秒が挿入されたため、59.9から59.0に時刻が巻き戻っていることが確認できます。 それと同時に経過時刻も32m43.87sから32m42.97sと巻き戻ってしまいました。

おなじプログラムをGo1.9で実行してみます。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
(前略)
2017-06-30 23:59:59.038322917 +0000 UTC m=+1962.019889237 32m42.01969158s
2017-06-30 23:59:59.138507805 +0000 UTC m=+1962.120074107 32m42.11987645s
2017-06-30 23:59:59.238704422 +0000 UTC m=+1962.220270727 32m42.22007307s
2017-06-30 23:59:59.338875317 +0000 UTC m=+1962.320441617 32m42.32024396s
2017-06-30 23:59:59.439066666 +0000 UTC m=+1962.420632996 32m42.420435339s
2017-06-30 23:59:59.539255964 +0000 UTC m=+1962.520822264 32m42.520624607s
2017-06-30 23:59:59.639446597 +0000 UTC m=+1962.621012897 32m42.62081524s
2017-06-30 23:59:59.739644525 +0000 UTC m=+1962.721210832 32m42.721013175s
2017-06-30 23:59:59.839827168 +0000 UTC m=+1962.821393501 32m42.821195844s
2017-06-30 23:59:59.94003045 +0000 UTC m=+1962.921596780 32m42.921399123s #
2017-06-30 23:59:59.043859649 +0000 UTC m=+1963.025425981 32m43.025228324s # うるう秒挿入!
2017-06-30 23:59:59.144008957 +0000 UTC m=+1963.125575282 32m43.125377625s
2017-06-30 23:59:59.244196844 +0000 UTC m=+1963.225763148 32m43.225565491s
2017-06-30 23:59:59.344388476 +0000 UTC m=+1963.325954758 32m43.325757101s
2017-06-30 23:59:59.444598162 +0000 UTC m=+1963.426164679 32m43.425967022s
2017-06-30 23:59:59.54473741 +0000 UTC m=+1963.526303708 32m43.526106051s
2017-06-30 23:59:59.644895019 +0000 UTC m=+1963.626461309 32m43.626263652s
2017-06-30 23:59:59.745084175 +0000 UTC m=+1963.726650464 32m43.726452807s
2017-06-30 23:59:59.845264185 +0000 UTC m=+1963.826830509 32m43.826632852s
2017-06-30 23:59:59.94546352 +0000 UTC m=+1963.927029829 32m43.926832172s
2017-07-01 00:00:00.04563023 +0000 UTC m=+1964.027196518 32m44.026998861s

うるう秒が挿入されるとwall clockは59.9から59.0に時刻が巻き戻っています。 しかし経過時刻は32m42.9から32m43.0と巻き戻りは発生していません。

Go1.9からt.String()がmonotonic clockの情報を返すようになるので、今回の検証ログにも表示されています。 monotonic clockも m=+1962.921596780 から m=+1963.025425981 と巻き戻りは発生していません。 (mの意味はよくわかってないけどプロセスの起動時間?)

時刻を変えてみた

検証用のfakentpdを止めて本物の上位ntpdを復活させると、 時刻の差が大きいため元の時刻に一気に修正されます。 この場合についても試してみました。

Go1.8で実行した場合。 時刻が戻ると同時に経過時間が-144hとおかしな値になってしまいました。

1
2
3
4
5
6
7
(前略)
2017-07-01 00:30:20.802110381 +0000 UTC 4m52.493894502s
2017-07-01 00:30:20.9022538 +0000 UTC 4m52.594037921s
2017-07-01 00:30:21.002404752 +0000 UTC 4m52.694188873s #
2017-06-24 23:41:17.694698679 +0000 UTC -144h44m10.6135172s # 正しい時刻に戻った
2017-06-24 23:41:17.794881161 +0000 UTC -144h44m10.513334718s
2017-06-24 23:41:17.895024223 +0000 UTC -144h44m10.413191656s

Go1.9で実行した場合です。 wall clockは正しい時刻に戻りましたが、monotonic clockはその影響を受けず、 経過時間も正しく計算できています。

1
2
3
4
5
6
2017-07-01 00:30:20.802071152 +0000 UTC m=+289.102414299 4m49.102265199s
2017-07-01 00:30:20.902234666 +0000 UTC m=+289.202577610 4m49.20242851s
2017-07-01 00:30:21.00238566 +0000 UTC m=+289.302728596 4m49.302579496s #
2017-06-24 23:41:17.694655753 +0000 UTC m=+289.402903206 4m49.402754106s # 正しい時刻に戻った
2017-06-24 23:41:17.794841932 +0000 UTC m=+289.503089435 4m49.502940335s
2017-06-24 23:41:17.895004891 +0000 UTC m=+289.603252211 4m49.603103111s

ドリフトしてみた

monotonic time は ntpd の干渉を全く受けないわけではなく、 ドリフトの補正は受けます。 せっかくなのでこれも確認してみました。

以下のコマンドで500PPM(Parts-per-Million)早く時刻が進むntpdとして動作します。 1PPMは100万分の1の誤差なので、500PPMでは2000秒(約33分)で1秒ズレます。

1
$ sudo fakentpd -d 500

(ほんとうは2倍速!とかやってみたかったけど、さすがに偽ntpdだとバレて同期対象から外された)

起動からの経過時間を返すサーバーと、 サーバーとの時刻を比較するクライアントを用意します。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
package main

import (
  "fmt"
  "log"
  "net/http"
  "time"
)

func main() {
  start := time.Now()
  http.HandleFunc("/", func(w http.ResponseWriter, req *http.Request) {
      // 起動からの経過時間を返す
      fmt.Fprintf(w, "%.6f", time.Since(start).Seconds())
      log.Printf("%.6f", time.Since(start).Seconds())
  })
  http.ListenAndServe(":8080", nil)
}
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
package main

import (
  "io/ioutil"
  "log"
  "net/http"
  "os"
  "strconv"
  "time"
)

// サーバー側の経過時間を取得する
func get(u string) float64 {
  resp, _ := http.Get(u)
  defer resp.Body.Close()
  data, _ := ioutil.ReadAll(resp.Body)
  t, _ := strconv.ParseFloat(string(data), 64)
  return t
}

func main() {
  start := time.Now()
  startRemote := get(os.Args[1])
  for {
      time.Sleep(time.Second)
      end := time.Now()
      endRemote := get(os.Args[1])
      log.Printf("local:  %.6f", end.Sub(start).Seconds())
      log.Printf("remote: %.6f", endRemote-startRemote)
  }
}

ドリフト補正が反映されるよう数時間同期状態を保ったあと、 検証用プログラムを走らせると以下のような結果になりました。

1
2
3
4
5
6
7
8
9
(前略)
2017/06/25 08:34:27 local:  1997.178992
2017/06/25 08:34:27 remote: 1998.176471
2017/06/25 08:34:28 local:  1998.179892
2017/06/25 08:34:28 remote: 1999.177970
2017/06/25 08:34:29 local:  1999.180993
2017/06/25 08:34:29 remote: 2000.179569
2017/06/25 08:34:30 local:  2000.182062
2017/06/25 08:34:30 remote: 2001.181200

起動から2000秒で1秒のズレ=500PPMのドリフトがかかっていることが確認できました。

まとめ

Go1.9からサポートされるmonotonic clockについて検証を行いました。 うるう秒や時刻変更の影響を受けず、正しく経過時間を測定できることが確認できました。 また、ドリフトの調整は受けることも確認できました。

monotonic clockになると、methaneさんが紹介しているzero time cacheの 実用性があがって利用しやすくなりますね。 さらにCloudflare DNSがうるう秒にやられる こともなくなるので安心です。

注意点としてはt.String()がmonotonic clockの情報を返すので、 時刻の出力を雑にfmt.Println(t)とかしていると出力が変わってしまうことくらいでしょうか。 (皆さんちゃんとFormatしてますよね?)

もうすぐ来年1月1日のうるう秒の有無が発表される時期です。 それまでにはGo1.9の正式版がリリースされているはずなので、 変な罠に引っかからないよう皆さんアップデートしましょう!

参考

Comments