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

Multi-Threaded Timing Application with Significant Jitter and Errors?

编辑:虽然我确实同意这个问题的关键取决于 Thread.sleep() 的准确性,但我一直相信 Thread.sleep() 倾向于睡眠时间超过要求。为什么线程会在其睡眠持续时间到期之前恢复?我可以理解 OS 调度程序没有及时回到线程唤醒它,但为什么它会更早到达那里?如果 OS 可以任意提前唤醒线程,那么睡眠线程有什么意义?

我正在尝试编写一个 class 来在我的项目中进行模块化计时。我的想法是让 class 能够测量我感兴趣的任何特定代码段的执行时间。我想进行这种测量,而不必就地编写特定的计时代码并为自己提供一个干净的模块化接口。

这个概念是围绕一个教练建立的,他的每个跑步者都有多个秒表。我可以用不同的秒表 ID 调用一个 class 来创建线程来测量它们各自的相对执行时间。此外,还有一个圈功能来测量手表时钟的子间隔。该实现以秒表(教练)class 和手表(跑步者)class.

对 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 class 中的线程可能做错了什么。似乎单圈持续时间被取消并导致我的开始时间和结束时间之间存在一些值。

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

有人能搞清楚为什么会有 1 毫秒左右的抖动吗?

奖金:为什么手表会时不时地弄乱圈速?

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

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

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