HDFS-10923. Make InstrumentedLock require ReentrantLock.
Project: http://git-wip-us.apache.org/repos/asf/hadoop/repo Commit: http://git-wip-us.apache.org/repos/asf/hadoop/commit/c7ce6fdc Tree: http://git-wip-us.apache.org/repos/asf/hadoop/tree/c7ce6fdc Diff: http://git-wip-us.apache.org/repos/asf/hadoop/diff/c7ce6fdc Branch: refs/heads/HDFS-10467 Commit: c7ce6fdc20fe053f0bb3bcf900ffc0e1db6feee5 Parents: 3a3697d Author: Arpit Agarwal <a...@apache.org> Authored: Fri Sep 30 23:00:06 2016 -0700 Committer: Arpit Agarwal <a...@apache.org> Committed: Fri Sep 30 23:00:06 2016 -0700 ---------------------------------------------------------------------- .../apache/hadoop/hdfs/InstrumentedLock.java | 185 ------------------ .../hadoop/hdfs/InstrumentedReentrantLock.java | 195 +++++++++++++++++++ .../datanode/fsdataset/impl/FsDatasetImpl.java | 4 +- .../hadoop/hdfs/TestInstrumentedLock.java | 166 ---------------- .../hdfs/TestInstrumentedReentrantLock.java | 177 +++++++++++++++++ 5 files changed, 374 insertions(+), 353 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/hadoop/blob/c7ce6fdc/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/InstrumentedLock.java ---------------------------------------------------------------------- diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/InstrumentedLock.java b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/InstrumentedLock.java deleted file mode 100644 index 6279e95..0000000 --- a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/InstrumentedLock.java +++ /dev/null @@ -1,185 +0,0 @@ -/** - * Licensed to the Apache Software Foundation (ASF) under one - * or more contributor license agreements. See the NOTICE file - * distributed with this work for additional information - * regarding copyright ownership. The ASF licenses this file - * to you under the Apache License, Version 2.0 (the - * "License"); you may not use this file except in compliance - * with the License. You may obtain a copy of the License at - * <p> - * http://www.apache.org/licenses/LICENSE-2.0 - * <p> - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ -package org.apache.hadoop.hdfs; - -import java.util.concurrent.TimeUnit; -import java.util.concurrent.atomic.AtomicLong; -import java.util.concurrent.locks.Condition; -import java.util.concurrent.locks.Lock; -import java.util.concurrent.locks.ReentrantLock; - -import org.apache.hadoop.classification.InterfaceAudience; -import org.apache.hadoop.classification.InterfaceStability; -import org.apache.commons.logging.Log; -import org.apache.hadoop.util.StringUtils; -import org.apache.hadoop.util.Timer; - -import com.google.common.annotations.VisibleForTesting; - -/** - * This is a debugging class that can be used by callers to track - * whether a specifc lock is being held for too long and periodically - * log a warning and stack trace, if so. - * - * The logged warnings are throttled so that logs are not spammed. - * - * A new instance of InstrumentedLock can be created for each object - * that needs to be instrumented. - */ -@InterfaceAudience.Private -@InterfaceStability.Unstable -public class InstrumentedLock implements Lock { - - private final Lock lock; - private final Log logger; - private final String name; - private final Timer clock; - - /** Minimum gap between two lock warnings. */ - private final long minLoggingGap; - /** Threshold for detecting long lock held time. */ - private final long lockWarningThreshold; - - // Tracking counters for lock statistics. - private volatile long lockAcquireTimestamp; - private final AtomicLong lastLogTimestamp; - private final AtomicLong warningsSuppressed = new AtomicLong(0); - - /** - * Create a instrumented lock instance which logs a warning message - * when lock held time is above given threshold. - * - * @param name the identifier of the lock object - * @param logger this class does not have its own logger, will log to the - * given logger instead - * @param minLoggingGapMs the minimum time gap between two log messages, - * this is to avoid spamming to many logs - * @param lockWarningThresholdMs the time threshold to view lock held - * time as being "too long" - */ - public InstrumentedLock(String name, Log logger, long minLoggingGapMs, - long lockWarningThresholdMs) { - this(name, logger, new ReentrantLock(), - minLoggingGapMs, lockWarningThresholdMs); - } - - public InstrumentedLock(String name, Log logger, Lock lock, - long minLoggingGapMs, long lockWarningThresholdMs) { - this(name, logger, lock, - minLoggingGapMs, lockWarningThresholdMs, new Timer()); - } - - @VisibleForTesting - InstrumentedLock(String name, Log logger, Lock lock, - long minLoggingGapMs, long lockWarningThresholdMs, Timer clock) { - this.name = name; - this.lock = lock; - this.clock = clock; - this.logger = logger; - minLoggingGap = minLoggingGapMs; - lockWarningThreshold = lockWarningThresholdMs; - lastLogTimestamp = new AtomicLong( - clock.monotonicNow() - Math.max(minLoggingGap, lockWarningThreshold)); - } - - @Override - public void lock() { - lock.lock(); - lockAcquireTimestamp = clock.monotonicNow(); - } - - @Override - public void lockInterruptibly() throws InterruptedException { - lock.lockInterruptibly(); - lockAcquireTimestamp = clock.monotonicNow(); - } - - @Override - public boolean tryLock() { - if (lock.tryLock()) { - lockAcquireTimestamp = clock.monotonicNow(); - return true; - } - return false; - } - - @Override - public boolean tryLock(long time, TimeUnit unit) throws InterruptedException { - if (lock.tryLock(time, unit)) { - lockAcquireTimestamp = clock.monotonicNow(); - return true; - } - return false; - } - - @Override - public void unlock() { - long localLockReleaseTime = clock.monotonicNow(); - long localLockAcquireTime = lockAcquireTimestamp; - lock.unlock(); - check(localLockAcquireTime, localLockReleaseTime); - } - - @Override - public Condition newCondition() { - return lock.newCondition(); - } - - @VisibleForTesting - void logWarning(long lockHeldTime, long suppressed) { - logger.warn(String.format("Lock held time above threshold: " + - "lock identifier: %s " + - "lockHeldTimeMs=%d ms. Suppressed %d lock warnings. " + - "The stack trace is: %s" , - name, lockHeldTime, suppressed, - StringUtils.getStackTrace(Thread.currentThread()))); - } - - /** - * Log a warning if the lock was held for too long. - * - * Should be invoked by the caller immediately AFTER releasing the lock. - * - * @param acquireTime - timestamp just after acquiring the lock. - * @param releaseTime - timestamp just before releasing the lock. - */ - private void check(long acquireTime, long releaseTime) { - if (!logger.isWarnEnabled()) { - return; - } - - final long lockHeldTime = releaseTime - acquireTime; - if (lockWarningThreshold - lockHeldTime < 0) { - long now; - long localLastLogTs; - do { - now = clock.monotonicNow(); - localLastLogTs = lastLogTimestamp.get(); - long deltaSinceLastLog = now - localLastLogTs; - // check should print log or not - if (deltaSinceLastLog - minLoggingGap < 0) { - warningsSuppressed.incrementAndGet(); - return; - } - } while (!lastLogTimestamp.compareAndSet(localLastLogTs, now)); - long suppressed = warningsSuppressed.getAndSet(0); - logWarning(lockHeldTime, suppressed); - } - } - -} http://git-wip-us.apache.org/repos/asf/hadoop/blob/c7ce6fdc/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/InstrumentedReentrantLock.java ---------------------------------------------------------------------- diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/InstrumentedReentrantLock.java b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/InstrumentedReentrantLock.java new file mode 100644 index 0000000..010571e --- /dev/null +++ b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/InstrumentedReentrantLock.java @@ -0,0 +1,195 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * <p> + * http://www.apache.org/licenses/LICENSE-2.0 + * <p> + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.hadoop.hdfs; + +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicLong; +import java.util.concurrent.locks.Condition; +import java.util.concurrent.locks.Lock; +import java.util.concurrent.locks.ReentrantLock; + +import org.apache.hadoop.classification.InterfaceAudience; +import org.apache.hadoop.classification.InterfaceStability; +import org.apache.commons.logging.Log; +import org.apache.hadoop.util.StringUtils; +import org.apache.hadoop.util.Timer; + +import com.google.common.annotations.VisibleForTesting; + +/** + * This is a debugging class that can be used by callers to track + * whether a specific lock is being held for too long and periodically + * log a warning and stack trace, if so. + * + * The logged warnings are throttled so that logs are not spammed. + * + * A new instance of InstrumentedLock can be created for each object + * that needs to be instrumented. + */ +@InterfaceAudience.Private +@InterfaceStability.Unstable +public class InstrumentedReentrantLock implements Lock { + + @VisibleForTesting + final ReentrantLock lock; + private final Log logger; + private final String name; + private final Timer clock; + + /** Minimum gap between two lock warnings. */ + private final long minLoggingGap; + /** Threshold for detecting long lock held time. */ + private final long lockWarningThreshold; + + // Tracking counters for lock statistics. + private volatile long lockAcquireTimestamp; + private final AtomicLong lastLogTimestamp; + private final AtomicLong warningsSuppressed = new AtomicLong(0); + + /** + * Create a instrumented lock instance which logs a warning message + * when lock held time is above given threshold. + * + * @param name the identifier of the lock object + * @param logger this class does not have its own logger, will log to the + * given logger instead + * @param minLoggingGapMs the minimum time gap between two log messages, + * this is to avoid spamming to many logs + * @param lockWarningThresholdMs the time threshold to view lock held + * time as being "too long" + */ + public InstrumentedReentrantLock( + String name, Log logger, long minLoggingGapMs, + long lockWarningThresholdMs) { + this(name, logger, new ReentrantLock(), + minLoggingGapMs, lockWarningThresholdMs); + } + + public InstrumentedReentrantLock( + String name, Log logger, ReentrantLock lock, + long minLoggingGapMs, long lockWarningThresholdMs) { + this(name, logger, lock, + minLoggingGapMs, lockWarningThresholdMs, new Timer()); + } + + @VisibleForTesting + InstrumentedReentrantLock( + String name, Log logger, ReentrantLock lock, + long minLoggingGapMs, long lockWarningThresholdMs, Timer clock) { + this.name = name; + this.lock = lock; + this.clock = clock; + this.logger = logger; + minLoggingGap = minLoggingGapMs; + lockWarningThreshold = lockWarningThresholdMs; + lastLogTimestamp = new AtomicLong( + clock.monotonicNow() - Math.max(minLoggingGap, lockWarningThreshold)); + } + + @Override + public void lock() { + lock.lock(); + if (lock.getHoldCount() == 1) { + lockAcquireTimestamp = clock.monotonicNow(); + } + } + + @Override + public void lockInterruptibly() throws InterruptedException { + lock.lockInterruptibly(); + if (lock.getHoldCount() == 1) { + lockAcquireTimestamp = clock.monotonicNow(); + } + } + + @Override + public boolean tryLock() { + if (lock.tryLock() && lock.getHoldCount() == 1) { + lockAcquireTimestamp = clock.monotonicNow(); + return true; + } + return false; + } + + @Override + public boolean tryLock(long time, TimeUnit unit) throws InterruptedException { + if (lock.tryLock(time, unit) && lock.getHoldCount() == 1) { + lockAcquireTimestamp = clock.monotonicNow(); + return true; + } + return false; + } + + @Override + public void unlock() { + final boolean needReport = (lock.getHoldCount() == 1); + long localLockReleaseTime = clock.monotonicNow(); + long localLockAcquireTime = lockAcquireTimestamp; + lock.unlock(); + if (needReport) { + check(localLockAcquireTime, localLockReleaseTime); + } + } + + @Override + public Condition newCondition() { + return lock.newCondition(); + } + + @VisibleForTesting + void logWarning(long lockHeldTime, long suppressed) { + logger.warn(String.format("Lock held time above threshold: " + + "lock identifier: %s " + + "lockHeldTimeMs=%d ms. Suppressed %d lock warnings. " + + "The stack trace is: %s" , + name, lockHeldTime, suppressed, + StringUtils.getStackTrace(Thread.currentThread()))); + } + + /** + * Log a warning if the lock was held for too long. + * + * Should be invoked by the caller immediately AFTER releasing the lock. + * + * @param acquireTime - timestamp just after acquiring the lock. + * @param releaseTime - timestamp just before releasing the lock. + */ + private void check(long acquireTime, long releaseTime) { + if (!logger.isWarnEnabled()) { + return; + } + + final long lockHeldTime = releaseTime - acquireTime; + if (lockWarningThreshold - lockHeldTime < 0) { + long now; + long localLastLogTs; + do { + now = clock.monotonicNow(); + localLastLogTs = lastLogTimestamp.get(); + long deltaSinceLastLog = now - localLastLogTs; + // check should print log or not + if (deltaSinceLastLog - minLoggingGap < 0) { + warningsSuppressed.incrementAndGet(); + return; + } + } while (!lastLogTimestamp.compareAndSet(localLastLogTs, now)); + long suppressed = warningsSuppressed.getAndSet(0); + logWarning(lockHeldTime, suppressed); + } + } +} http://git-wip-us.apache.org/repos/asf/hadoop/blob/c7ce6fdc/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/datanode/fsdataset/impl/FsDatasetImpl.java ---------------------------------------------------------------------- diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/datanode/fsdataset/impl/FsDatasetImpl.java b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/datanode/fsdataset/impl/FsDatasetImpl.java index 26a2e9f..ab31f25 100644 --- a/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/datanode/fsdataset/impl/FsDatasetImpl.java +++ b/hadoop-hdfs-project/hadoop-hdfs/src/main/java/org/apache/hadoop/hdfs/server/datanode/fsdataset/impl/FsDatasetImpl.java @@ -58,7 +58,7 @@ import org.apache.hadoop.fs.StorageType; import org.apache.hadoop.hdfs.DFSConfigKeys; import org.apache.hadoop.hdfs.DFSUtilClient; import org.apache.hadoop.hdfs.ExtendedBlockId; -import org.apache.hadoop.hdfs.InstrumentedLock; +import org.apache.hadoop.hdfs.InstrumentedReentrantLock; import org.apache.hadoop.util.AutoCloseableLock; import org.apache.hadoop.hdfs.protocol.Block; import org.apache.hadoop.hdfs.protocol.BlockListAsLongs; @@ -266,7 +266,7 @@ class FsDatasetImpl implements FsDatasetSpi<FsVolumeImpl> { this.conf = conf; this.smallBufferSize = DFSUtilClient.getSmallBufferSize(conf); this.datasetLock = new AutoCloseableLock( - new InstrumentedLock(getClass().getName(), LOG, + new InstrumentedReentrantLock(getClass().getName(), LOG, conf.getTimeDuration( DFSConfigKeys.DFS_LOCK_SUPPRESS_WARNING_INTERVAL_KEY, DFSConfigKeys.DFS_LOCK_SUPPRESS_WARNING_INTERVAL_DEFAULT, http://git-wip-us.apache.org/repos/asf/hadoop/blob/c7ce6fdc/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/TestInstrumentedLock.java ---------------------------------------------------------------------- diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/TestInstrumentedLock.java b/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/TestInstrumentedLock.java deleted file mode 100644 index f470688..0000000 --- a/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/TestInstrumentedLock.java +++ /dev/null @@ -1,166 +0,0 @@ -/** - * Licensed to the Apache Software Foundation (ASF) under one - * or more contributor license agreements. See the NOTICE file - * distributed with this work for additional information - * regarding copyright ownership. The ASF licenses this file - * to you under the Apache License, Version 2.0 (the - * "License"); you may not use this file except in compliance - * with the License. You may obtain a copy of the License at - * <p> - * http://www.apache.org/licenses/LICENSE-2.0 - * <p> - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ -package org.apache.hadoop.hdfs; - -import java.util.concurrent.atomic.AtomicLong; -import java.util.concurrent.atomic.AtomicReference; -import java.util.concurrent.locks.Lock; - -import org.apache.hadoop.util.AutoCloseableLock; -import org.apache.hadoop.util.Timer; - -import org.apache.commons.logging.Log; -import org.apache.commons.logging.LogFactory; - -import org.junit.Rule; -import org.junit.Test; -import org.junit.rules.TestName; -import static org.mockito.Mockito.*; -import static org.junit.Assert.*; - -/** - * A test class for InstrumentedLock. - */ -public class TestInstrumentedLock { - - static final Log LOG = LogFactory.getLog(TestInstrumentedLock.class); - - @Rule public TestName name = new TestName(); - - /** - * Test exclusive access of the lock. - * @throws Exception - */ - @Test(timeout=10000) - public void testMultipleThread() throws Exception { - String testname = name.getMethodName(); - InstrumentedLock lock = new InstrumentedLock(testname, LOG, 0, 300); - lock.lock(); - try { - Thread competingThread = new Thread() { - @Override - public void run() { - assertFalse(lock.tryLock()); - } - }; - competingThread.start(); - competingThread.join(); - } finally { - lock.unlock(); - } - } - - /** - * Test the correctness with try-with-resource syntax. - * @throws Exception - */ - @Test(timeout=10000) - public void testTryWithResourceSyntax() throws Exception { - String testname = name.getMethodName(); - final AtomicReference<Thread> lockThread = new AtomicReference<>(null); - Lock lock = new InstrumentedLock(testname, LOG, 0, 300) { - @Override - public void lock() { - super.lock(); - lockThread.set(Thread.currentThread()); - } - @Override - public void unlock() { - super.unlock(); - lockThread.set(null); - } - }; - AutoCloseableLock acl = new AutoCloseableLock(lock); - try (AutoCloseable localLock = acl.acquire()) { - assertEquals(acl, localLock); - Thread competingThread = new Thread() { - @Override - public void run() { - assertNotEquals(Thread.currentThread(), lockThread.get()); - assertFalse(lock.tryLock()); - } - }; - competingThread.start(); - competingThread.join(); - assertEquals(Thread.currentThread(), lockThread.get()); - } - assertNull(lockThread.get()); - } - - /** - * Test the lock logs warning when lock held time is greater than threshold - * and not log warning otherwise. - * @throws Exception - */ - @Test(timeout=10000) - public void testLockLongHoldingReport() throws Exception { - String testname = name.getMethodName(); - final AtomicLong time = new AtomicLong(0); - Timer mclock = new Timer() { - @Override - public long monotonicNow() { - return time.get(); - } - }; - Lock mlock = mock(Lock.class); - - final AtomicLong wlogged = new AtomicLong(0); - final AtomicLong wsuppresed = new AtomicLong(0); - InstrumentedLock lock = new InstrumentedLock( - testname, LOG, mlock, 2000, 300, mclock) { - @Override - void logWarning(long lockHeldTime, long suppressed) { - wlogged.incrementAndGet(); - wsuppresed.set(suppressed); - } - }; - - // do not log warning when the lock held time is short - lock.lock(); // t = 0 - time.set(200); - lock.unlock(); // t = 200 - assertEquals(0, wlogged.get()); - assertEquals(0, wsuppresed.get()); - - lock.lock(); // t = 200 - time.set(700); - lock.unlock(); // t = 700 - assertEquals(1, wlogged.get()); - assertEquals(0, wsuppresed.get()); - - // despite the lock held time is greater than threshold - // suppress the log warning due to the logging gap - // (not recorded in wsuppressed until next log message) - lock.lock(); // t = 700 - time.set(1100); - lock.unlock(); // t = 1100 - assertEquals(1, wlogged.get()); - assertEquals(0, wsuppresed.get()); - - // log a warning message when the lock held time is greater the threshold - // and the logging time gap is satisfied. Also should display suppressed - // previous warnings. - time.set(2400); - lock.lock(); // t = 2400 - time.set(2800); - lock.unlock(); // t = 2800 - assertEquals(2, wlogged.get()); - assertEquals(1, wsuppresed.get()); - } - -} http://git-wip-us.apache.org/repos/asf/hadoop/blob/c7ce6fdc/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/TestInstrumentedReentrantLock.java ---------------------------------------------------------------------- diff --git a/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/TestInstrumentedReentrantLock.java b/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/TestInstrumentedReentrantLock.java new file mode 100644 index 0000000..3374b8a --- /dev/null +++ b/hadoop-hdfs-project/hadoop-hdfs/src/test/java/org/apache/hadoop/hdfs/TestInstrumentedReentrantLock.java @@ -0,0 +1,177 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * <p> + * http://www.apache.org/licenses/LICENSE-2.0 + * <p> + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.hadoop.hdfs; + +import java.util.concurrent.atomic.AtomicLong; +import java.util.concurrent.atomic.AtomicReference; +import java.util.concurrent.locks.Lock; +import java.util.concurrent.locks.ReentrantLock; + +import org.apache.hadoop.util.AutoCloseableLock; +import org.apache.hadoop.util.FakeTimer; + +import org.apache.commons.logging.Log; +import org.apache.commons.logging.LogFactory; + +import org.junit.Rule; +import org.junit.Test; +import org.junit.rules.TestName; +import static org.mockito.Mockito.*; +import static org.junit.Assert.*; + +/** + * A test class for {@link InstrumentedReentrantLock}. + */ +public class TestInstrumentedReentrantLock { + + static final Log LOG = LogFactory.getLog(TestInstrumentedReentrantLock.class); + + @Rule public TestName name = new TestName(); + + /** + * Test exclusive access of the lock. + * @throws Exception + */ + @Test(timeout=10000) + public void testMultipleThread() throws Exception { + String testname = name.getMethodName(); + InstrumentedReentrantLock lock = + new InstrumentedReentrantLock(testname, LOG, 0, 300); + lock.lock(); + try { + Thread competingThread = new Thread() { + @Override + public void run() { + assertFalse(lock.tryLock()); + } + }; + competingThread.start(); + competingThread.join(); + } finally { + lock.unlock(); + } + } + + /** + * Test the correctness with try-with-resource syntax. + * @throws Exception + */ + @Test(timeout=10000) + public void testTryWithResourceSyntax() throws Exception { + String testname = name.getMethodName(); + final AtomicReference<Thread> lockThread = new AtomicReference<>(null); + Lock lock = new InstrumentedReentrantLock(testname, LOG, 0, 300) { + @Override + public void lock() { + super.lock(); + lockThread.set(Thread.currentThread()); + } + @Override + public void unlock() { + super.unlock(); + lockThread.set(null); + } + }; + AutoCloseableLock acl = new AutoCloseableLock(lock); + try (AutoCloseable localLock = acl.acquire()) { + assertEquals(acl, localLock); + Thread competingThread = new Thread() { + @Override + public void run() { + assertNotEquals(Thread.currentThread(), lockThread.get()); + assertFalse(lock.tryLock()); + } + }; + competingThread.start(); + competingThread.join(); + assertEquals(Thread.currentThread(), lockThread.get()); + } + assertNull(lockThread.get()); + } + + /** + * Test the lock logs warning when lock held time is greater than threshold + * and not log warning otherwise. + * @throws Exception + */ + @Test(timeout=10000) + public void testLockLongHoldingReport() throws Exception { + String testname = name.getMethodName(); + FakeTimer mclock = new FakeTimer(); + final int warningThreshold = 500; + final int minLoggingGap = warningThreshold * 10; + + final AtomicLong wlogged = new AtomicLong(0); + final AtomicLong wsuppresed = new AtomicLong(0); + InstrumentedReentrantLock lock = new InstrumentedReentrantLock( + testname, LOG, new ReentrantLock(), minLoggingGap, + warningThreshold, mclock) { + @Override + void logWarning(long lockHeldTime, long suppressed) { + wlogged.incrementAndGet(); + wsuppresed.set(suppressed); + } + }; + + // do not log warning when the lock held time is <= warningThreshold. + lock.lock(); + mclock.advance(warningThreshold); + lock.unlock(); + assertEquals(0, wlogged.get()); + assertEquals(0, wsuppresed.get()); + + // log a warning when the lock held time exceeds the threshold. + lock.lock(); + mclock.advance(warningThreshold + 1); + assertEquals(1, lock.lock.getHoldCount()); + lock.unlock(); + assertEquals(1, wlogged.get()); + assertEquals(0, wsuppresed.get()); + + // despite the lock held time is greater than threshold + // suppress the log warning due to the logging gap + // (not recorded in wsuppressed until next log message) + lock.lock(); + mclock.advance(warningThreshold + 1); + lock.unlock(); + assertEquals(1, wlogged.get()); + assertEquals(0, wsuppresed.get()); + + // log a warning message when the lock held time is greater the threshold + // and the logging time gap is satisfied. Also should display suppressed + // previous warnings. + lock.lock(); + mclock.advance(minLoggingGap + 1); + lock.unlock(); // t = 2800 + assertEquals(2, wlogged.get()); + assertEquals(1, wsuppresed.get()); + + // Ensure that nested acquisitions do not log. + wlogged.set(0); + wsuppresed.set(0); + lock.lock(); + lock.lock(); + mclock.advance(minLoggingGap + 1); + lock.unlock(); + assertEquals(0, wlogged.get()); // No warnings on nested release. + assertEquals(0, wsuppresed.get()); + lock.unlock(); + assertEquals(1, wlogged.get()); // Last release immediately logs. + assertEquals(0, wsuppresed.get()); + } +} --------------------------------------------------------------------- To unsubscribe, e-mail: common-commits-unsubscr...@hadoop.apache.org For additional commands, e-mail: common-commits-h...@hadoop.apache.org