Minor Performance Improvements

- Remove expensive log formatting
- Move from Exchanger that requires both produce and consumer
to bet at the same point to a array based approach where the producer doesn't
need to wait for the consumer
- Added some more perfLogger output
- Added extra VM option to output config
- Updated FV tests that weren't thread sage

Signed-off-by: Matthew B White <whitemat@uk.ibm.com>

Author: mbwhite

fabric-chaincode-docker/Dockerfile

@@ -40,7 +40,9 @@ RUN gradle \
     fabric-chaincode-shim:publishToMavenLocal \
     -x javadoc \
     -x test \
-    -x checkstyleMain -x checkstyleTest
+    -x checkstyleMain \
+    -x checkstyleTest \
+    -x dependencyCheckAnalyze
 
 # Installing all protos jar dependencies to maven local
 WORKDIR /root/chaincode-java/shim-src/fabric-chaincode-protos/build/publications/protosJar/

fabric-chaincode-docker/start

@@ -8,12 +8,14 @@ LIB_JARS=$(find ${LIB_DIR} -name "*.jar" | paste -s -d ":" -)
 CHAINCODE_JARS=$(find ${CHAINCODE_DIR} -name "*.jar" | paste -s -d ":" -)
 NUM_CHAINCODE_JARS=$(find ${CHAINCODE_DIR} -name "*.jar" | wc -l)
 
+JAVA_OPTS="-XshowSettings"
+
 if [ -f ${CHAINCODE_DIR}/.uberjar ]; then
     if [ ${NUM_CHAINCODE_JARS} -ne 1 ]; then
         >&2 echo "Cannot start uber JAR as more than one JAR file was found in the chaincode directory"
         exit 255
     fi
-    exec java -jar ${CHAINCODE_JARS} "$@"
+    exec java ${JAVA_OPTS} -jar ${CHAINCODE_JARS} "$@"
 else
-    exec java -cp ${CHAINCODE_JARS}:${LIB_JARS} org.hyperledger.fabric.contract.ContractRouter "$@"
+    exec java ${JAVA_OPTS} -cp ${CHAINCODE_JARS}:${LIB_JARS} org.hyperledger.fabric.contract.ContractRouter "$@"
 fi

fabric-chaincode-protos/build.gradle

@@ -47,11 +47,12 @@ buildscript {
 dependencies {
     compile 'com.google.protobuf:protobuf-java:3.11.1'
     compile 'com.google.protobuf:protobuf-java-util:3.11.1'
-    compile 'io.grpc:grpc-netty:1.30.2'
-    compile 'io.grpc:grpc-protobuf:1.30.2'
-    compile 'io.grpc:grpc-stub:1.30.2'
+    compile 'io.grpc:grpc-netty-shaded:1.31.1'
+    compile 'io.grpc:grpc-protobuf:1.31.1'
+    compile 'io.grpc:grpc-stub:1.31.1'
     // Required if using Java 11+ as no longer bundled in the core libraries
     compile 'javax.annotation:javax.annotation-api:1.3.2'
+    compileOnly 'org.apache.tomcat:annotations-api:6.0.53' // necessary for Java 9+
 }
 
 protobuf {

fabric-chaincode-shim/build.gradle

@@ -22,7 +22,6 @@ plugins {
 
 apply plugin: 'org.owasp.dependencycheck'
 
-
 checkstyle {
     toolVersion '8.29'
     configFile file("../ci/checkstyle/checkstyle.xml")
@@ -37,7 +36,6 @@ checkstyleTest {
 
 
 
-
 check.dependsOn dependencyCheckAnalyze
 
 tasks.withType(org.gradle.api.tasks.testing.Test) {
@@ -53,6 +51,9 @@ dependencies {
     compile group: 'org.json', name: 'json', version: '20180813'
     // Required if using Java 11+ as no longer bundled in the core libraries
     testCompile group: 'javax.xml.bind', name: 'jaxb-api', version: '2.3.1'
+    compile 'io.grpc:grpc-netty-shaded:1.31.1'
+    compile 'io.grpc:grpc-protobuf:1.31.1'
+    compile 'io.grpc:grpc-stub:1.31.1'
 }
 
 dependencyCheck {

fabric-chaincode-shim/src/main/java/commons-logging.properties

@@ -93,6 +93,7 @@ private static Level mapLevel(final String level) {
             case "CRITICAL":
                 return Level.SEVERE;
             case "WARNING":
+            case "WARN":
                 return Level.WARNING;
             case "INFO":
                 return Level.INFO;

fabric-chaincode-shim/src/main/java/org/hyperledger/fabric/Logging.java

@@ -53,6 +53,9 @@ public void run() {
     protected void logMetrics() {
 
         perflogger.info(() -> {
+            if (DefaultProvider.this.taskService == null) {
+                return "No Metrics Provider service yet";
+            }
             final StringBuilder sb = new StringBuilder();
             sb.append('{');
             sb.append(String.format(" \"active_count\":%d ", DefaultProvider.this.taskService.getActiveCount())).append(',');

fabric-chaincode-shim/src/main/java/org/hyperledger/fabric/metrics/impl/DefaultProvider.java

@@ -13,23 +13,19 @@
 import java.io.File;
 import java.io.IOException;
 import java.io.InputStream;
-import java.io.PrintWriter;
-import java.io.StringWriter;
 import java.nio.file.Files;
 import java.nio.file.Paths;
 import java.security.Security;
 import java.util.Base64;
-import java.util.Collections;
-import java.util.Date;
-import java.util.List;
 import java.util.Properties;
-import java.util.logging.Formatter;
 import java.util.logging.Level;
-import java.util.logging.LogManager;
 import java.util.logging.LogRecord;
 import java.util.logging.Logger;
 import java.util.logging.SimpleFormatter;
 
+import com.google.protobuf.InvalidProtocolBufferException;
+import com.google.protobuf.util.JsonFormat;
+
 import org.apache.commons.cli.CommandLine;
 import org.apache.commons.cli.DefaultParser;
 import org.apache.commons.cli.Options;
@@ -42,14 +38,11 @@
 import org.hyperledger.fabric.shim.impl.ChaincodeSupportClient;
 import org.hyperledger.fabric.shim.impl.InvocationTaskManager;
 
-import com.google.protobuf.InvalidProtocolBufferException;
-import com.google.protobuf.util.JsonFormat;
-
 import io.grpc.ManagedChannelBuilder;
-import io.grpc.netty.GrpcSslContexts;
-import io.grpc.netty.NegotiationType;
-import io.grpc.netty.NettyChannelBuilder;
-import io.netty.handler.ssl.SslContext;
+import io.grpc.netty.shaded.io.grpc.netty.GrpcSslContexts;
+import io.grpc.netty.shaded.io.grpc.netty.NegotiationType;
+import io.grpc.netty.shaded.io.grpc.netty.NettyChannelBuilder;
+import io.grpc.netty.shaded.io.netty.handler.ssl.SslContext;
 
 public abstract class ChaincodeBase implements Chaincode {
 
@@ -147,6 +140,7 @@ protected final void connectToPeer() throws IOException {
     }
 
     protected final void initializeLogging() {
+        // the VM wide formatting string.
         System.setProperty("java.util.logging.SimpleFormatter.format",
                 "%1$tH:%1$tM:%1$tS:%1$tL %4$-7.7s %2$-80.80s %5$s%6$s%n");
         final Logger rootLogger = Logger.getLogger("");
@@ -157,53 +151,12 @@ protected final void initializeLogging() {
 
                 @Override
                 public synchronized String format(final LogRecord record) {
-                    return super.format(record).replaceFirst(".*SEVERE\\s*\\S*\\s*\\S*", "\u001B[1;31m$0\u001B[0m")
-                            .replaceFirst(".*WARNING\\s*\\S*\\s*\\S*", "\u001B[1;33m$0\u001B[0m")
-                            .replaceFirst(".*CONFIG\\s*\\S*\\s*\\S*", "\u001B[35m$0\u001B[0m")
-                            .replaceFirst(".*FINE\\s*\\S*\\s*\\S*", "\u001B[36m$0\u001B[0m")
-                            .replaceFirst(".*FINER\\s*\\S*\\s*\\S*", "\u001B[36m$0\u001B[0m")
-                            .replaceFirst(".*FINEST\\s*\\S*\\s*\\S*", "\u001B[36m$0\u001B[0m");
+                    return Thread.currentThread() + " " + super.format(record);
                 }
 
             });
         }
 
-        final LogManager logManager = LogManager.getLogManager();
-
-        final Formatter f = new Formatter() {
-
-            private final Date dat = new Date();
-            private final String format = "%1$tH:%1$tM:%1$tS:%1$tL %4$-7.7s %2$-80.80s %5$s%6$s%n";
-
-            @Override
-            public String format(final LogRecord record) {
-                dat.setTime(record.getMillis());
-                String source;
-                if (record.getSourceClassName() != null) {
-                    source = record.getSourceClassName();
-                    if (record.getSourceMethodName() != null) {
-                        source += " " + record.getSourceMethodName();
-                    }
-                } else {
-                    source = record.getLoggerName();
-                }
-                final String message = formatMessage(record);
-                String throwable = "";
-                if (record.getThrown() != null) {
-                    final StringWriter sw = new StringWriter();
-                    final PrintWriter pw = new PrintWriter(sw);
-                    pw.println();
-                    record.getThrown().printStackTrace(pw);
-                    pw.close();
-                    throwable = sw.toString();
-                }
-                return String.format(format, dat, source, record.getLoggerName(), record.getLevel(), message,
-                        throwable);
-
-            }
-
-        };
-
         rootLogger.info("Updated all handlers the format");
         // set logging level of chaincode logger
         final Level chaincodeLogLevel = mapLevel(System.getenv(CORE_CHAINCODE_LOGGING_LEVEL));
@@ -223,31 +176,26 @@ public String format(final LogRecord record) {
         Logger.getLogger(ChaincodeBase.class.getPackage().getName()).setLevel(shimLogLevel);
         Logger.getLogger(ContractRouter.class.getPackage().getName()).setLevel(chaincodeLogLevel);
 
-        final List<?> loggers = Collections.list(LogManager.getLogManager().getLoggerNames());
-        loggers.forEach(x -> {
-            final Logger l = LogManager.getLogManager().getLogger((String) x);
-            // err what is the code supposed to do?
-        });
-
     }
 
     private Level mapLevel(final String level) {
 
         if (level != null) {
             switch (level.toUpperCase().trim()) {
-            case "CRITICAL":
-            case "ERROR":
-                return Level.SEVERE;
-            case "WARNING":
-                return Level.WARNING;
-            case "INFO":
-                return Level.INFO;
-            case "NOTICE":
-                return Level.CONFIG;
-            case "DEBUG":
-                return Level.FINEST;
-            default:
-                break;
+                case "CRITICAL":
+                case "ERROR":
+                    return Level.SEVERE;
+                case "WARNING":
+                case "WARN":
+                    return Level.WARNING;
+                case "INFO":
+                    return Level.INFO;
+                case "NOTICE":
+                    return Level.CONFIG;
+                case "DEBUG":
+                    return Level.FINEST;
+                default:
+                    break;
             }
         }
         return Level.INFO;