1 /* 2 * Copyright (c) 2015, 2019, Oracle and/or its affiliates. All rights reserved. 3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 4 * 5 * This code is free software; you can redistribute it and/or modify it 6 * under the terms of the GNU General Public License version 2 only, as 7 * published by the Free Software Foundation. 8 * 9 * This code is distributed in the hope that it will be useful, but WITHOUT 10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 12 * version 2 for more details (a copy is included in the LICENSE file that 13 * accompanied this code). 14 * 15 * You should have received a copy of the GNU General Public License version 16 * 2 along with this work; if not, write to the Free Software Foundation, 17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. 18 * 19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA 20 * or visit www.oracle.com if you need additional information or have any 21 * questions. 22 */ 23 package org.openjdk.bench.java.util.logging; 24 25 import java.util.concurrent.TimeUnit; 26 import java.util.concurrent.atomic.AtomicInteger; 27 import java.util.logging.LogRecord; 28 import org.openjdk.jmh.annotations.Benchmark; 29 import org.openjdk.jmh.annotations.BenchmarkMode; 30 import org.openjdk.jmh.annotations.Mode; 31 import org.openjdk.jmh.annotations.OutputTimeUnit; 32 import org.openjdk.jmh.annotations.Param; 33 import org.openjdk.jmh.annotations.Scope; 34 import org.openjdk.jmh.annotations.State; 35 import org.openjdk.jmh.infra.Blackhole; 36 37 @State(value = Scope.Benchmark) 38 @BenchmarkMode(Mode.AverageTime) 39 @OutputTimeUnit(TimeUnit.NANOSECONDS) 40 public class LoggingRuntimeMicros { 41 42 // TestStack will add this number of calls to the call stack 43 @Param({"4", "100", "1000"}) 44 // For more thorough testing, consider: 45 // @Param({"4", "10", "100", "256", "1000"}) 46 public int depth; 47 48 /** Logging handler for testing logging calls. */ 49 @State(value = Scope.Thread) // create a separate one for each worker thread 50 public static class TestHandler extends java.util.logging.Handler { 51 private final static AtomicInteger serialNum = new AtomicInteger(0); 52 53 private final java.util.logging.Logger logger; 54 private volatile LogRecord record; 55 56 @SuppressWarnings("initialization") 57 public TestHandler() { 58 // Each instance uses its own logger 59 logger = java.util.logging.Logger.getLogger("StackWalkBench" + serialNum.incrementAndGet()); 60 logger.setUseParentHandlers(false); 61 logger.addHandler(this); 62 } 63 64 @Override 65 public void publish(LogRecord record) { 66 record.getSourceMethodName(); 67 this.record = record; 68 } 69 70 private LogRecord reset() { 71 LogRecord record = this.record; 72 this.record = null; 73 return record; 74 } 75 76 public final LogRecord testInferCaller(String msg) { 77 logger.info(msg); 78 LogRecord rec = this.reset(); 79 if (!"testInferCaller".equals(rec.getSourceMethodName())) { 80 throw new RuntimeException("bad caller: " 81 + rec.getSourceClassName() + "." 82 + rec.getSourceMethodName()); 83 } 84 return rec; 85 } 86 87 public final LogRecord testLogp(String msg) { 88 logger.logp(java.util.logging.Level.INFO, "foo", "bar", msg); 89 LogRecord rec = this.reset(); 90 if (!"bar".equals(rec.getSourceMethodName())) { 91 throw new RuntimeException("bad caller: " 92 + rec.getSourceClassName() + "." 93 + rec.getSourceMethodName()); 94 } 95 return rec; 96 } 97 @Override public void flush() {} 98 @Override public void close() throws SecurityException {} 99 } 100 101 /** Build a call stack of a given size, then run trigger code in it. 102 * (Does not account for existing frames higher up in the JMH machinery). 103 */ 104 static class TestStack { 105 final long fence; 106 long current; 107 final Runnable trigger; 108 109 TestStack(long max, Runnable trigger) { 110 this.fence = max; 111 this.current = 0; 112 this.trigger = trigger; 113 } 114 115 public void start() { 116 one(); 117 } 118 119 public void one() { 120 if (check()) { 121 two(); 122 } 123 } 124 125 void two() { 126 if (check()) { 127 three(); 128 } 129 } 130 131 private void three() { 132 if (check()) { 133 one(); 134 } 135 } 136 137 boolean check() { 138 if (++current == fence) { 139 trigger.run(); 140 return false; 141 } else { 142 return true; 143 } 144 } 145 } 146 147 @Benchmark 148 public void testLoggingInferCaller(TestHandler handler, Blackhole bh) { 149 final Blackhole localBH = bh; 150 final boolean[] done = {false}; 151 new TestStack(depth, new Runnable() { 152 public void run() { 153 localBH.consume(handler.testInferCaller("test")); 154 done[0] = true; 155 } 156 }).start(); 157 if (!done[0]) { 158 throw new RuntimeException(); 159 } 160 } 161 162 @Benchmark 163 public void testLoggingLogp(TestHandler handler, Blackhole bh) { 164 final Blackhole localBH = bh; 165 final boolean[] done = {false}; 166 new TestStack(depth, new Runnable() { 167 public void run() { 168 localBH.consume(handler.testLogp("test")); 169 done[0] = true; 170 } 171 }).start(); 172 if (!done[0]) { 173 throw new RuntimeException(); 174 } 175 } 176 }