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 public TestHandler() { 57 // Each instance uses its own logger 58 logger = java.util.logging.Logger.getLogger("StackWalkBench" + serialNum.incrementAndGet()); 59 logger.setUseParentHandlers(false); 60 logger.addHandler(this); 61 } 62 63 @Override 64 public void publish(LogRecord record) { 65 record.getSourceMethodName(); 66 this.record = record; 67 } 68 69 private LogRecord reset() { 70 LogRecord record = this.record; 71 this.record = null; 72 return record; 73 } 74 75 public final LogRecord testInferCaller(String msg) { 76 logger.info(msg); 77 LogRecord rec = this.reset(); 78 if (!"testInferCaller".equals(rec.getSourceMethodName())) { 79 throw new RuntimeException("bad caller: " 80 + rec.getSourceClassName() + "." 81 + rec.getSourceMethodName()); 82 } 83 return rec; 84 } 85 86 public final LogRecord testLogp(String msg) { 87 logger.logp(java.util.logging.Level.INFO, "foo", "bar", msg); 88 LogRecord rec = this.reset(); 89 if (!"bar".equals(rec.getSourceMethodName())) { 90 throw new RuntimeException("bad caller: " 91 + rec.getSourceClassName() + "." 92 + rec.getSourceMethodName()); 93 } 94 return rec; 95 } 96 @Override public void flush() {} 97 @Override public void close() throws SecurityException {} 98 } 99 100 /** Build a call stack of a given size, then run trigger code in it. 101 * (Does not account for existing frames higher up in the JMH machinery). 102 */ 103 static class TestStack { 104 final long fence; 105 long current; 106 final Runnable trigger; 107 108 TestStack(long max, Runnable trigger) { 109 this.fence = max; 110 this.current = 0; 111 this.trigger = trigger; 112 } 113 114 public void start() { 115 one(); 116 } 117 118 public void one() { 119 if (check()) { 120 two(); 121 } 122 } 123 124 void two() { 125 if (check()) { 126 three(); 127 } 128 } 129 130 private void three() { 131 if (check()) { 132 one(); 133 } 134 } 135 136 boolean check() { 137 if (++current == fence) { 138 trigger.run(); 139 return false; 140 } else { 141 return true; 142 } 143 } 144 } 145 146 @Benchmark 147 public void testLoggingInferCaller(TestHandler handler, Blackhole bh) { 148 final Blackhole localBH = bh; 149 final boolean[] done = {false}; 150 new TestStack(depth, new Runnable() { 151 public void run() { 152 localBH.consume(handler.testInferCaller("test")); 153 done[0] = true; 154 } 155 }).start(); 156 if (!done[0]) { 157 throw new RuntimeException(); 158 } 159 } 160 161 @Benchmark 162 public void testLoggingLogp(TestHandler handler, Blackhole bh) { 163 final Blackhole localBH = bh; 164 final boolean[] done = {false}; 165 new TestStack(depth, new Runnable() { 166 public void run() { 167 localBH.consume(handler.testLogp("test")); 168 done[0] = true; 169 } 170 }).start(); 171 if (!done[0]) { 172 throw new RuntimeException(); 173 } 174 } 175 }