Log the total time taken to reconfigure

2 files changed, 11 insertions, 7 deletions

diff --git a/zookeeper-server/zookeeper-server-3.5.6/src/main/java/com/yahoo/vespa/zookeeper/Reconfigurer.java b/zookeeper-server/zookeeper-server-3.5.6/src/main/java/com/yahoo/vespa/zookeeper/Reconfigurer.java
index 92211403fac..1654327edcd 100644
--- a/zookeeper-server/zookeeper-server-3.5.6/src/main/java/com/yahoo/vespa/zookeeper/Reconfigurer.java
+++ b/zookeeper-server/zookeeper-server-3.5.6/src/main/java/com/yahoo/vespa/zookeeper/Reconfigurer.java
@@ -88,6 +88,7 @@ public class Reconfigurer extends AbstractComponent {
     }
 
     private void reconfigure(ZookeeperServerConfig newConfig, Consumer<Duration> sleeper) {
+        Instant reconfigTriggered = Instant.now();
         String leavingServers = String.join(",", difference(serverIds(activeConfig), serverIds(newConfig)));
         String joiningServers = String.join(",", difference(servers(newConfig), servers(activeConfig)));
         leavingServers = leavingServers.isEmpty() ? null : leavingServers;
@@ -99,16 +100,21 @@ public class Reconfigurer extends AbstractComponent {
         boolean reconfigured = false;
         Instant end = Instant.now().plus(retryReconfigurationPeriod);
         // Loop reconfiguring since we might need to wait until another reconfiguration is finished before we can succeed
-        while ( ! reconfigured && Instant.now().isBefore(end)) {
+        for (int attempts = 1; ! reconfigured && Instant.now().isBefore(end); attempts++) {
             try {
-                Instant start = Instant.now();
+                Instant reconfigStarted = Instant.now();
                 zooKeeperReconfigure(connectionSpec, joiningServers, leavingServers);
-                log.log(Level.INFO, "Reconfiguration finished after " + Duration.between(start, Instant.now()));
+                Instant reconfigEnded = Instant.now();
+                log.log(Level.INFO, "Reconfiguration completed in " +
+                                    Duration.between(reconfigTriggered, reconfigEnded) +
+                                    ", after " + attempts + " attempt(s). ZooKeeper reconfig call took " +
+                                    Duration.between(reconfigStarted, reconfigEnded));
                 reconfigured = true;
             } catch (KeeperException e) {
                 if ( ! (e instanceof KeeperException.ReconfigInProgress))
                     throw new RuntimeException(e);
-                log.log(Level.INFO, "Will retry in " + timeBetweenRetries);
+                log.log(Level.INFO, "Reconfiguration failed due to colliding with another reconfig. Retrying in " +
+                                    timeBetweenRetries);
                 sleeper.accept(timeBetweenRetries);
             }
         }
diff --git a/zookeeper-server/zookeeper-server-3.5.6/src/test/java/com/yahoo/vespa/zookeeper/ReconfigurerTest.java b/zookeeper-server/zookeeper-server-3.5.6/src/test/java/com/yahoo/vespa/zookeeper/ReconfigurerTest.java
index afbe2b38665..bf1f9ca5611 100644
--- a/zookeeper-server/zookeeper-server-3.5.6/src/test/java/com/yahoo/vespa/zookeeper/ReconfigurerTest.java
+++ b/zookeeper-server/zookeeper-server-3.5.6/src/test/java/com/yahoo/vespa/zookeeper/ReconfigurerTest.java
@@ -148,9 +148,7 @@ public class ReconfigurerTest {
 
         @Override
         void zooKeeperReconfigure(String connectionSpec, String joiningServers, String leavingServers) throws KeeperException {
-            attempts++;
-            System.out.println("attempt " + attempts + " at reconfiguring");
-            if (attempts < 3)
+            if (++attempts < 3)
                 throw new KeeperException.ReconfigInProgress();
             else
                 super.zooKeeperReconfigure(connectionSpec, joiningServers, leavingServers);