Measure server processing and idle time

[#150061059] https://www.pivotaltracker.com/story/show/150061059

server/src/main/java/org/cloudfoundry/identity/uaa/metrics/IdleTimer.java

@@ -0,0 +1,73 @@
+/*
+ * ****************************************************************************
+ *     Cloud Foundry
+ *     Copyright (c) [2009-2017] Pivotal Software, Inc. All Rights Reserved.
+ *
+ *     This product is licensed to you under the Apache License, Version 2.0 (the "License").
+ *     You may not use this product except in compliance with the License.
+ *
+ *     This product includes a number of subcomponents with
+ *     separate copyright notices and license terms. Your use of these
+ *     subcomponents is subject to the terms and conditions of the
+ *     subcomponent's license, as noted in the LICENSE file.
+ * ****************************************************************************
+ */
+
+package org.cloudfoundry.identity.uaa.metrics;
+
+/**
+ * Calculates the time that a server is idle (no requests processing)
+ * The idle time calculator starts as soon as this object is created.
+ */
+public class IdleTimer {
+
+    private int inflightRequests = 0;
+    private long idleTime = 0;
+    private long lastIdleStart = System.currentTimeMillis();
+    private final long startTime = System.currentTimeMillis();
+    private long requestCount = 0;
+
+    public synchronized void endRequest() {
+        switch (--inflightRequests) {
+            case 0:
+                lastIdleStart = System.currentTimeMillis();
+                break;
+            case -1:
+                throw new IllegalStateException("Illegal end request invocation, no request in flight");
+            default:
+                break;
+        }
+        requestCount++;
+    }
+
+    public synchronized void startRequest() {
+        switch (++inflightRequests) {
+            case 1:
+                idleTime += (System.currentTimeMillis() - lastIdleStart);
+                break;
+            default:
+                break;
+        }
+
+    }
+
+    public int getInflightRequests() {
+        return inflightRequests;
+    }
+
+    public synchronized long getIdleTime() {
+        if (inflightRequests == 0) {
+            return (System.currentTimeMillis() - lastIdleStart) + idleTime;
+        } else {
+            return idleTime;
+        }
+    }
+
+    public long getRequestCount() {
+        return requestCount;
+    }
+
+    public long getRunTime() {
+        return System.currentTimeMillis() - startTime;
+    }
+}

server/src/main/java/org/cloudfoundry/identity/uaa/metrics/UaaMetricsFilter.java

@@ -31,7 +31,6 @@
 import java.util.HashMap;
 import java.util.Map;
 import java.util.concurrent.ConcurrentHashMap;
-import java.util.concurrent.atomic.AtomicInteger;
 
 import static org.springframework.util.StringUtils.hasText;
 
@@ -43,7 +42,7 @@ public class UaaMetricsFilter extends OncePerRequestFilter {
 
 
     private TimeService timeService = new TimeServiceImpl();
-    private AtomicInteger inflight = new AtomicInteger(0);
+    private IdleTimer inflight = new IdleTimer();
     Map<String,MetricsQueue> perUriMetrics = new ConcurrentHashMap<>();
 
     @Override
@@ -53,11 +52,11 @@ protected void doFilterInternal(HttpServletRequest request, HttpServletResponse
             RequestMetric metric = RequestMetric.start(request.getRequestURI(), timeService.getCurrentTimeMillis());
             try {
                 MetricsAccessor.setCurrent(metric);
-                inflight.incrementAndGet();
+                inflight.startRequest();
                 filterChain.doFilter(request, response);
             } finally {
                 MetricsAccessor.clear();
-                inflight.decrementAndGet();
+                inflight.endRequest();
                 metric.stop(response.getStatus(), timeService.getCurrentTimeMillis());
                 MetricsQueue queue = getMetricsQueue(uriGroup);
                 queue.offer(metric);
@@ -120,9 +119,30 @@ protected String getUriGroup(HttpServletRequest request) {
 
     @ManagedMetric(category = "performance", displayName = "Inflight Requests")
     public int getInflightRequests() {
-        return inflight.get();
+        return inflight.getInflightRequests();
     }
 
+    @ManagedMetric(category = "performance", displayName = "Idle time (ms)")
+    public long getIdleTime() {
+        return inflight.getIdleTime();
+    }
+
+    @ManagedMetric(category = "performance", displayName = "Processing request time (ms)")
+    public long getProcessingTime() {
+        return inflight.getRunTime() - inflight.getIdleTime();
+    }
+
+    @ManagedMetric(category = "performance", displayName = "Total server run time (ms)")
+    public long getRunTime() {
+        return inflight.getRunTime();
+    }
+
+    @ManagedMetric(category = "performance", displayName = "Number of completed requests")
+    public long getCompletedRequests() {
+        return inflight.getRequestCount();
+    }
+
+
     @ManagedMetric(category = "performance", displayName = "Server Request Summary")
     public Map<String, String> getSummary() {
         Map<String, String> data = new HashMap<>();

server/src/test/java/org/cloudfoundry/identity/uaa/metrics/IdleTimerTests.java

@@ -0,0 +1,99 @@
+/*
+ * ****************************************************************************
+ *     Cloud Foundry
+ *     Copyright (c) [2009-2017] Pivotal Software, Inc. All Rights Reserved.
+ *
+ *     This product is licensed to you under the Apache License, Version 2.0 (the "License").
+ *     You may not use this product except in compliance with the License.
+ *
+ *     This product includes a number of subcomponents with
+ *     separate copyright notices and license terms. Your use of these
+ *     subcomponents is subject to the terms and conditions of the
+ *     subcomponent's license, as noted in the LICENSE file.
+ * ****************************************************************************
+ */
+
+package org.cloudfoundry.identity.uaa.metrics;
+
+import org.junit.Before;
+import org.junit.Rule;
+import org.junit.Test;
+import org.junit.rules.ExpectedException;
+
+import java.util.concurrent.CountDownLatch;
+
+import static org.hamcrest.Matchers.greaterThan;
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertThat;
+
+public class IdleTimerTests {
+
+    public static final int LOOP_COUNT = 100000;
+    private IdleTimer timer;
+
+    @Rule
+    public ExpectedException exception = ExpectedException.none();
+    public static final int THREAD_COUNT = 10;
+
+    @Before
+    public void setup() throws Exception {
+        timer = new IdleTimer();
+    }
+
+    @Test
+    public void timer_started() throws Exception {
+        Thread.sleep(10);
+        assertEquals(0, timer.getInflightRequests());
+        assertThat(timer.getRunTime(), greaterThan(0l));
+        assertThat(timer.getIdleTime(), greaterThan(0l));
+    }
+
+    @Test
+    public void illegal_end_request() throws Exception {
+        exception.expect(IllegalStateException.class);
+        exception.expectMessage("Illegal end request invocation, no request in flight");
+        timer.endRequest();
+    }
+
+    @Test
+    public void while_inflight() throws Exception {
+        timer.startRequest();
+        long idleTime = timer.getIdleTime();
+        assertEquals(1, timer.getInflightRequests());
+        timer.startRequest();
+        assertEquals(2, timer.getInflightRequests());
+        timer.endRequest();
+        assertEquals(1, timer.getInflightRequests());
+        Thread.sleep(10);
+        assertEquals("Idle time should not have changed.", idleTime, timer.getIdleTime());
+        timer.endRequest();
+        assertEquals(0, timer.getInflightRequests());
+        Thread.sleep(10);
+        assertThat("Idle time should have changed.", timer.getIdleTime(), greaterThan(idleTime));
+    }
+
+    @Test
+    public void concurrency_test() throws Exception {
+        final CountDownLatch latch = new CountDownLatch(THREAD_COUNT);
+        Thread[] threads = new Thread[THREAD_COUNT];
+        for (int i = 0; i< THREAD_COUNT; i++) {
+            threads[i] = new Thread(() -> {
+               for (int loop = 0; loop< LOOP_COUNT; loop++) {
+                   try {
+                       timer.startRequest();
+                   } finally {
+                       timer.endRequest();
+                   }
+               }
+               latch.countDown();
+            });
+        }
+        for (int i = 0; i< THREAD_COUNT; i++) {
+            threads[i].start();
+        }
+        latch.await();
+        assertEquals(THREAD_COUNT * LOOP_COUNT, timer.getRequestCount());
+        assertEquals(0, timer.getInflightRequests());
+    }
+
+}

server/src/test/java/org/cloudfoundry/identity/uaa/metrics/UaaMetricsFilterTests.java

@@ -28,11 +28,17 @@
 import javax.servlet.FilterChain;
 import java.util.Arrays;
 import java.util.Map;
+import java.util.concurrent.locks.Lock;
+import java.util.concurrent.locks.ReentrantLock;
 
+import static org.hamcrest.Matchers.greaterThan;
 import static org.junit.Assert.assertEquals;
 import static org.junit.Assert.assertFalse;
 import static org.junit.Assert.assertNotNull;
 import static org.junit.Assert.assertNull;
+import static org.junit.Assert.assertThat;
+import static org.mockito.ArgumentMatchers.any;
+import static org.mockito.Mockito.doAnswer;
 
 public class UaaMetricsFilterTests {
 
@@ -80,6 +86,42 @@ public void happy_path() throws Exception {
         assertNull(MetricsAccessor.getCurrent());
     }
 
+    @Test
+    public void idle_counter() throws Exception {
+        final Lock lock = new ReentrantLock();
+        lock.lock();
+        request.setRequestURI("/oauth/token");
+        final FilterChain chain = Mockito.mock(FilterChain.class);
+        final UaaMetricsFilter filter = new UaaMetricsFilter();
+        doAnswer(invocation -> {
+            try {
+                lock.lock();
+            } finally {
+                lock.unlock();
+                return null;
+            }
+        }).when(chain).doFilter(any(), any());
+        Runnable invocation = () -> {
+            try {
+                filter.doFilterInternal(request, response, chain);
+            } catch (Exception e) {
+                e.printStackTrace();
+            }
+        };
+        Thread invoker = new Thread(invocation);
+        invoker.start();
+        Thread.sleep(10);
+        assertEquals(1, filter.getInflightRequests());
+        lock.unlock();
+        Thread.sleep(25);
+        assertEquals(0, filter.getInflightRequests());
+        long idleTime = filter.getIdleTime();
+        assertThat(idleTime, greaterThan(20l));
+        System.out.println("Total idle time was:"+idleTime);
+        Thread.sleep(10);
+        assertThat("Idle time should have changed.", filter.getIdleTime(), greaterThan(idleTime));
+    }
+
     @Test
     public void uri_groups() throws Exception {
         request.setContextPath("");