2015年7月1日水曜日

2015年7月1日の うるう秒 調整時の ntpd の挙動観測データ

本日(2015年7月1日 9:00 JST)、うるう秒挿入が実施されるので、手持ちのマシンで観測データを記録してみたいと思います。
マシン環境は次のとおりです。
[root@hoge ~]# cat /etc/centos-release
CentOS release 6.6 (Final)
[root@hoge ~]# uname -a
Linux hoge 2.6.32-504.23.4.el6.x86_64 #1 SMP Tue Jun 9 20:57:37 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
[root@hoge ~]# dmidecode -s system-manufacturer ; dmidecode -s system-version
LENOVO
ThinkPad W520
[root@hoge ~]# ps -fC ntpd
UID        PID  PPID  C STIME TTY          TIME CMD
ntp      12778     1  0 Jun30 ?        00:00:10 ntpd -u ntp:ntp -p /var/run/ntpd.pid -g -x
[root@hoge ~]# rpm -q ntp
ntp-4.2.6p5-3.el6.centos.x86_64
ThinkPad W520 + CentOS 6.6 + ntp 4.2.6系(slewモード設定)という環境です。

まず、Leap Indicator が到着しているか確認です。予め、昨日の朝から ntpq -c readvar を定期採取するように仕込んでおきました。
[root@hoge ~]# less ntpq-c_readvar.log
...
2015-06-30 09:31:12 associd=0 status=0615 leap_none, sync_ntp, 1 event, clock_sync,
2015-06-30 09:31:12 version="ntpd 4.2.6p5@1.2349-o Mon Mar 16 14:53:03 UTC 2015 (1)",
2015-06-30 09:31:12 processor="x86_64", system="Linux/2.6.32-504.23.4.el6.x86_64", leap=00,
2015-06-30 09:31:12 stratum=3, precision=-24, rootdelay=23.151, rootdisp=315.573,
2015-06-30 09:31:12 refid=106.187.50.84,
2015-06-30 09:31:12 reftime=d93c60c7.306f0aee  Tue, Jun 30 2015  9:26:47.189,
2015-06-30 09:31:12 clock=d93c61d0.45e5528d  Tue, Jun 30 2015  9:31:12.273, peer=18506, tc=6,
2015-06-30 09:31:12 mintc=3, offset=-270.419, frequency=198.276, sys_jitter=4.409,
2015-06-30 09:31:12 clk_jitter=10.496, clk_wander=6.132

2015-06-30 09:32:12 associd=0 status=4615 leap_add_sec, sync_ntp, 1 event, clock_sync,
2015-06-30 09:32:12 version="ntpd 4.2.6p5@1.2349-o Mon Mar 16 14:53:03 UTC 2015 (1)",
2015-06-30 09:32:12 processor="x86_64", system="Linux/2.6.32-504.23.4.el6.x86_64", leap=01,
2015-06-30 09:32:12 stratum=3, precision=-24, rootdelay=52.667, rootdisp=321.239,
2015-06-30 09:32:12 refid=202.234.64.222,
2015-06-30 09:32:12 reftime=d93c61bd.33a3a956  Tue, Jun 30 2015  9:30:53.201,
2015-06-30 09:32:12 clock=d93c620c.4797c6d6  Tue, Jun 30 2015  9:32:12.279, peer=18505, tc=6,
2015-06-30 09:32:12 mintc=3, offset=-270.889, frequency=194.208, sys_jitter=3.803,
2015-06-30 09:32:12 clk_jitter=9.819, clk_wander=5.913

2015-06-30 09:33:12 associd=0 status=461a leap_add_sec, sync_ntp, 1 event, leap_disarmed,
2015-06-30 09:33:12 version="ntpd 4.2.6p5@1.2349-o Mon Mar 16 14:53:03 UTC 2015 (1)",
2015-06-30 09:33:12 processor="x86_64", system="Linux/2.6.32-504.23.4.el6.x86_64", leap=01,
2015-06-30 09:33:12 stratum=3, precision=-24, rootdelay=19.556, rootdisp=307.926,
2015-06-30 09:33:12 refid=122.215.240.52,
2015-06-30 09:33:12 reftime=d93c61f5.2f46436e  Tue, Jun 30 2015  9:31:49.184,
2015-06-30 09:33:12 clock=d93c6248.46b5ce84  Tue, Jun 30 2015  9:33:12.276, peer=18503, tc=6,
2015-06-30 09:33:12 mintc=3, offset=-262.259, frequency=193.207, sys_jitter=5.568,
2015-06-30 09:33:12 clk_jitter=9.679, clk_wander=5.543
...
Leap Indicator は、うるう秒の 24時間前 から通知されることになってますが、わたしのマシンで認識されたのは、9時半頃だったようです。

次は、現在(6:16)の状態です。
[root@hoge ~]# date
Wed Jul  1 06:16:29 JST 2015
[root@hoge ~]# ntpq -c readvar
associd=0 status=461a leap_add_sec, sync_ntp, 1 event, leap_disarmed,
version="ntpd 4.2.6p5@1.2349-o Mon Mar 16 14:53:03 UTC 2015 (1)",
processor="x86_64", system="Linux/2.6.32-504.23.4.el6.x86_64", leap=01,
stratum=3, precision=-24, rootdelay=54.844, rootdisp=62.648,
refid=202.234.64.222,
reftime=d93d82c0.32fbf279  Wed, Jul  1 2015  6:04:00.199,
clock=d93d85b6.7bb5c81a  Wed, Jul  1 2015  6:16:38.483, peer=18505, tc=7,
mintc=3, offset=-2.242, frequency=-1.742, sys_jitter=1.101,
clk_jitter=0.896, clk_wander=0.023
[root@hoge ~]# ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
-122x215x240x52. 133.243.238.164  2 u  124  128  377   17.892   -0.253   0.572
+chobi.paina.jp  131.112.125.48   2 u   98  128  377   19.177   -2.397  53.470
*ntp.kiba.net    193.221.26.33    2 u  107  128  373   31.772   -3.135   5.208
+gw1.kohaaloha.c 133.243.238.244  2 u  110  128  377   19.573   -1.331   0.842
[root@hoge ~]# grep ^server /etc/ntp.conf  ※いじっているのは次の箇所だけです
server 0.centos.pool.ntp.org iburst maxpoll 8
server 1.centos.pool.ntp.org iburst maxpoll 8
server 2.centos.pool.ntp.org iburst maxpoll 8
server 3.centos.pool.ntp.org iburst maxpoll 8
[root@hoge ~]# ntptime
ntp_gettime() returns code 5 (ERROR)
  time d93d85c3.123a8000  Wed, Jul  1 2015  6:16:51.071, (.071205),
  maximum error 16000000 us, estimated error 16 us, TAI offset 0
ntp_adjtime() returns code 5 (ERROR)
  modes 0x0 (),
  offset 0.000 us, frequency 0.000 ppm, interval 1 s,
  maximum error 16000000 us, estimated error 16 us,
  status 0x41 (PLL,UNSYNC),
  time constant 7, precision 1.000 us, tolerance 500 ppm,
続きは、また今晩書きたいと思います。

2015-07-02追記
次回の参考になるよう、slew モードで1秒が補正されるまでのデータを残しておきます。
まず、munin のグラフです。


次は、ntpq -np の出力を定期採取したデータです。
                         remote           refid      st t when poll reach   delay   offset  jitter
                    ==============================================================================
2015-07-01 04:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u   11   64  377   19.788   -2.099   0.993
2015-07-01 04:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u   32  128  377   19.714   -1.349   0.772
2015-07-01 05:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u  118  128  377   20.725   -2.126   2.264
2015-07-01 05:32:14 *106.xxx.yy.zz   133.243.u.vvv    2 u   76  128  377   20.475   -1.875   1.471
2015-07-01 06:02:14 +106.xxx.yy.zz   133.243.u.vvv    2 u   27  128  377   20.205   -1.154   2.433
2015-07-01 06:32:14 *106.xxx.yy.zz   133.243.u.vvv    2 u  122  128  377   21.338   -0.645   2.110
2015-07-01 07:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u  202  256  377   20.592   -2.101   1.402
2015-07-01 07:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  143  256  377   20.653   -2.038   3.277
2015-07-01 08:02:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  111  256  377   20.023   -2.303   0.631
2015-07-01 08:32:14 *106.xxx.yy.zz   133.243.u.vvv    2 u   60  256  377   19.803   -2.709   0.536
2015-07-01 09:02:14 +106.xxx.yy.zz   133.243.u.vvv    2 u    9  256  377   21.023   -1.460 378.296
2015-07-01 09:32:14 x106.xxx.yy.zz   133.243.u.vvv    2 u  231  256  377   18.791  -1001.8 377.872
2015-07-01 10:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u  187  256  377   18.732  -850.50 128.921
2015-07-01 10:32:14 x106.xxx.yy.zz   133.243.u.vvv    2 u  140  256  377   19.959  -338.47 202.357
2015-07-01 11:02:14 x106.xxx.yy.zz   133.243.u.vvv    2 u  108  256  377   19.959  -338.47 124.808
2015-07-01 11:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u   94  256  377   18.902  -92.918  48.587
2015-07-01 12:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u   46  256  377   19.725  -46.976  24.980
2015-07-01 12:32:14 -106.xxx.yy.zz   133.243.u.vvv    2 u   14  256  377   21.471   24.117  16.097
2015-07-01 13:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u  247  256  377   21.222   33.890  23.763
2015-07-01 13:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  202  256  377   21.370   47.732  20.740
2015-07-01 14:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u  160  256  377   20.123   66.180  31.655
2015-07-01 14:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  128  256  377   19.378   67.970   5.429
2015-07-01 15:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u   99  256  377   19.839   71.999   0.685
2015-07-01 15:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u   50  256  377   20.541   71.707   3.409
2015-07-01 16:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u   10  256  377   20.986   73.016   1.333
2015-07-01 16:32:14 *106.xxx.yy.zz   133.243.u.vvv    2 u  252  256  377   20.864   71.603   3.392
2015-07-01 17:02:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  215  256  377   21.057   72.781   3.576
2015-07-01 17:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  153  256  377   20.601   68.391   5.254
2015-07-01 18:02:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  108  256  377   21.467   66.549   2.707
2015-07-01 18:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u   60  256  377   21.532   63.015  36.577
2015-07-01 19:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u    7  256  377   21.525   58.468   1.322
2015-07-01 19:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  233  256  377   22.197   57.370   3.762
2015-07-01 20:02:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  184  256  377   19.177   58.782  30.390
2015-07-01 20:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  122  256  377   20.570   54.714   1.959
2015-07-01 21:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u   79  256  377   20.570   54.714   5.023
2015-07-01 21:32:14 *106.xxx.yy.zz   133.243.u.vvv    2 u   50  256  377   21.628   50.943   4.072
2015-07-01 22:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u    3  256  377   36.953   41.933   4.676
2015-07-01 22:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  224  256  377   37.968   44.620  46.186
2015-07-01 23:02:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  181  256  377   36.238   41.819  16.091
2015-07-01 23:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  152  256  377   36.340   46.415   7.950
2015-07-02 00:02:14 +106.xxx.yy.zz   133.243.u.vvv    2 u   89  256  377   39.487   42.372  11.150
2015-07-02 00:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u   59  128  377   32.067   32.882   5.267
2015-07-02 01:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u   21   64  377   21.239   13.838   6.248
2015-07-02 01:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u   50  128  377   22.461   12.798   3.011
2015-07-02 02:02:14 +106.xxx.yy.zz   133.243.u.vvv    2 u   11  256  377   21.303   11.877  16.779
2015-07-02 02:32:14 +106.xxx.yy.zz   133.243.u.vvv    2 u  249  256  377   21.504   16.263   6.163
2015-07-02 03:02:14 *106.xxx.yy.zz   133.243.u.vvv    2 u   61  128  377   20.093   16.886   1.101
2015-07-02 03:32:16 *106.xxx.yy.zz   133.243.u.vvv    2 u   24   64  377   20.018    5.750   2.548
2015-07-02 04:02:16 +106.xxx.yy.zz   133.243.u.vvv    2 u   48   64  377   21.012    2.840   0.944
2015-07-02 04:32:16 *106.xxx.yy.zz   133.243.u.vvv    2 u   63  128  377   19.750    3.482   0.846
2015-07-02 05:02:16 *106.xxx.yy.zz   133.243.u.vvv    2 u   12   64  377   19.643    4.361  26.509
2015-07-02 05:32:16 +106.xxx.yy.zz   133.243.u.vvv    2 u   41   64  377   21.850    1.910   2.910
2015-07-02 06:02:16 +106.xxx.yy.zz   133.243.u.vvv    2 u   12   64  377   20.327    1.325   7.538
2015-07-02 06:32:16 *106.xxx.yy.zz   133.243.u.vvv    2 u   49   64  377   19.247    1.809   3.580
2015-07-02 07:02:16 *106.xxx.yy.zz   133.243.u.vvv    2 u   77  128  377   20.714   -0.037   1.250
2015-07-02 07:32:16 *106.xxx.yy.zz   133.243.u.vvv    2 u   28  128  377   20.356    1.243   0.894
2015-07-02 08:02:16 +106.xxx.yy.zz   133.243.u.vvv    2 u  260  256  377   21.686    2.613   2.557
2015-07-02 08:32:16 +106.xxx.yy.zz   133.243.u.vvv    2 u  227  256  377   20.114    2.458  16.880
2015-07-02 09:02:16 +106.xxx.yy.zz   133.243.u.vvv    2 u  187  256  377   21.051    3.840   0.556
2015-07-02 09:32:16 *106.xxx.yy.zz   133.243.u.vvv    2 u  150  256  377   21.165    3.337   6.229
2015-07-02 10:02:16 *106.xxx.yy.zz   133.243.u.vvv    2 u  105  128  377   20.724    2.008   1.382
実際は、上位サーバは4つ指定してあり、そのうちの1つについて 30 分毎のデータです。前回(2012-07-01)観測したマシンでは、offset が 10 ミリ秒より小さくなるまでに 27 時間かかりましたが、今回は maxpoll 8 を設定した効果が出たようで、18 時間半でした。

最後に、/var/log/messages 抜粋です。
[root@hoge ~]# who -b
         system boot  2015-06-30 06:00
[root@hoge ~]# grep ntp /var/log/messages
※データ採取準備をして1度マシンを再起動した
Jun 30 06:01:04 hoge ntpd[12771]: ntpd 4.2.6p5@1.2349-o Mon Mar 16 14:53:03 UTC 2015 (1)
Jun 30 06:01:04 hoge ntpd[12778]: proto: precision = 0.048 usec
Jun 30 06:01:04 hoge ntpd[12778]: 0.0.0.0 c01d 0d kern kernel time sync enabled
Jun 30 06:01:04 hoge ntpd[12778]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Jun 30 06:01:04 hoge ntpd[12778]: Listen and drop on 1 v6wildcard :: UDP 123
Jun 30 06:01:04 hoge ntpd[12778]: Listen normally on 2 lo 127.0.0.1 UDP 123
Jun 30 06:01:04 hoge ntpd[12778]: Listen normally on 3 lo ::1 UDP 123
Jun 30 06:01:04 hoge ntpd[12778]: peers refreshed
Jun 30 06:01:04 hoge ntpd[12778]: Listening on routing socket on fd #20 for interface updates
Jun 30 06:01:04 hoge ntpd[12778]: Deferring DNS for 0.centos.pool.ntp.org 1
Jun 30 06:01:04 hoge ntpd[12778]: Deferring DNS for 1.centos.pool.ntp.org 1
Jun 30 06:01:04 hoge ntpd[12778]: Deferring DNS for 2.centos.pool.ntp.org 1
Jun 30 06:01:04 hoge ntpd[12778]: Deferring DNS for 3.centos.pool.ntp.org 1
Jun 30 06:01:04 hoge ntpd[12778]: 0.0.0.0 c016 06 restart
Jun 30 06:01:04 hoge ntpd[12778]: 0.0.0.0 c012 02 freq_set ntpd 500.000 PPM
Jun 30 06:01:07 hoge ntpd[12778]: Listen normally on 4 virbr0 192.168.122.1 UDP 123
Jun 30 06:01:07 hoge ntpd[12778]: peers refreshed
Jun 30 06:01:09 hoge ntpd[12778]: Listen normally on 5 eth0 fe80::f2de:f1ff:fef9:52c5 UDP 123
Jun 30 06:01:09 hoge ntpd[12778]: peers refreshed
Jun 30 06:01:22 hoge ntpd[12778]: Listen normally on 6 wlan0 fe80::2677:3ff:fe8f:224 UDP 123
Jun 30 06:01:22 hoge ntpd[12778]: peers refreshed
Jun 30 06:01:24 hoge ntpd[12778]: Listen normally on 7 wlan0 192.168.1.4 UDP 123
Jun 30 06:01:24 hoge ntpd[12778]: peers refreshed
Jun 30 06:01:24 hoge ntpd_intres[12786]: DNS 0.centos.pool.ntp.org -> 122.215.240.52
Jun 30 06:01:24 hoge ntpd_intres[12786]: DNS 1.centos.pool.ntp.org -> 157.7.154.23
Jun 30 06:01:24 hoge ntpd_intres[12786]: DNS 2.centos.pool.ntp.org -> 202.234.64.222
Jun 30 06:01:25 hoge ntpd_intres[12786]: DNS 3.centos.pool.ntp.org -> 106.187.50.84
Jun 30 06:01:31 hoge ntpd[12778]: 0.0.0.0 c615 05 clock_sync
Jun 30 09:32:53 hoge ntpd[12778]: 0.0.0.0 461a 0a leap_disarmed
Jul  1 09:00:00 hoge ntpd[12778]: 0.0.0.0 061b 0b leap_event
Jul  1 09:17:18 hoge ntpd[12778]: 0.0.0.0 0618 08 no_sys_peer
※以後はntpdからメッセージは出なかった
というわけで、めでたし、めでたし。
人気ブログランキングへ にほんブログ村 IT技術ブログへ