java - ReentrantLock tryLock(timeout,timeUnit) 无法按预期工作

Question

我对 ReentrantLock tryLock(timeout,timeUnit) 方法有一些困惑，当
运行下面的代码似乎 tryLock 超时，直到上一个线程结束，有人能解释一下吗？

public class MyService2 {
public ReentrantLock lock = new ReentrantLock();

public void waitMethod() {
    try {
        System.out.println(System.currentTimeMillis() + " " + Thread.currentThread().getName() + " enter ");
        boolean b = lock.tryLock(2, TimeUnit.SECONDS);
        if (b) {
            System.out.println(System.currentTimeMillis() + " lock begin:" + Thread.currentThread().getName());
            for (int i = 0; i < Integer.MAX_VALUE / 10; i++) {
                Math.random();
            }
            System.out.println(System.currentTimeMillis() + " lock end " + Thread.currentThread().getName());
            return;
        }
        System.out.println(System.currentTimeMillis() + " " + Thread.currentThread().getName() + " got no lock end ");
    } catch (InterruptedException e) {
        e.printStackTrace();
    } finally {
        if (lock.isHeldByCurrentThread()) {
            lock.unlock();
        }
    }
}

public static void main(String[] args) throws InterruptedException {
    MyService2 myService2 = new MyService2();
    Runnable runnable = myService2::waitMethod;
    Thread thread1 = new Thread(runnable);
    thread1.setName("T1");
    thread1.start();
    TimeUnit.MILLISECONDS.sleep(10);
    Thread thread2 = new Thread(runnable);
    thread2.setName("T2");
    thread2.start();
}

运行这段代码后，结果是这样的

1555343172612 T1 enter 
1555343172613 lock begin:T1
1555343172627 T2 enter 
1555343179665 lock end T1
1555343179665 T2 got no lock end 

我的问题是为什么线程 T2 不会在 2 秒内超时而不是等到线程 T1 结束？

但我刚刚发现:

1. 例如，如果将 Math.random() 替换为 TimeUnit.SECONDS.sleep(1)，则效果很好。

2. 如果在 Debug模式下运行，它也可以正常工作。

Answer 1

这是一个有一些修改的替代方案:

首先，清理。更清晰的名字。更少的侵入性日志记录。相对时间值。

其次，两个计算线程启动之间的 0.1 秒 sleep 被移至每个线程中。这更清楚地赋予启动计算线程的线程优先权。

第三，启动线程与计算线程连接。即将计算的结论与启动线程联系起来。在原始代码中，计算线程启动后没有对其进行管理。如果计算线程打算不受管理，则需要记录下来。

第四，复制整个启动线程加上两个计算线程结构。即给予结构一个更真实的运行时环境，并将结构的不同行为一起呈现在一个 View 中。

修改的一个主题是使程序的预期行为和实际行为(通过日志输出查看)变得清晰。我们的目标是为这些内容提供最大程度的清晰度。

建议进行额外的修改，即将日志语句放入缓存中，然后在所有计算单元完成后显示收集的日志行。这消除了由日志语句引起的行为变化，这些变化通常是相当大的。

package my.tests;

import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.ReentrantLock;

public class LockTest {

    private static long initialTime;

    protected static void setInitialTime() {
        initialTime = System.currentTimeMillis();
    }

    public static long getInitialTime() {
        return initialTime;
    }

    public static final int CELL_COUNT = 10;

    public static void main(String[] args) {
        setInitialTime();

        System.out.println("Beginning [ " + Integer.toString(CELL_COUNT) + " ] computation cells");

        Thread[] cellThreads = new Thread[CELL_COUNT];
        for ( int cellNo = 0; cellNo < CELL_COUNT; cellNo++ ) {
            final String cellNoText = Integer.toString(cellNo);
            Runnable computeCell = () -> { 
                (new LockTest(cellNoText) ).compute();
            };
            Thread cellThread = new Thread(computeCell);
            cellThreads[cellNo] = cellThread;
        }

        // Start them all up ...

        for ( Thread cellThread : cellThreads ) {
            cellThread.start();
        }

        // Then wait for them all to finish ...

        for ( Thread cellThread : cellThreads ) {
            try {
                cellThread.join();
            } catch ( InterruptedException e ) {
                System.out.println("Unexpected interruption: " + e.getMessage());
                e.printStackTrace();
            }
        }

        System.out.println("Completed [ " + Integer.toString(CELL_COUNT) + " ] computation cells");
    }

    //

    public LockTest(String cellName) {
        this.cellName = cellName;
    }

    private final String cellName;

    public String getCellName() {
        return cellName;
    }

    // Logging ...

    public String formatTime(long timeMs) {
        return String.format("%12d (ms)", new Long(timeMs));
    }

    public long getRelativeTime(long currentTime) {
        return currentTime - getInitialTime();
    }

    public String formatRelativeTime(long timeMs) {
        return String.format(
            "%12d %8d (ms)",
            new Long(timeMs),
            new Long( timeMs - getInitialTime() ));
    }

    public void log(String methodName, String message) {
        long timeMs = System.currentTimeMillis();
        String threadName = Thread.currentThread().getName();

        System.out.println(
            formatRelativeTime(timeMs) + ": " +
            methodName + ": " +
            threadName + ": " + message);
    }

    //

    public void compute() {
        log("compute", "ENTER: " + getCellName());

        Runnable computation = () -> {
            guardedComputation(
                100L, 0,                  // Pause 0.1s before attempting the computation
                1, TimeUnit.SECONDS,      // Try to obtain the computation lock for up to 1.0s.
                Integer.MAX_VALUE / 60 ); // Run this many computations; takes about 2s; adjust as needed
        };

        Thread computer1 = new Thread(computation);
        computer1.setName( getCellName() + "." + "T1");

        Thread computer2 = new Thread(computation);
        computer2.setName( getCellName() + "." + "T2");

        // Run two sets of computations:
        //
        // Each will pause for 0.1s before performing the computations.
        //
        // Performing computations requires a computation lock; wait up to 2.0s
        // to acquire the lock.

        computer1.start();
        computer2.start();

        try {
            computer1.join();
        } catch ( InterruptedException e ) {
            System.out.println("Unexpected interruption: " + e.getMessage());
            e.printStackTrace();
            return;
        }

        try {
            computer2.join();
        } catch ( InterruptedException e ) {
            System.out.println("Unexpected interruption: " + e.getMessage());
            e.printStackTrace();
            return;
        }

        log("compute", "RETURN: " + getCellName());
    }

    // Computation locking ...

    private final ReentrantLock computationLock = new ReentrantLock();

    public boolean acquireComputationLock(long maxWait, TimeUnit maxWaitUnit) throws InterruptedException {
        return computationLock.tryLock(maxWait, maxWaitUnit);
    }

    public void releaseComputationLock() {
        if ( computationLock.isHeldByCurrentThread() ) {
            computationLock.unlock();
        }
    }

    //

    public void guardedComputation(
        long pauseMs, int pauseNs,
        long maxWait, TimeUnit maxWaitUnit, int computations) {

        String methodName = "guardedComputation";

        log(methodName, "ENTER");

        try {
            Thread.sleep(pauseMs, pauseNs);
        } catch ( InterruptedException e ) {
            System.out.println("Unexpected interruption: " + e.getMessage());
            e.printStackTrace();
            return;
        }

        try {
            boolean didLock;
            try {
                didLock = acquireComputationLock(maxWait, maxWaitUnit);
            } catch ( InterruptedException e ) {
                System.out.println("Unexpected interruption: " + e.getMessage());
                e.printStackTrace();
                return;
            }

            String computationsText = Integer.toString(computations);
            if ( didLock ) {
                log(methodName, "Starting computations: " + computationsText);
                for ( int computationNo = 0; computationNo < computations; computationNo++ ) {
                    Math.random();
                }
                log(methodName, "Completed computations: " + computationsText);
            } else {
                log(methodName, "Skipping computations: " + computationsText);
            }

        } finally {
            releaseComputationLock();
        }

        log(methodName, "RETURN");
    }
}