Javaアプリケーションのログの時刻がずれている

Javaのアプリケーションによって出力されたログの時刻がずれている現象が発生。
かつて、HP-UXで「はまった」ことを思い出した。


当時は、HP-UX上のWebアプリケーションにて、log4jを用いてログを出力していた。log4jをふつうに用いていると、LoggingEventのインスタンスを生成する際にSystem#currentTimeMillisメソッドを用いて時刻を取得している。
しかし運用が開始し、定期メンテナンスを繰り返すうちに、ログの時刻がOSの時刻とずれていることに気がつく*1。System#currentTimeMillisメソッドでは、OSから時刻を取得していると思っていたので、Java側の問題ではないと思っていたのだが、、Webアプリケーションを再起動すると、時刻のずれがなくなるのだ。そこで、本腰を入れて調べてみたら、すぐに見つかった。

HotSpot JVMは、gettimeofday()システム コールを使って日時情報を取得します。 パフォーマンス上、アプリケーションの起動時からのCPUの単位時間を使用して現在時刻を計算する、新しいメカニズムが使用されています。 このため、dateコマンド、 adjtime()関数または ntpなどの時刻同期ユーティリティを使用してシステム日付または時刻に行った変更は、Java プロセスが再起動されるまでプログラムが返す日時に反映されません。

システム時刻に対する変更を即座に反映する必要がある場合、-XX:+UseGetTimeOfDayオプションを使用すると、新しい軽量のメカニズムの代わりにgettimeofday呼び出しを使用するようJVMに指示できます。 ただし、この場合、パフォーマンスが低下することに注意してください。

http://docs.hp.com/ja/12587/jdk_rnotes_6.0.00.htm

HP-UX上のHPのJVMにおいては、オプションをつけてJavaのプロセスを起動しない限り、プロセスの起動時にOSから時刻を取得し、以降はCPUのクロックをもとに時刻を管理するというではないか。オプションをつけたら、パフォーマンスが上がる(そのかわり時間はずれる)ようにしてほしい。時間がとても大切になることは、けっこう多いから*2


ん?今回はHotSpotのはず。と思ったら、そもそもOSの時刻がくるっていたw
NTP有効になってるって言ったぢゃん!

*1:Webアプリケーションや、log4jのSimpleSocketServerなど、サーバプロセスである場合はけっこうずれる。当時、1ヵ月に数秒は(もっとかも)ずれていたと記憶している。

*2:時刻を用いた処理や、ログにとっては、とても大切かと。gettimeofdayシステムコール、そんなに高コストなのか?もっとぜんぜんダメダメなパフォーマンスの問題が多く存在するので、ちっとも気にならないw