Javaの System.sleep() が、Linux CLOCK_MONOTONICを全力で無駄にしている

この辺りを手元で確認したという話.

Thread.sleep() で5秒スリープするJavaプログラム

import java.text.SimpleDateFormat;
import java.util.Date;

public class Sleep5Sec {
    public static void main(String[] args) {
        try {
            SimpleDateFormat fmt = new SimpleDateFormat("HH:mm:ss.SSS");
            final Date d0 = new Date();
            final long t0 = System.nanoTime();
            Thread.sleep(5 * 1000);
            final long t1 = System.nanoTime();
            final Date d1 = new Date();
            System.out.printf("%15d - %15d => %13.6f ms%n", t1, t0, 1e-6 * (t1 - t0));
            System.out.printf("%15s - %15s => %6d%7s ms%n",
                fmt.format(d1), fmt.format(d0), d1.getTime() - d0.getTime(), "");
        } catch (Exception ex) {
            ex.printStackTrace();
        }
    }
}

さらに「現在時刻を3秒進ませる/遅らせる」シェルコマンド(1秒弱の誤差が出るのはご勘弁):

$ sudo date -s @$[ `date +%s` + 3 ]
2013年 12月 16日 月曜日 13:03:25 SGT
$ sudo date -s @$[ `date +%s` - 3 ]
2013年 12月 16日 月曜日 13:03:44 SGT

これらを組み合わせてみる:

$ java Sleep5Sec
(別端末上で素早く時刻を3秒進ませる)
5149670129719 - 5144669487622 => 5000.642097 ms
13:43:11.145 - 13:43:04.088 =>       7057 ms
$ java Sleep5Sec
(別端末上で素早く時刻を3秒遅らせる)
5174094020305 - 5165450038923 => 8643.981382 ms
13:43:29.893 - 13:43:24.893 =>       5000 ms

うーん,つらぽよ...
この非対称性は,時刻を遅らせた方はspurious wakeup的な事象が起きたと誤認されて(外の雨音で目覚めたが目覚まし時計を見るとまだ朝4時なので寝直すイメージ)Javaランタイム内でもう一度「残り時間」をスリープするsyscallを呼んでると解釈.

もっと厳密にやるときはCPUのキャッシュやhotspotちゃんを温めたりするんだけど,今回の試験で見えた差は明らかにそういうレイヤではないのでスキップ.
なおLinux syscallレイヤではこのような問題は起きないことも合わせて実験済み:

#define _POSIX_C_SOURCE 199309L

#include <time.h>
#include <errno.h>
#include <stdio.h>

int main(void) {
    struct timespec slp = { 5, 0 }, rest, t0, t1, m0, m1;

    clock_gettime(CLOCK_REALTIME, &t0);
    clock_gettime(CLOCK_MONOTONIC, &m0);
    while (nanosleep(&slp, &rest) && (EINTR == errno || EAGAIN == errno))
        slp = rest;
    clock_gettime(CLOCK_REALTIME, &t1);
    clock_gettime(CLOCK_MONOTONIC, &m1);

    const long long GIGA = 1000 * 1000 * 1000,
        a = GIGA * t0.tv_sec + t0.tv_nsec,
        b = GIGA * t1.tv_sec + t1.tv_nsec,
        c = GIGA * m0.tv_sec + m0.tv_nsec,
        d = GIGA * m1.tv_sec + m1.tv_nsec;
    printf("%20lld - %20lld = %13.6f\n", b, a, 1e-6 * (b - a));
    printf("%20lld - %20lld = %13.6f\n", d, c, 1e-6 * (d - c));

    return 0;
}

ちゃんとmanにも明記されている:

NOTES

... Linux measures the time using the CLOCK_MONOTONIC clock. ...

次回はソケットのタイムアウトで実験.
実験環境:

$ lsb_release -a
LSB Version:   (略)
Distributor ID: Ubuntu
Description:    Ubuntu 12.04.2 LTS
Release:        12.04
Codename:       precise
$ uname -a      
Linux kaidev01 3.2.0-57-generic #87-Ubuntu SMP Tue Nov 12 21:35:10 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux
$ java -version
java version "1.7.0_25"
OpenJDK Runtime Environment (IcedTea 2.3.10) (7u25-2.3.10-1ubuntu0.12.04.2)
OpenJDK 64-Bit Server VM (build 23.7-b01, mixed mode)

CPUはIvy橋 Core i7-3770の4コア × HT.