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 }