8150865: SQE test: GC unified logging: check that dynamic log level doesn't break anything
authorkzhaldyb
Tue, 10 May 2016 21:23:33 +0300
changeset 38275 38582fe9500f
parent 38272 6c2e34a19f10
child 38276 5abf2a76e337
8150865: SQE test: GC unified logging: check that dynamic log level doesn't break anything Reviewed-by: jwilhelm, dfazunen
hotspot/test/TEST.groups
hotspot/test/gc/logging/TestUnifiedLoggingSwitchStress.java
--- a/hotspot/test/TEST.groups	Tue May 10 18:30:03 2016 +0200
+++ b/hotspot/test/TEST.groups	Tue May 10 21:23:33 2016 +0300
@@ -338,6 +338,7 @@
   sanity/ExecuteInternalVMTests.java \
   gc/ \
   -gc/g1/ \
+  -gc/logging/TestUnifiedLoggingSwitchStress.java \
   -gc/stress \
   -gc/survivorAlignment/TestPromotionFromSurvivorToTenuredAfterMinorGC.java \
   -gc/cms/TestMBeanCMS.java \
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/test/gc/logging/TestUnifiedLoggingSwitchStress.java	Tue May 10 21:23:33 2016 +0300
@@ -0,0 +1,245 @@
+/*
+ * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ *
+ */
+
+package gc.logging;
+
+import jdk.test.lib.Utils;
+
+import javax.management.InstanceNotFoundException;
+import javax.management.MBeanException;
+import javax.management.MBeanServer;
+import javax.management.MalformedObjectNameException;
+import javax.management.ObjectName;
+import javax.management.ReflectionException;
+import java.lang.management.ManagementFactory;
+import java.util.LinkedList;
+import java.util.List;
+import java.util.Random;
+
+
+/**
+ * @test TestUnifiedLoggingSwitchStress
+ * @summary Switches gc log level on fly while stressing memory/gc
+ * @key gc
+ * @key stress
+ * @library /testlibrary /test/lib /
+ * @modules java.management java.base/jdk.internal.misc
+ *
+ * @run main/othervm -Xmx256M -Xms256M
+ *                   gc.logging.TestUnifiedLoggingSwitchStress 60
+ */
+
+class MemoryStresser implements Runnable {
+    public static volatile boolean shouldStop = false;
+
+    private final List<byte[]> liveObjects = new LinkedList<>();
+    private final List<byte[]> liveHObjects = new LinkedList<>();
+    private int maxSimpleAllocationMemory = 0;
+    private int usedMemory = 0;
+
+    /**
+     * Maximum amount of huge allocations
+     */
+    private static int H_ALLOCATION_MAX_COUNT = 4;
+    /**
+     * Maximum regions in one huge allocation
+     */
+    private static int H_ALLOCATION_REGION_SIZE = 2;
+    private static final int G1_REGION_SIZE = 1024 * 1024;
+    /**
+     * Maximum size of simple allocation
+     */
+    private static final int MAX_SIMPLE_ALLOCATION_SIZE = (int) (G1_REGION_SIZE / 2 * 0.9);
+
+    /**
+     * Maximum size of dead (i.e. one which is made unreachable right after allocation) object
+     */
+    private static final int DEAD_OBJECT_MAX_SIZE = G1_REGION_SIZE / 10;
+    private static final Random RND = Utils.getRandomInstance();
+
+    /**
+     * @param maxMemory maximum memory that could be allocated
+     */
+    public MemoryStresser(int maxMemory) {
+        maxSimpleAllocationMemory = maxMemory - G1_REGION_SIZE * H_ALLOCATION_MAX_COUNT * H_ALLOCATION_REGION_SIZE;
+    }
+
+    public final Runnable[] actions = new Runnable[]{
+            // Huge allocation
+            () -> {
+                if (liveHObjects.size() < H_ALLOCATION_MAX_COUNT) {
+                    int allocationSize = RND.nextInt((int) (G1_REGION_SIZE * (H_ALLOCATION_REGION_SIZE - 0.5)
+                            * 0.9));
+                    liveHObjects.add(new byte[allocationSize + G1_REGION_SIZE / 2]);
+                }
+            },
+
+            // Huge deallocation
+            () -> {
+                if (liveHObjects.size() > 0) {
+                    int elementNum = RND.nextInt(liveHObjects.size());
+                    liveHObjects.remove(elementNum);
+                }
+            },
+
+            // Simple allocation
+            () -> {
+                if (maxSimpleAllocationMemory - usedMemory != 0) {
+                    int arraySize = RND.nextInt(Math.min(maxSimpleAllocationMemory - usedMemory,
+                            MAX_SIMPLE_ALLOCATION_SIZE));
+                    if (arraySize != 0) {
+                        liveObjects.add(new byte[arraySize]);
+                        usedMemory += arraySize;
+                    }
+                }
+            },
+
+            // Simple deallocation
+            () -> {
+                if (liveObjects.size() != 0) {
+                    int elementNum = RND.nextInt(liveObjects.size());
+                    int shouldFree = liveObjects.get(elementNum).length;
+                    liveObjects.remove(elementNum);
+                    usedMemory -= shouldFree;
+                }
+            },
+
+            // Dead object allocation
+            () -> {
+                int size = RND.nextInt(DEAD_OBJECT_MAX_SIZE);
+                byte[] deadObject = new byte[size];
+            }
+    };
+
+    @Override
+    public void run() {
+        while (!shouldStop) {
+            actions[RND.nextInt(actions.length)].run();
+            Thread.yield();
+        }
+
+        System.out.println("Memory Stresser finished");
+    }
+}
+
+class LogLevelSwitcher implements Runnable {
+
+    public static volatile boolean shouldStop = false;
+    private final int logCount; // how many various log files will be used
+    private final String logFilePrefix; // name of log file will be logFilePrefix + index
+    private final Random RND = Utils.getRandomInstance();
+    private final MBeanServer MBS = ManagementFactory.getPlatformMBeanServer();
+
+    /**
+     * @param logFilePrefix prefix for log files
+     * @param logCount     amount of log files
+     */
+    public LogLevelSwitcher(String logFilePrefix, int logCount) {
+        this.logCount = logCount;
+        this.logFilePrefix = logFilePrefix;
+
+    }
+
+    private static final String[] LOG_LEVELS = {"error", "warning", "info", "debug", "trace"};
+
+    @Override
+    public void run() {
+
+        while (!shouldStop) {
+            int fileNum = RND.nextInt(logCount);
+            int logLevel = RND.nextInt(LOG_LEVELS.length);
+
+            String outputCommand = String.format("output=%s_%d.log", logFilePrefix, fileNum);
+            String logLevelCommand = "what='gc*=" + LOG_LEVELS[logLevel] + "'";
+
+            try {
+                Object out = MBS.invoke(new ObjectName("com.sun.management:type=DiagnosticCommand"),
+                                        "vmLog",
+                                        new Object[]{new String[]{outputCommand, logLevelCommand}},
+                                        new String[]{String[].class.getName()});
+
+                if (!out.toString().isEmpty()) {
+                    System.out.format("WARNING: Diagnostic command vmLog with arguments %s,%s returned not empty"
+                                    + " output %s\n",
+                            outputCommand, logLevelCommand, out);
+                }
+            } catch (InstanceNotFoundException | MBeanException | ReflectionException | MalformedObjectNameException e) {
+                System.out.println("Got exception trying to change log level:" + e);
+                e.printStackTrace();
+                throw new Error(e);
+            }
+            Thread.yield();
+        }
+        System.out.println("Log Switcher finished");
+    }
+}
+
+
+public class TestUnifiedLoggingSwitchStress {
+    /**
+     * Count of memory stressing threads
+     */
+    private static final int MEMORY_STRESSERS_COUNT = 3;
+    /**
+     * Count of log switching threads
+     */
+    private static final int LOG_LEVEL_SWITCHERS_COUNT = 2;
+    /**
+     * Count of log files created by each log switching thread
+     */
+    private static final int LOG_FILES_COUNT = 2;
+    /**
+     * Maximum amount memory allocated by each stressing thread
+     */
+    private static final int MAX_MEMORY_PER_STRESSER = (int) (Runtime.getRuntime().freeMemory()
+            / MEMORY_STRESSERS_COUNT * 0.7);
+
+    public static void main(String[] args) throws InterruptedException {
+        if (args.length != 1) {
+            throw new Error("Test Bug: Expected duration (in seconds) wasn't provided as command line argument");
+        }
+        long duration = Integer.parseInt(args[0]) * 1000;
+
+        long startTime = System.currentTimeMillis();
+
+        List<Thread> threads = new LinkedList<>();
+
+        for (int i = 0; i < LOG_LEVEL_SWITCHERS_COUNT; i++) {
+            threads.add(new Thread(new LogLevelSwitcher("Output_" + i, LOG_FILES_COUNT)));
+        }
+
+        for (int i = 0; i < MEMORY_STRESSERS_COUNT; i++) {
+            threads.add(new Thread(new MemoryStresser(MAX_MEMORY_PER_STRESSER)));
+        }
+
+        threads.stream().forEach(Thread::start);
+
+        while (System.currentTimeMillis() - startTime < duration) {
+            Thread.yield();
+        }
+
+        MemoryStresser.shouldStop = true;
+        LogLevelSwitcher.shouldStop = true;
+    }
+}