具有明显抖动和误差的多线程计时应用？

Question

编辑：虽然我同意这个问题的关键在于Thread.sleep（）的准确性，但我一直认为Thread.sleep（）偏向于睡眠时间超过要求。为什么线程会在其睡眠持续时间到期之前恢复？我可以理解操作系统调度程序没有及时回到线程以唤醒它，但是为什么它会更早到达那里呢？如果操作系统可以任意早早地唤醒它们，那么Hibernate线程的意义何在？

我正在尝试编写一个类来在我的项目中进行模块化计时。这个想法是使一个类能够测量我感兴趣的任何特定代码的执行时间。我想在不编写特定计时代码的情况下进行这种测量，并为自己提供一个干净的模块化界面。

这个概念是围绕着一个教练为他的每个跑步者准备多个秒表而建立的。我可以调用一个具有不同秒表 ID 的类，以创建测量其各自相对执行时间的线程。此外，还有一个圈速功能，用于测量手表时钟的子间隔。该实现以秒表（教练）类和手表（跑步者）类使用哈希图为中心。

下面是我的实现：

import java.util.HashMap;
import java.util.Map;
import java.util.Map.Entry;

public class Stopwatch {
    private static Map<String, Watch> watchMap = new HashMap<>();

    public static boolean start( String watchID ) {
        if( !watchMap.containsKey( watchID ) ) {
            watchMap.put(watchID, new Watch() );
            return true;
        } else {
            return false;
        }
    }

    public static void stop( String watchID ) {
        if( watchMap.containsKey(watchID) ) {
            watchMap.get(watchID).stop();
        }
    }

    public static void startLap( String watchID, String lapID ) {
        if( watchMap.containsKey(watchID) ) {
            watchMap.get(watchID).startLap(lapID);
        }
    }

    public static void endLap( String watchID, String lapID ) {
        if( watchMap.containsKey(watchID) ) {
            watchMap.get(watchID).stopLap(lapID);
        }
    }

    public static void stopAndSystemPrint( String watchID ) {
        if( watchMap.containsKey(watchID)) {
            Watch watch = watchMap.get(watchID);
            if( watch.isRunning() ) {
                watch.stop();
            }
            Map<String, Long> lapMap = watch.getLapMap();

            System.out.println("/****************** " + watchID 
                             + " *******************\\" );
            System.out.println("Watch started at: " + watch.getStartTime() 
                             + " nanosec" );
            for( Entry<String, Long> lap : lapMap.entrySet() ) {
                System.out.println("\t" + lap.getKey() + ": " 
                                + ((double)lap.getValue() / 1000000.0) 
                                + " msec" );
            } 
            System.out.println("Watch ended at: " + watch.getEndTime() 
                             + " nanosec" );
            System.out.println("Watch total duration: " 
                             + (double)(watch.getDuration() / 1000000.0 ) 
                             + " msec" );
            System.out.println("\\****************** " + watchID 
                             + " *******************/\n\n");
        }
    }

    private static class Watch implements Runnable {

        private Thread timingThread;
        private long startTime;
        private long currentTime;
        private long endTime;

        private volatile boolean running;
        private Map<String, Long> lapMap;

        public Watch() {
            startTime = System.nanoTime();
            lapMap = new HashMap<>();

            running = true;
            timingThread = new Thread( this );
            timingThread.start();
        }

        @Override
        public void run() {
            while( isRunning() ) {
                currentTime = System.nanoTime();
                // 0.5 Microsecond resolution
                try {
                    Thread.sleep(0, 500);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        }

        public void stop() {
            running = false;
            endTime = System.nanoTime();
        }

        public void startLap( String lapID ) {
            lapMap.put( lapID, currentTime );
        }

        public void stopLap( String lapID ) {
            if( lapMap.containsKey( lapID ) ) {
                lapMap.put(lapID, currentTime - lapMap.get(lapID) );
            }
        }

        public Map<String, Long> getLapMap() {
            return this.lapMap;
        }

        public boolean isRunning() {
            return this.running;
        }

        public long getStartTime() {
            return this.startTime;
        }

        public long getEndTime() {
            return this.endTime;
        }

        public long getDuration() {
            if( isRunning() ) {
                return currentTime - startTime;
            } else {
                return endTime - startTime;
            }
        }
    }
}

下面是我用来测试此实现的代码：

public class StopwatchTest {

    public static void main(String[] args) throws InterruptedException {
        String watch1 = "watch1";
        Stopwatch.start( watch1 );

        String watch2 = "watch2";
        Stopwatch.start(watch2);

        String watch3 = "watch3";
        Stopwatch.start(watch3);

        String lap1 = "lap1";
        Stopwatch.startLap( watch1, lap1 );
        Stopwatch.startLap( watch2, lap1 );

        Thread.sleep(13);

        Stopwatch.endLap( watch1, lap1 );
        String lap2 = "lap2";
        Stopwatch.startLap( watch1, lap2 );

        Thread.sleep( 500 );

        Stopwatch.endLap( watch1, lap2 );

        Stopwatch.endLap( watch2, lap1 );

        Stopwatch.stop(watch3);

        String lap3 = "lap3";
        Stopwatch.startLap(watch1, lap3);

        Thread.sleep( 5000 );

        Stopwatch.endLap(watch1, lap3);

        Stopwatch.stop(watch1);
        Stopwatch.stop(watch2);
        Stopwatch.stop(watch3);

        Stopwatch.stopAndSystemPrint(watch1);
        Stopwatch.stopAndSystemPrint(watch2);
        Stopwatch.stopAndSystemPrint(watch3);
    }
}

最后，此测试可以生成的输出：

/****************** watch1 *******************\
Watch started at: 45843652013177 nanosec
    lap1: 12.461469 msec
    lap2: 498.615724 msec
    lap3: 4999.242803 msec
Watch ended at: 45849165709934 nanosec
Watch total duration: 5513.696757 msec
\****************** watch1 *******************/


/****************** watch2 *******************\
Watch started at: 45843652251560 nanosec
    lap1: 4.5844165436787E7 msec
Watch ended at: 45849165711920 nanosec
Watch total duration: 5513.46036 msec
\****************** watch2 *******************/


/****************** watch3 *******************\
Watch started at: 45843652306520 nanosec
Watch ended at: 45849165713576 nanosec
Watch total duration: 5513.407056 msec
\****************** watch3 *******************/

这段代码有一些有趣的（至少对我来说）结果。

一，是手表在1毫秒的数量级上提前或延迟完成。我本来以为，尽管纳秒时钟有些不准确，但我可以获得比1毫秒更好的精度。也许我忘记了一些关于重要数字和准确性的事情。

另一个是，在此测试结果中，watch2 以圈数的以下结果结束：

Watch started at: 45843652251560 nanosec
    lap1: 4.5844165436787E7 msec
Watch ended at: 45849165711920 nanosec

我检查了我在< code>stopAndSystemPrint方法中操作值的方式，但这似乎对错误没有任何影响。我只能得出结论，我在那里做的数学是可靠的，而在此之前的一些东西有时会被打破。有时这让我担心，因为我认为它告诉我，我可能在< code>Watch类中的线程上做了一些错误的事情。看起来一圈的持续时间被取消了，导致我的开始时间和结束时间之间出现了一些值。

我不确定这些问题是否是排他性的，但如果我必须选择一个来解决，那将是抖动。

有人能搞清楚为什么会有1ms量级的抖动吗？

额外收获:为什么手表会时不时地把单圈时间搞得一团糟？

Answer 1

手表有时会出错，因为您在读取currentTime的线程中执行计算，这与写入currentTime的线程不同。因此，有时读取的值未初始化，即为零。在您提到的涉及watch2的特定情况下，会记录零圈开始时间，因为记录圈开始时间的线程无法使用初始currentTimevalue。

若要解决此问题，请将< code>currentTime声明为< code>volatile。您可能还需要设置延迟或让步，以允许< code >手表在开始任何圈之前进行一次时间更新。

至于抖动，< code>currentTime不稳定可能是部分或全部问题，因为starts和stops的调用线程可能正在处理陈旧数据。此外，Thread.sleep()仅在系统时钟准确的程度上是准确的，在大多数系统中，这不是纳秒级的准确性。关于后者的更多信息可以在评论中提到的可能重复的Basilevs处找到。