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 }