It is slow when generate correlation Id

[wyzssw]

This is a picture profiled on my production server.
It stuck at UUID.randomUUID(),

java.security.SecureRandom#nextBytes
  @Override
    synchronized public void nextBytes(byte[] bytes) {
        secureRandomSpi.engineNextBytes(bytes);
    }

UUID performance is very slow，could logbook use random instead of uuid?
https://stackoverflow.com/questions/14532976/performance-of-random-uuid-generation-with-java-7-or-java-6

[AlexanderYastrebov]

It would be also interesting to see if it is a problem with java 8 - nextBytes is not synchronized anymore as far as I can see.

[whiskeysierra]

Maybe this is the problem:

The random form of UUID requires a source of "cryptography strength" random numbers. (If it didn't then there could be the probability that a given UUID is reissued could increase to worrying levels.)

Typical crypto-strength random number generators use a source of entropy that is external to the application. It might be a hardware random number generator, but more commonly it is accumulated "randomness" that is harvested by the operating system in normal operation. The problem is that sources of entropy have a rate limit. If you exceed that rate over a period of time, you can drain the source. What happens next is system dependent, but on some systems the syscall to read entropy will stall ... until more is available.

I expect that is what is happening on your client's system.

One workaround (for Linux systems) is to install the rngd daemon and configure it to "top up" the entropy pool using a pseudo-random number generator. The downside is that this might compromise your UUID generator's randomness.

https://stackoverflow.com/a/14533384/232539

[AlexanderYastrebov]

If there is no requirement for it to be in form of UUID, something like this could be suitable:

diff --git logbook-core/src/main/java/org/zalando/logbook/DefaultLogbook.java logbook-core/src/main/java/org/zalando/logbook/DefaultLogbook.java
index 65f43d8..adff12f 100644
--- logbook-core/src/main/java/org/zalando/logbook/DefaultLogbook.java
+++ logbook-core/src/main/java/org/zalando/logbook/DefaultLogbook.java
@@ -1,11 +1,12 @@
 package org.zalando.logbook;
 
 import java.io.IOException;
+import java.security.SecureRandom;
 import java.time.Clock;
 import java.time.Duration;
 import java.time.Instant;
 import java.util.Optional;
-import java.util.UUID;
+import java.util.Random;
 import java.util.function.Predicate;
 
 final class DefaultLogbook implements Logbook {
@@ -40,7 +41,7 @@ final class DefaultLogbook implements Logbook {
     public Optional<Correlator> write(final RawHttpRequest rawHttpRequest) throws IOException {
         final Instant start = Instant.now(clock);
         if (writer.isActive(rawHttpRequest) && predicate.test(rawHttpRequest)) {
-            final String correlationId = UUID.randomUUID().toString();
+            final String correlationId = generateCorrelationId();
             final RawHttpRequest filteredRawHttpRequest = rawRequestFilter.filter(rawHttpRequest);
             final HttpRequest request = requestFilter.filter(filteredRawHttpRequest.withBody());
 
@@ -64,6 +65,12 @@ final class DefaultLogbook implements Logbook {
         }
     }
 
+    private static final Random RANDOM = new Random(new SecureRandom().nextLong());
+
+    private static String generateCorrelationId() {
+        return Long.toString(RANDOM.nextLong());
+    }
+
     static class SimplePrecorrelation<I> implements Precorrelation<I> {
 
         private final String id;

[whiskeysierra]

If someone is initializing the DefaultLogbook class, then he will most likely use it. I don't think that it's need to defer initialization. It would actually put the burden on the first request instead of doing it at application startup.

[whiskeysierra]

The random number could be negative, but I don't think that's a problem.

[AlexanderYastrebov]

The random number could be negative, but I don't think that's a problem.

return Long.toHexString(RANDOM.nextLong());

It could be even faster