Assert on total wait time in lock contention tests (async-profiler#1017)

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) : ""));
         }
     }
 }

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");
+    }
 }

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();
+    }
+}