Merge pull request #524 from skjolber/jmhHttpLogFormatter

Improve performance of DefaultHttpLogFormatter
zalando · Jun 18, 2019 · 11d4f4a · 11d4f4a
2 parents 03539f5 + 98e6c7b
commit 11d4f4a
Show file tree

Hide file tree

Showing 5 changed files with 157 additions and 102 deletions.
diff --git a/logbook-api/src/main/java/org/zalando/logbook/RequestURI.java b/logbook-api/src/main/java/org/zalando/logbook/RequestURI.java
@@ -21,24 +21,36 @@ enum Component {
     }
 
     static String reconstruct(final HttpRequest request) {
-        return reconstruct(request, EnumSet.allOf(Component.class));
+        final StringBuilder url = new StringBuilder();
+        reconstruct(request, url);
+        return url.toString();
+    }
+
+    static void reconstruct(final HttpRequest request, StringBuilder output) {
+        reconstruct(request, EnumSet.allOf(Component.class), output);
     }
 
     static String reconstruct(final HttpRequest request, final Component... components) {
-        return reconstruct(request, EnumSet.copyOf(asList(components)));
+        final StringBuilder url = new StringBuilder();
+        reconstruct(request, EnumSet.copyOf(asList(components)), url);
+        return url.toString();
+    }
+
+    static String reconstruct(final HttpRequest request, final Set<Component> components) {
+        final StringBuilder url = new StringBuilder();
+        reconstruct(request, components, url);
+        return url.toString();
     }
 
-    private static String reconstruct(final HttpRequest request, final Set<Component> components) {
+    private static void reconstruct(final HttpRequest request, final Set<Component> components, StringBuilder url) {
         final String scheme = request.getScheme();
         final String host = request.getHost();
         final Optional<Integer> port = request.getPort();
         final String path = request.getPath();
         final String query = request.getQuery();
 
-        final StringBuilder url = new StringBuilder();
-
         if (components.contains(SCHEME)) {
-            url.append(scheme).append(":");
+            url.append(scheme).append(':');
         }
 
         if (components.contains(AUTHORITY)) {
@@ -63,13 +75,11 @@ private static String reconstruct(final HttpRequest request, final Set<Component
         if (components.contains(QUERY) && !query.isEmpty()) {
             url.append('?').append(query);
         }
-
-        return url.toString();
     }
 
     private static boolean isNotStandardPort(final String scheme, final int port) {
-        return "http".equals(scheme) && port != 80 ||
-                "https".equals(scheme) && port != 443;
+        return ("http".equals(scheme) && port != 80) ||
+                ("https".equals(scheme) && port != 443);
     }
 
 }
diff --git a/logbook-api/src/test/java/org/zalando/logbook/RequestURITest.java b/logbook-api/src/test/java/org/zalando/logbook/RequestURITest.java
@@ -2,7 +2,9 @@
 
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
+import org.zalando.logbook.RequestURI.Component;
 
+import java.util.EnumSet;
 import java.util.Optional;
 
 import static org.hamcrest.MatcherAssert.assertThat;
@@ -101,13 +103,24 @@ void shouldReconstructWithoutSchemeAuthorityAndPath() {
 
     @Test
     void shouldUseComponentValueOf() {
-        RequestURI.Component.valueOf("SCHEME");
+        Component.valueOf("SCHEME");
     }
 
     @Test
     void shouldUseOriginValueOf() {
         Origin.valueOf("LOCAL");
     }
 
-
+    @Test
+    void shouldReconstructUsingBuilder() {
+        StringBuilder builder = new StringBuilder();
+        reconstruct(request, builder);
+        assertThat(builder.toString(), is("http://localhost/admin?limit=1"));
+    }
+
+    @Test
+    void shouldReconstructSpecificComponents() {
+        String r = reconstruct(request, EnumSet.of(SCHEME, AUTHORITY, PATH));
+        assertThat(r, is("http://localhost/admin"));
+    }
 }
diff --git a/logbook-core/src/main/java/org/zalando/logbook/DefaultHttpLogFormatter.java b/logbook-core/src/main/java/org/zalando/logbook/DefaultHttpLogFormatter.java
@@ -1,25 +1,56 @@
 package org.zalando.logbook;
 
-import org.apiguardian.api.API;
+import static org.apiguardian.api.API.Status.STABLE;
 
 import java.io.IOException;
-import java.util.ArrayList;
-import java.util.Collections;
 import java.util.List;
 import java.util.Map;
+import java.util.Map.Entry;
 
-import static java.util.stream.Collectors.toList;
-import static java.util.stream.Collectors.toMap;
-import static org.apiguardian.api.API.Status.EXPERIMENTAL;
-import static org.apiguardian.api.API.Status.STABLE;
-import static org.zalando.logbook.Origin.REMOTE;
+import org.apiguardian.api.API;
 
 @API(status = STABLE)
 public final class DefaultHttpLogFormatter implements HttpLogFormatter {
 
+    /**
+     * Produces an HTTP-like request in individual lines.
+     *
+     * @param precorrelation the request correlation
+     * @param request the HTTP request 
+     * @return a line-separated HTTP request
+     * @throws IOException if reading body fails
+     */
+
     @Override
-    public String format(final Precorrelation precorrelation, final HttpRequest request) throws IOException {
-        return format(prepare(precorrelation, request));
+    public String format(Precorrelation precorrelation, HttpRequest request) throws IOException {
+        final String correlationId = precorrelation.getId();
+
+        String body = request.getBodyAsString();
+
+        StringBuilder builder = new StringBuilder(body.length() + 2048);
+
+        builder.append(direction(request));
+        builder.append(" Request: ");
+        builder.append(correlationId);
+        builder.append('\n');
+
+        builder.append(request.getMethod());
+        builder.append(' ');
+        RequestURI.reconstruct(request, builder);
+        builder.append(' ');
+        builder.append(request.getProtocolVersion());
+        builder.append('\n');
+
+        writeHeaders(builder, request);
+
+        if (!body.isEmpty()) {
+            builder.append('\n');
+            builder.append(body);
+        } else {
+            builder.setLength(builder.length() - 1); // discard last newline
+        }
+
+        return builder.toString();
     }
 
     /**
@@ -32,95 +63,66 @@ public String format(final Precorrelation precorrelation, final HttpRequest requ
      * @see #format(List)
      * @see StructuredHttpLogFormatter#prepare(Precorrelation, HttpRequest)
      */
-    @API(status = EXPERIMENTAL)
-    public List<String> prepare(final Precorrelation precorrelation, final HttpRequest request) throws IOException {
-        final String requestLine = String.format("%s %s %s", request.getMethod(), request.getRequestUri(),
-                request.getProtocolVersion());
-        return prepare(request, "Request", precorrelation.getId(), requestLine);
-    }
 
     @Override
     public String format(final Correlation correlation, final HttpResponse response) throws IOException {
-        return format(prepare(correlation, response));
-    }
-
-    /**
-     * Produces an HTTP-like response in individual lines.
-     * <p>
-     * Pr@param correlation the response correlation
-     *
-     * @param correlation the correlated request and response pair
-     * @return a line-separated HTTP response
-     * @throws IOException if reading body fails
-     * @see #prepare(Precorrelation, HttpRequest)
-     * @see #format(List)
-     * @see StructuredHttpLogFormatter#prepare(Correlation, HttpResponse)
-     */
-    @API(status = EXPERIMENTAL)
-    public List<String> prepare(final Correlation correlation, final HttpResponse response) throws IOException {
-        final StringBuilder statusLineBuilder = new StringBuilder(64);
-        statusLineBuilder.append(response.getProtocolVersion());
-        statusLineBuilder.append(' ');
-        statusLineBuilder.append(response.getStatus());
+        final String correlationId = correlation.getId();
+
+        String body = response.getBodyAsString();
+
+        StringBuilder builder = new StringBuilder(body.length() + 2048);
+
+        builder.append(direction(response));
+        builder.append(" Response: ");
+        builder.append(correlationId);
+        builder.append("\nDuration: ");
+        builder.append(correlation.getDuration().toMillis());
+        builder.append(" ms\n");
+
+        builder.append(response.getProtocolVersion());
+        builder.append(' ');
+        builder.append(response.getStatus());
         final String reasonPhrase = response.getReasonPhrase();
         if(reasonPhrase != null) {
-            statusLineBuilder.append(' ');
-            statusLineBuilder.append(reasonPhrase);
+            builder.append(' ');
+            builder.append(reasonPhrase);
         }
-        return prepare(response, "Response", correlation.getId(),
-                "Duration: " + correlation.getDuration().toMillis() + " ms", statusLineBuilder.toString());
-    }
-
-    private <H extends HttpMessage> List<String> prepare(final H message, final String type,
-            final String correlationId, final String... prefixes) throws IOException {
-        final List<String> lines = new ArrayList<>();
-
-        lines.add(direction(message) + " " + type + ": " + correlationId);
-        Collections.addAll(lines, prefixes);
-        lines.addAll(formatHeaders(message));
+
+        builder.append('\n');
 
-        final String body = message.getBodyAsString();
+        writeHeaders(builder, response);
 
         if (!body.isEmpty()) {
-            lines.add("");
-            lines.add(body);
+            builder.append('\n');
+            builder.append(body);
+        } else {
+            builder.setLength(builder.length() - 1); // discard last newline
         }
-
-        return lines;
-    }
-
-    private String direction(final HttpMessage request) {
-        return request.getOrigin() == REMOTE ? "Incoming" : "Outgoing";
-    }
-
-    private List<String> formatHeaders(final HttpMessage message) {
-        return message.getHeaders().entrySet().stream()
-                .collect(toMap(Map.Entry::getKey, this::formatHeaderValues))
-                .entrySet().stream()
-                .map(this::formatHeader)
-                .collect(toList());
-    }
-
-    private String formatHeaderValues(final Map.Entry<String, List<String>> entry) {
-        return String.join(", ", entry.getValue());
+
+        return builder.toString();        
     }
 
-    private String formatHeader(final Map.Entry<String, String> entry) {
-        return String.format("%s: %s", entry.getKey(), entry.getValue());
+    private void writeHeaders(StringBuilder builder, HttpMessage httpMessage) {
+        Map<String, List<String>> headers = httpMessage.getHeaders();
+
+        if(!headers.isEmpty()) {
+            for (Entry<String, List<String>> entry : headers.entrySet()) {
+                builder.append(entry.getKey()); 
+                builder.append(": ");
+                List<String> headerValues = entry.getValue();
+                if(!headerValues.isEmpty()) {
+                    for(String value : entry.getValue()) {
+                        builder.append(value); 
+                        builder.append(", ");
+                    }
+                    builder.setLength(builder.length() - 2); // discard last comma
+                }
+                builder.append('\n');
+            }
+        }
     }
 
-    /**
-     * Renders an HTTP-like message into a printable string.
-     *
-     * @param lines lines of an HTTP message
-     * @return the whole message as a single string, separated by new lines
-     * @see #prepare(Precorrelation, HttpRequest)
-     * @see #prepare(Correlation, HttpResponse)
-     * @see StructuredHttpLogFormatter#format(Map)
-     */
-    @API(status = EXPERIMENTAL)
-    public String format(final List<String> lines) {
-        return String.join("\n", lines);
+    private String direction(final HttpMessage request) {
+        return request.getOrigin() == Origin.REMOTE ? "Incoming" : "Outgoing";
     }
-
 }
diff --git a/logbook-core/src/test/java/org/zalando/logbook/DefaultHttpLogFormatterTest.java b/logbook-core/src/test/java/org/zalando/logbook/DefaultHttpLogFormatterTest.java
@@ -5,6 +5,11 @@
 import org.zalando.logbook.DefaultLogbook.SimplePrecorrelation;
 
 import java.io.IOException;
+import java.util.Arrays;
+import java.util.Collections;
+import java.util.List;
+import java.util.Map;
+import java.util.TreeMap;
 
 import static java.time.Clock.systemUTC;
 import static java.time.Duration.ofMillis;
@@ -131,5 +136,30 @@ void shouldLogResponseForUnknownStatusCode() throws IOException {
                 "\n" +
                 "{\"success\":true}"));
     }
-
+
+    @Test
+    void shouldLogResponseForEmptyHeader() throws IOException {
+        final String correlationId = "2d51bc02-677e-11e5-8b9b-10ddb1ee7671";
+
+        Map<String, List<String>> headers = new TreeMap<>();
+        headers.put("Content-Type", Arrays.asList("application/json"));
+        headers.put("X-Empty-Header", Collections.emptyList());
+
+        final HttpResponse response = MockHttpResponse.create()
+                .withProtocolVersion("HTTP/1.0")
+                .withOrigin(Origin.REMOTE)
+                .withStatus(201)
+                .withHeaders(headers)
+                .withBodyAsString("{\"success\":true}");
+
+        final String http = unit.format(new SimpleCorrelation(correlationId, ofMillis(125)), response);
+
+        assertThat(http, is("Incoming Response: 2d51bc02-677e-11e5-8b9b-10ddb1ee7671\n" +
+                "Duration: 125 ms\n" +
+                "HTTP/1.0 201 Created\n" +
+                "Content-Type: application/json\n" +
+                "X-Empty-Header: \n" +
+                "\n" +
+                "{\"success\":true}"));
+    }
 }
diff --git a/logbook-servlet/src/test/java/org/zalando/logbook/servlet/WritingTest.java b/logbook-servlet/src/test/java/org/zalando/logbook/servlet/WritingTest.java
@@ -91,8 +91,8 @@ private void shouldLogRequestBody(final String contentType, final String content
         assertThat(request, endsWith(
                 "GET http://localhost/api/sync HTTP/1.1\n" +
                         "Accept: application/json\n" +
-                        "Host: localhost\n" +
                         "Content-Type: " + contentType + "\n" +
+                        "Host: localhost\n" +
                         "\n" +
                         content));
     }
@@ -116,8 +116,8 @@ void shouldNotLogFormRequestOff() throws Exception {
         assertThat(request, endsWith(
                 "GET http://localhost/api/sync HTTP/1.1\n" +
                         "Accept: application/json\n" +
-                        "Host: localhost\n" +
-                        "Content-Type: application/x-www-form-urlencoded"));
+                        "Content-Type: application/x-www-form-urlencoded\n" +
+                        "Host: localhost"));
     }
 
     @Test