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

Question

编辑：虽然我确实同意这个问题的关键在于 Thread.sleep() 的准确性，但我一直认为 Thread.sleep() 倾向于比要求的睡眠时间更长。为什么线程会在睡眠时间到期之前恢复？我可以理解操作系统调度程序没有及时回到线程来唤醒它，但为什么它会更早到达那里呢？如果操作系统可以任意提前唤醒线程，那么休眠线程的意义何在？

我正在尝试编写一个类来在我的项目中进行模块化计时。这个想法是让一个类能够测量我感兴趣的任何特定代码的执行时间。我想在无需就地编写特定时序代码的情况下进行此测量，并为自己提供一个干净的模块化接口。

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

这是我的实现：

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

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

我不确定这些问题是唯一的，但如果我必须选择一个来解决，那就是抖动。

有人能弄清楚为什么会有 1ms 左右的抖动吗？

奖励：为什么手表有时会弄乱单圈持续时间？

Answer 1

手表有时会出现混乱，因为您在读取 ​​currentTime 的线程中执行计算，该线程与写入 currentTime 的线程不同。因此，有时读取的值是未初始化的——即零。在您提到的涉及watch2 的特定情况下，记录了零圈开始时间，因为初始currentTime 值对记录圈开始时间的线程不可用。

要解决此问题，请将 currentTime 声明为 volatile。您可能还需要延迟或让步，以允许watch 在开始任何圈之前进行一次更新。

至于抖动，currentTime 不是 volatile 的事实可能是部分或全部问题，因为用于启动和停止的调用线程可能正在处理陈旧数据。此外，Thread.sleep() 仅在系统时钟准确的程度上是准确的，在大多数系统中，这不是纳秒精度。关于后者的更多信息应在评论中可能重复的 Basilevs 提及中提供。