diff --git a/test/one/profiler/test/Assert.java b/test/one/profiler/test/Assert.java index 2b8ca0bb8..e29f6389a 100644 --- a/test/one/profiler/test/Assert.java +++ b/test/one/profiler/test/Assert.java @@ -5,17 +5,37 @@ package one.profiler.test; +import java.util.logging.Level; +import java.util.logging.Logger; + public class Assert { + private static final Logger log = Logger.getLogger(Assert.class.getName()); public static void isGreater(double value, double threshold) { - if (value < threshold) { - throw new AssertionError("Expected " + value + " > " + threshold); + isGreater(value, threshold, null); + } + + public static void isGreater(double value, double threshold, String message) { + boolean asserted = value <= threshold; + log.log(Level.FINE, "isGreater (asserted: " + asserted + ") " + (message == null ? "" : message) + ": " + value + " > " + threshold); + + if (asserted) { + throw new AssertionError( + "Expected " + value + " > " + threshold + (message != null ? (": " + message) : "")); } } public static void isLess(double value, double threshold) { - if (value > threshold) { - throw new AssertionError("Expected " + value + " < " + threshold); + isLess(value, threshold, null); + } + + public static void isLess(double value, double threshold, String message) { + boolean asserted = value >= threshold; + log.log(Level.FINE, "isLess (asserted: " + asserted + ")" + (message == null ? "" : message) + ": " + value + " < " + threshold); + + if (asserted) { + throw new AssertionError( + "Expected " + value + " < " + threshold + (message != null ? (": " + message) : "")); } } } diff --git a/test/test/lock/LockProfiling.java b/test/test/lock/LockProfiling.java deleted file mode 100644 index 19cf19ece..000000000 --- a/test/test/lock/LockProfiling.java +++ /dev/null @@ -1,86 +0,0 @@ -/* - * Copyright The async-profiler authors - * SPDX-License-Identifier: Apache-2.0 - */ - -package test.lock; - -import java.util.concurrent.ThreadLocalRandom; -import java.util.concurrent.locks.LockSupport; -import java.util.concurrent.ConcurrentHashMap; -import java.util.Map; - -public class LockProfiling { - static final int timeOutsideLock = 1_000_000; // 1 ms - static final ThreadLocal totalUsefulWork = ThreadLocal.withInitial(() -> 0.0); - static final ThreadLocal totalWait = ThreadLocal.withInitial(() -> 0.0); - static volatile boolean exitRequested = false; - - static final Map totalUsefulWorksMs = new ConcurrentHashMap<>(); - static final Map totalWaitsMs = new ConcurrentHashMap<>(); - - public static void main(String[] args) throws InterruptedException { - Thread[] c1 = contend(0.05); - Thread[] c2 = contend(0.5); - - Thread.sleep(2 * 1000); - exitRequested = true; - - for (Thread t : c1) { - t.join(); - } - for (Thread t : c2) { - t.join(); - } - } - - static Thread[] contend(double fraction) { - Object lock = new Object(); - - long timeUnderLockNs = (long) ((fraction * timeOutsideLock) / (1 - fraction)); - - Thread t1 = new Thread(() -> contend(timeUnderLockNs, timeOutsideLock, lock), - "contend-" + fraction + "-t1"); - t1.start(); - - Thread t2 = new Thread(() -> contend(timeUnderLockNs, timeOutsideLock, lock), - "contend-" + fraction + "-t2"); - t2.start(); - - return new Thread[] { t1, t2 }; - } - - static void usefulWork(long ns) { - LockSupport.parkNanos(ns); - totalUsefulWork.set(totalUsefulWork.get() + ns); - } - - static void contend(long timeUnderLockNs, long timeOutsideLock, Object lock) { - while (!exitRequested) { - long start = System.nanoTime(); - long delay = ThreadLocalRandom.current().nextLong(0, timeOutsideLock); - - usefulWork(delay); - synchronized (lock) { - usefulWork(timeUnderLockNs); - } - usefulWork(timeOutsideLock - delay); - - long duration = System.nanoTime() - start; - long wait = duration - timeUnderLockNs - timeOutsideLock; - totalWait.set(totalWait.get() + wait); - } - - String name = Thread.currentThread().getName(); - totalUsefulWorksMs.put(name, totalUsefulWork.get() / 1e6); - totalWaitsMs.put(name, totalWait.get() / 1e6); - } - - public static double parseNameForFraction(String name) { - String prefix = "contend-"; - int start = name.indexOf(prefix) + prefix.length(); - int end = name.indexOf("-t"); - - return Double.parseDouble(name.substring(start, end)); - } -} diff --git a/test/test/lock/LockTests.java b/test/test/lock/LockTests.java index e2a4e5fce..ae6152ebf 100644 --- a/test/test/lock/LockTests.java +++ b/test/test/lock/LockTests.java @@ -5,41 +5,12 @@ package test.lock; +import one.profiler.test.Assert; import one.profiler.test.Output; import one.profiler.test.Test; import one.profiler.test.TestProcess; public class LockTests { - private static void contendedLocks(TestProcess p, int interval, double minRatio) throws Exception { - Output out = p.profile("--lock " + interval + " --threads -o collapsed"); - Output waitingLocks = out.filter("LockProfiling\\.contend;java\\.lang\\.Object"); - - double ratio = 100 * out.ratio("contend-0.5-", "contend-0.05-"); - - System.out.println("interval = " + interval + ", ratio = " + ratio + ", minRatio = " + minRatio); - - assert (ratio >= minRatio) || (Double.isNaN(ratio) && Double.isNaN(minRatio)); - } - - // 0 is equivalent to disabling sampling of locks, so all profiles are included. - - // Disable tests for now - @Test(mainClass = LockProfiling.class, inputs = { "0", "70" }, enabled = false) - @Test(mainClass = LockProfiling.class, inputs = { "10000", "70" }, enabled = false) - - // Large (for the specific paylod) interval value skews the sampled lock - // contention distribution. - @Test(mainClass = LockProfiling.class, inputs = { "1000000", "90" }, enabled = false) - - // Very large interval causes all profiles be dropped. - @Test(mainClass = LockProfiling.class, inputs = { "1000000000", "NaN" }, enabled = false) - public void contendedLocks(TestProcess p) throws Exception { - int interval = Integer.parseInt(p.inputs()[0]); - double minRatio = Double.parseDouble(p.inputs()[1]); - - contendedLocks(p, interval, minRatio); - } - @Test(mainClass = DatagramTest.class, debugNonSafepoints = true) // Fails on Alpine public void datagramSocketLock(TestProcess p) throws Exception { Output out = p.profile("-e cpu -d 3 -o collapsed --cstack dwarf"); @@ -48,4 +19,26 @@ public void datagramSocketLock(TestProcess p) throws Exception { out = p.profile("-e lock -d 3 -o collapsed"); assert out.samples("sun/nio/ch/DatagramChannelImpl.send") > 10; } + + @Test(mainClass = RaceToLock.class, inputs = { "0" }, output = true) + @Test(mainClass = RaceToLock.class, inputs = { "10000" }, output = true) + @Test(mainClass = RaceToLock.class, inputs = { "1000000" }, output = true) + public void raceToLocks(TestProcess p) throws Exception { + int interval = Integer.parseInt(p.inputs()[0]); + + Output out = p.profile("--lock " + interval + " --threads -o collapsed"); + Output stdout = p.readFile(TestProcess.STDOUT); + long shared1 = out.samples("\\[shared1"); + long shared2 = out.samples("\\[shared2"); + + Assert.isGreater(out.samples("\\[random1"), 0, "sampled all threads 1/4"); + Assert.isGreater(out.samples("\\[random2"), 0, "sampled all threads 2/4"); + Assert.isGreater(shared1, 0, "sampled all threads 3/4"); + Assert.isGreater(shared2, 0, "sampled all threads 4/4"); + + double sharedDiff = 1.0 * Math.abs(shared1 - shared2) / Math.max(shared1, shared2); + + Assert.isLess(sharedDiff, 0.15, "sharedDiff < 0.15"); + Assert.isGreater(stdout.samples("sharedWaitTime"), stdout.samples("randomWaitTime"), "sharedWaitTime > randomWaitTime"); + } } diff --git a/test/test/lock/RaceToLock.java b/test/test/lock/RaceToLock.java new file mode 100644 index 000000000..17872852d --- /dev/null +++ b/test/test/lock/RaceToLock.java @@ -0,0 +1,88 @@ +/* + * Copyright The async-profiler authors + * SPDX-License-Identifier: Apache-2.0 + */ + +package test.lock; + +import java.util.concurrent.locks.Lock; +import java.util.concurrent.locks.ReentrantLock; +import java.util.concurrent.locks.LockSupport; +import java.util.ArrayList; +import java.util.List; +import java.util.Random; + +public class RaceToLock { + + private final Lock sharedLock = new ReentrantLock(true); + private final Object sharedObj = new Object(); + private long sharedWaitTime = 0; + + private final Random random = new Random(); + private final Lock lock1 = new ReentrantLock(true); + private final Lock lock2 = new ReentrantLock(true); + private volatile long randomWaitTime; + + private volatile boolean exitRequested; + + private void doWork() { + LockSupport.parkNanos(1); + } + + private void runSharedCounter() { + while (!exitRequested) { + long start = System.nanoTime(); + sharedLock.lock(); + sharedWaitTime += System.nanoTime() - start; + + try { + doWork(); + } finally { + sharedLock.unlock(); + } + } + } + + private void runRandomCounter() { + while (!exitRequested) { + Lock lock = random.nextBoolean() ? lock1 : lock2; + + long start = System.nanoTime(); + lock.lock(); + randomWaitTime += System.nanoTime() - start; + try { + doWork(); + } finally { + lock.unlock(); + } + } + } + + public void dump() { + // Referred to from tests. + System.out.println("sharedWaitTime: " + sharedWaitTime); + System.out.println("randomWaitTime: " + randomWaitTime); + } + + public static void main(String[] args) throws InterruptedException { + RaceToLock app = new RaceToLock(); + Thread[] threads = { + new Thread(null, app::runSharedCounter, "shared1"), + new Thread(null, app::runSharedCounter, "shared2"), + + new Thread(null, app::runRandomCounter, "random1"), + new Thread(null, app::runRandomCounter, "random2") + }; + for (Thread t : threads) { + t.start(); + } + + Thread.sleep(2000); + app.exitRequested = true; + for (Thread t : threads) { + t.join(); + } + + app.dump(); + } +}