Merge pull request #50 from scalecube/feature/improve-logging

Improved logging, split by benchmark tests

Author: artem-v

.gitignore

@@ -24,6 +24,8 @@
 /reports
 */reports
 *.csv
+*.log
+*.zip
 
 # Mac-specific directory that no other operating system needs.
 .DS_Store

README.md

@@ -134,3 +134,6 @@ This method intends for execution asynchronous tasks with consumption some resou
 ```
 
 It's time to describe the settings in more detail. First, you can see two ramp-up parameters, these are `rampUpDuration` and `rampUpInterval`. They need to specify how long will be processing ramp-up stage and how often will be invoked the resource supplier to receive a new resource. Also, we have two parameters to specify how long will be processing all `unitOfWork`s on the given resource (`executionTaskDuration`) and with another one you can specify some interval that will be applied to invoke the next `unitOfWork` on the given resource (`executionTaskInterval`).
+
+## Additional links
+ + [How-to-launch-benchmarks](https://github.com/scalecube/scalecube-benchmarks/wiki/How-to-launch-benchmarks)

benchmarks-api/src/main/java/io/scalecube/benchmarks/BenchmarksSettings.java

@@ -24,7 +24,7 @@ public class BenchmarksSettings {
   private static final long NUM_OF_ITERATIONS = Long.MAX_VALUE;
   private static final Duration RAMP_UP_DURATION = Duration.ofSeconds(10);
   private static final Duration RAMP_UP_INTERVAL = Duration.ofSeconds(1);
-  private static final String ALIAS = "alias";
+  private static final boolean CONSOLE_REPORTER_ENABLED = true;
 
   private final int nThreads;
   private final Duration executionTaskDuration;
@@ -38,6 +38,7 @@ public class BenchmarksSettings {
   private final long numOfIterations;
   private final Duration rampUpDuration;
   private final Duration rampUpInterval;
+  private final boolean consoleReporterEnabled;
 
   private final Map<String, String> options;
 
@@ -51,23 +52,21 @@ private BenchmarksSettings(Builder builder) {
     this.executionTaskInterval = builder.executionTaskInterval;
     this.reporterInterval = builder.reporterInterval;
     this.numOfIterations = builder.numOfIterations;
-
+    this.consoleReporterEnabled = builder.consoleReporterEnabled;
     this.rampUpDuration = builder.rampUpDuration;
     this.rampUpInterval = builder.rampUpInterval;
-
     this.options = builder.options;
-
-    this.registry = new MetricRegistry();
-
     this.durationUnit = builder.durationUnit;
     this.rateUnit = builder.rateUnit;
 
+    this.registry = new MetricRegistry();
+
     StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
     this.taskName = minifyClassName(stackTrace[stackTrace.length - 1].getClassName());
 
     String time = LocalDateTime.ofInstant(Instant.now(), ZoneOffset.UTC)
         .format(DateTimeFormatter.ofPattern("yyyy-MM-dd-HH-mm-ss"));
-    this.csvReporterDirectory = Paths.get("benchmarks", "results", find(ALIAS, taskName), time).toFile();
+    this.csvReporterDirectory = Paths.get("benchmarks", "results", find("alias", taskName), time).toFile();
     // noinspection ResultOfMethodCallIgnored
     this.csvReporterDirectory.mkdirs();
   }
@@ -124,6 +123,10 @@ public Duration rampUpInterval() {
     return rampUpInterval;
   }
 
+  public boolean consoleReporterEnabled() {
+    return consoleReporterEnabled;
+  }
+
   @Override
   public String toString() {
     final StringBuilder sb = new StringBuilder("BenchmarksSettings{");
@@ -138,6 +141,7 @@ public String toString() {
     sb.append(", rateUnit=").append(rateUnit);
     sb.append(", rampUpDuration=").append(rampUpDuration);
     sb.append(", rampUpInterval=").append(rampUpInterval);
+    sb.append(", consoleReporterEnabled=").append(consoleReporterEnabled);
     sb.append(", registry=").append(registry);
     sb.append(", options=").append(options);
     sb.append('}');
@@ -160,6 +164,7 @@ public static class Builder {
     private long numOfIterations = NUM_OF_ITERATIONS;
     private Duration rampUpDuration = RAMP_UP_DURATION;
     private Duration rampUpInterval = RAMP_UP_INTERVAL;
+    private boolean consoleReporterEnabled = CONSOLE_REPORTER_ENABLED;
 
     public Builder from(String[] args) {
       this.parse(args);
@@ -218,6 +223,11 @@ public Builder rampUpInterval(Duration rampUpInterval) {
       return this;
     }
 
+    public Builder consoleReporterEnabled(boolean consoleReporterEnabled) {
+      this.consoleReporterEnabled = consoleReporterEnabled;
+      return this;
+    }
+
     public BenchmarksSettings build() {
       return new BenchmarksSettings(this);
     }
@@ -250,6 +260,9 @@ private void parse(String[] args) {
             case "rampUpIntervalInMillis":
               rampUpInterval(Duration.ofMillis(Long.parseLong(value)));
               break;
+            case "consoleReporterEnabled":
+              consoleReporterEnabled(Boolean.parseBoolean(value));
+              break;
             default:
               addOption(key, value);
               break;

benchmarks-api/src/main/java/io/scalecube/benchmarks/BenchmarksState.java

@@ -18,11 +18,14 @@
 import org.reactivestreams.Subscriber;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
+import org.slf4j.MDC;
 
 import java.time.Duration;
 import java.util.List;
+import java.util.Map;
 import java.util.concurrent.CountDownLatch;
 import java.util.concurrent.Executors;
+import java.util.concurrent.ThreadFactory;
 import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicBoolean;
 import java.util.function.BiFunction;
@@ -51,10 +54,12 @@ public class BenchmarksState<SELF extends BenchmarksState<SELF>> {
 
   private static final Logger LOGGER = LoggerFactory.getLogger(BenchmarksState.class);
 
+  private static final String MDC_BENCHMARK_DIR = "benchmarkDir";
+
   protected final BenchmarksSettings settings;
 
-  protected Scheduler scheduler;
-  protected List<Scheduler> schedulers;
+  private Scheduler scheduler;
+  private List<Scheduler> schedulers;
 
   private ConsoleReporter consoleReporter;
   private CsvReporter csvReporter;
@@ -81,25 +86,31 @@ public final void start() {
       throw new IllegalStateException("BenchmarksState is already started");
     }
 
+    MDC.put(MDC_BENCHMARK_DIR, settings.csvReporterDirectory().toString());
+
     LOGGER.info("Benchmarks settings: " + settings);
 
     settings.registry().register(settings.taskName() + "-memory", new MemoryUsageGaugeSet());
 
-    consoleReporter = ConsoleReporter.forRegistry(settings.registry())
-        .outputTo(System.out)
-        .convertDurationsTo(settings.durationUnit())
-        .convertRatesTo(settings.rateUnit())
-        .build();
+    if (settings.consoleReporterEnabled()) {
+      consoleReporter = ConsoleReporter.forRegistry(settings.registry())
+          .outputTo(System.out)
+          .convertDurationsTo(settings.durationUnit())
+          .convertRatesTo(settings.rateUnit())
+          .build();
+    }
 
     csvReporter = CsvReporter.forRegistry(settings.registry())
         .convertDurationsTo(settings.durationUnit())
         .convertRatesTo(settings.rateUnit())
         .build(settings.csvReporterDirectory());
 
-    scheduler = Schedulers.fromExecutor(Executors.newFixedThreadPool(settings.nThreads()));
+    scheduler = Schedulers.fromExecutor(
+        Executors.newFixedThreadPool(settings.nThreads(), newThreadFactory()));
 
     schedulers = IntStream.rangeClosed(1, settings.nThreads())
-        .mapToObj(i -> Schedulers.fromExecutorService(Executors.newSingleThreadScheduledExecutor()))
+        .mapToObj(i -> Schedulers.fromExecutorService(
+            Executors.newSingleThreadScheduledExecutor(newThreadFactory())))
         .collect(Collectors.toList());
 
     try {
@@ -108,16 +119,20 @@ public final void start() {
       throw new IllegalStateException("BenchmarksState beforeAll() failed: " + ex, ex);
     }
 
-    consoleReporter.start(settings.reporterInterval().toMillis(), TimeUnit.MILLISECONDS);
+    if (settings.consoleReporterEnabled()) {
+      consoleReporter.start(settings.reporterInterval().toMillis(), TimeUnit.MILLISECONDS);
+    }
+
     csvReporter.start(settings.reporterInterval().toMillis(), TimeUnit.MILLISECONDS);
 
     Runtime.getRuntime().addShutdownHook(new Thread(() -> {
       if (started.get()) {
         csvReporter.report();
-        consoleReporter.report();
+        if (consoleReporter != null) {
+          consoleReporter.report();
+        }
       }
     }));
-
   }
 
   /**
@@ -150,6 +165,8 @@ public final void shutdown() {
       afterAll();
     } catch (Exception ex) {
       throw new IllegalStateException("BenchmarksState afterAll() failed: " + ex, ex);
+    } finally {
+      MDC.remove(MDC_BENCHMARK_DIR);
     }
   }
 
@@ -321,4 +338,24 @@ public final <T> void runWithRampUp(
       self.shutdown();
     }
   }
+
+  private ThreadFactory newThreadFactory() {
+    return runnable -> {
+      Map<String, String> mdcCopy = MDC.getCopyOfContextMap();
+
+      return new Thread(runnable) {
+
+        private boolean mdcWasSet;
+
+        @Override
+        public void run() {
+          if (!mdcWasSet) {
+            MDC.setContextMap(mdcCopy);
+            mdcWasSet = true;
+          }
+          super.run();
+        }
+      };
+    };
+  }
 }

benchmarks-examples/src/main/resources/log4j2.xml

@@ -4,16 +4,48 @@
   <Properties>
     <Property name="patternLayout">%level{length=1} %d{ISO8601} %c{1.} %m [%t]%n</Property>
   </Properties>
+
   <Appenders>
-    <Console name="STDOUT" target="SYSTEM_OUT">
-      <PatternLayout pattern="${patternLayout}"/>
-    </Console>
+
+    <Routing name="separateBenchmarkLogs">
+      <Routes pattern="$${ctx:benchmarkDir}">
+        <!-- This route is chosen if ThreadContext has values for keys: benchmarkDir -->
+        <Route>
+          <RollingFile name="Rolling-${ctx:benchmarkDir}"
+                       fileName="${ctx:benchmarkDir}/benchmarks.log"
+                       filePattern="${ctx:benchmarkDir}/benchmarks-%d{yyyy-MM-dd-HH}-%i.log.zip"
+                       ignoreExceptions="false">
+            <PatternLayout pattern="${patternLayout}"/>
+            <Policies>
+              <TimeBasedTriggeringPolicy/>
+              <SizeBasedTriggeringPolicy size="50MB"/>
+            </Policies>
+            <DefaultRolloverStrategy max="1000"/>
+          </RollingFile>
+        </Route>
+
+        <!-- This route is chosen if ThreadContext has no value for keys: benchmarkDir -->
+        <Route key="$${ctx:benchmarkDir}">
+          <RollingFile name="Rolling-default"
+                       fileName="benchmarks/default.log"
+                       filePattern="benchmarks/default-%d{yyyy-MM-dd-HH}-%i.log.zip"
+                       ignoreExceptions="false">
+            <PatternLayout pattern="${patternLayout}"/>
+            <Policies>
+              <TimeBasedTriggeringPolicy/>
+              <SizeBasedTriggeringPolicy size="50MB"/>
+            </Policies>
+            <DefaultRolloverStrategy max="1000"/>
+          </RollingFile>
+        </Route>
+
+      </Routes>
+    </Routing>
   </Appenders>
 
   <Loggers>
-    <Logger name="io.scalecube.config" level="error"/>
-    <Root level="debug">
-      <AppenderRef ref="STDOUT"/>
+    <Root level="${env:logLevel:-info}">
+      <AppenderRef ref="separateBenchmarkLogs"/>
     </Root>
   </Loggers>