ZOOKEEPER-3383: Improve prep processor metric accuracy and de-flaky u…

…nit test

Author: Jie Huang <jiehuang@fb.com>

Reviewers: andor@apache.org

Closes #937 from jhuan31/ZOOKEEPER-3383

zookeeper-server/src/main/java/org/apache/zookeeper/server/PrepRequestProcessor.java

@@ -133,6 +133,7 @@ public class PrepRequestProcessor extends ZooKeeperCriticalThread implements
             while (true) {
                 ServerMetrics.getMetrics().PREP_PROCESSOR_QUEUE_SIZE.add(submittedRequests.size());
                 Request request = submittedRequests.take();
+                ServerMetrics.getMetrics().PREP_PROCESSOR_QUEUE_TIME.add(Time.currentElapsedTime() - request.prepQueueStartTime);
                 long traceMask = ZooTrace.CLIENT_REQUEST_TRACE_MASK;
                 if (request.type == OpCode.ping) {
                     traceMask = ZooTrace.CLIENT_PING_TRACE_MASK;
@@ -143,9 +144,9 @@ public class PrepRequestProcessor extends ZooKeeperCriticalThread implements
                 if (Request.requestOfDeath == request) {
                     break;
                 }
-                long prepStartTime = Time.currentElapsedTime();
+
+                request.prepStartTime = Time.currentElapsedTime();
                 pRequest(request);
-                ServerMetrics.getMetrics().PREP_PROCESS_TIME.add(Time.currentElapsedTime() - prepStartTime);
             }
         } catch (RequestProcessorException e) {
             if (e.getCause() instanceof XidRolloverException) {
@@ -908,7 +909,7 @@ public class PrepRequestProcessor extends ZooKeeperCriticalThread implements
             }
         }
         request.zxid = zks.getZxid();
-        ServerMetrics.getMetrics().PREP_PROCESSOR_QUEUE_TIME.add(Time.currentElapsedTime() - request.prepQueueStartTime);
+        ServerMetrics.getMetrics().PREP_PROCESS_TIME.add(Time.currentElapsedTime() - request.prepStartTime);
         nextProcessor.processRequest(request);
     }
 

zookeeper-server/src/main/java/org/apache/zookeeper/server/Request.java

@@ -82,6 +82,8 @@ public class Request {
 
     public long prepQueueStartTime= -1;
 
+    public long prepStartTime = -1;
+
     public long commitProcQueueStartTime = -1;
 
     public long commitRecvTime = -1;

zookeeper-server/src/test/java/org/apache/zookeeper/server/PrepRequestProcessorMetricsTest.java

@@ -123,6 +123,8 @@ public class PrepRequestProcessorMetricsTest extends ZKTestCase {
         Map<String, Object> values = MetricsUtils.currentServerMetrics();
         Assert.assertEquals(3L, values.get("prep_processor_request_queued"));
 
+        // the sleep is just to make sure the requests will stay in the queue for some time
+        Thread.sleep(20);
         prepRequestProcessor.start();
 
         threeRequests.await(500, TimeUnit.MILLISECONDS);
@@ -130,7 +132,7 @@ public class PrepRequestProcessorMetricsTest extends ZKTestCase {
         values = MetricsUtils.currentServerMetrics();
         Assert.assertEquals(3L, values.get("max_prep_processor_queue_size"));
 
-        Assert.assertThat((long)values.get("min_prep_processor_queue_time_ms"), greaterThan(0l));
+        Assert.assertThat((long)values.get("min_prep_processor_queue_time_ms"), greaterThan(20l));
         Assert.assertEquals(3L, values.get("cnt_prep_processor_queue_time_ms"));
 
         Assert.assertEquals(3L, values.get("cnt_prep_process_time"));