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 }