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 }