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 }