Add metric for lock life duration

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=177070996

java/google/registry/model/server/Lock.java

@@ -74,6 +74,16 @@ public class Lock extends ImmutableObject {
   /** When the lock can be considered implicitly released. */
   DateTime expirationTime;
 
+  /** When was the lock acquired. Used for logging. */
+  DateTime acquiredTime;
+
+  /** The resource name used to create lockId. */
+  String resourceName;
+
+  /** The tld used to create lockId. */
+  @Nullable
+  String tld;
+
   /**
    * Create a new {@link Lock} for the given resource name in the specified tld (which can be
    * null for cross-tld locks).
@@ -82,14 +92,18 @@ public class Lock extends ImmutableObject {
       String resourceName,
       @Nullable String tld,
       String requestLogId,
-      DateTime expirationTime) {
+      DateTime acquiredTime,
+      Duration leaseLength) {
     checkArgument(!Strings.isNullOrEmpty(resourceName), "resourceName cannot be null or empty");
     Lock instance = new Lock();
     // Add the tld to the Lock's id so that it is unique for locks acquiring the same resource
     // across different TLDs.
     instance.lockId = makeLockId(resourceName, tld);
     instance.requestLogId = requestLogId;
-    instance.expirationTime = expirationTime;
+    instance.expirationTime = acquiredTime.plus(leaseLength);
+    instance.acquiredTime = acquiredTime;
+    instance.resourceName = resourceName;
+    instance.tld = tld;
     return instance;
   }
 
@@ -195,7 +209,8 @@ public class Lock extends ImmutableObject {
           resourceName,
           tld,
           requestStatusChecker.getLogId(),
-          now.plus(leaseLength));
+          now,
+          leaseLength);
       // Locks are not parented under an EntityGroupRoot (so as to avoid write contention) and
       // don't need to be backed up.
       ofy().saveWithoutBackup().entity(newLock);
@@ -203,7 +218,7 @@ public class Lock extends ImmutableObject {
     });
 
     logAcquireResult(acquireResult);
-    lockMetrics.record(resourceName, tld, acquireResult.lockState());
+    lockMetrics.recordAcquire(resourceName, tld, acquireResult.lockState());
     return Optional.ofNullable(acquireResult.newLock());
   }
 
@@ -221,6 +236,8 @@ public class Lock extends ImmutableObject {
           // Use noBackupOfy() so that we don't create a commit log entry for deleting the lock.
           logger.infofmt("Deleting lock: %s", lockId);
           ofy().deleteWithoutBackup().entity(Lock.this);
+          lockMetrics.recordRelease(
+              resourceName, tld, new Duration(acquiredTime, ofy().getTransactionTime()));
         } else {
           logger.severefmt(
               "The lock we acquired was transferred to someone else before we"

java/google/registry/model/server/LockMetrics.java

@@ -16,30 +16,57 @@ package google.registry.model.server;
 
 import com.google.common.collect.ImmutableSet;
 import google.registry.model.server.Lock.LockState;
+import google.registry.monitoring.metrics.DistributionFitter;
+import google.registry.monitoring.metrics.EventMetric;
+import google.registry.monitoring.metrics.ExponentialFitter;
 import google.registry.monitoring.metrics.IncrementableMetric;
 import google.registry.monitoring.metrics.LabelDescriptor;
 import google.registry.monitoring.metrics.MetricRegistryImpl;
 import javax.annotation.Nullable;
+import org.joda.time.Duration;
 
 /** Metrics for lock contention. */
 class LockMetrics {
 
-  private static final ImmutableSet<LabelDescriptor> LABEL_DESCRIPTORS =
+  private static final ImmutableSet<LabelDescriptor> REQUEST_LABEL_DESCRIPTORS =
       ImmutableSet.of(
           LabelDescriptor.create("tld", "TLD"),
           LabelDescriptor.create("resource", "resource name"),
           LabelDescriptor.create(
               "state", "The existing lock state (before attempting to acquire)."));
 
+  private static final ImmutableSet<LabelDescriptor> RELEASE_LABEL_DESCRIPTORS =
+      ImmutableSet.of(
+          LabelDescriptor.create("tld", "TLD"),
+          LabelDescriptor.create("resource", "resource name"));
+
+  // Finer-grained fitter than the DEFAULT_FITTER, allows values between 10 and 10*2^20, which
+  // gives almost 3 hours.
+  private static final DistributionFitter EXPONENTIAL_FITTER =
+      ExponentialFitter.create(20, 2.0, 10.0);
+
   private static final IncrementableMetric lockRequestsMetric =
       MetricRegistryImpl.getDefault()
           .newIncrementableMetric(
               "/lock/acquire_lock_requests",
               "Count of lock acquisition attempts",
               "count",
-              LABEL_DESCRIPTORS);
+              REQUEST_LABEL_DESCRIPTORS);
 
-  void record(String resourceName, @Nullable String tld, LockState state) {
+  private static final EventMetric lockLifetimeMetric =
+      MetricRegistryImpl.getDefault()
+          .newEventMetric(
+              "/lock/lock_duration",
+              "Lock lifetime",
+              "milliseconds",
+              RELEASE_LABEL_DESCRIPTORS,
+              EXPONENTIAL_FITTER);
+
+  void recordAcquire(String resourceName, @Nullable String tld, LockState state) {
     lockRequestsMetric.increment(String.valueOf(tld), resourceName, state.name());
   }
+
+  void recordRelease(String resourceName, @Nullable String tld, Duration duration) {
+    lockLifetimeMetric.record(duration.getMillis(), String.valueOf(tld), resourceName);
+  }
 }

javatests/google/registry/model/schema.txt

@@ -861,6 +861,9 @@ class google.registry.model.server.KmsSecretRevision {
 class google.registry.model.server.Lock {
   @Id java.lang.String lockId;
   java.lang.String requestLogId;
+  java.lang.String resourceName;
+  java.lang.String tld;
+  org.joda.time.DateTime acquiredTime;
   org.joda.time.DateTime expirationTime;
 }
 class google.registry.model.server.ServerSecret {

javatests/google/registry/model/server/LockTest.java

@@ -47,6 +47,7 @@ public class LockTest {
   private static final Duration ONE_DAY = Duration.standardDays(1);
   private static final Duration TWO_MILLIS = Duration.millis(2);
   private static final RequestStatusChecker requestStatusChecker = mock(RequestStatusChecker.class);
+  private static final FakeClock clock = new FakeClock();
 
   @Rule
   public final AppEngineRule appEngine = AppEngineRule.builder()
@@ -62,14 +63,24 @@ public class LockTest {
   private Optional<Lock> acquire(String tld, Duration leaseLength, LockState expectedLockState) {
     Lock.lockMetrics = mock(LockMetrics.class);
     Optional<Lock> lock = Lock.acquire(RESOURCE_NAME, tld, leaseLength, requestStatusChecker);
-    verify(Lock.lockMetrics).record(RESOURCE_NAME, tld, expectedLockState);
+    verify(Lock.lockMetrics).recordAcquire(RESOURCE_NAME, tld, expectedLockState);
     verifyNoMoreInteractions(Lock.lockMetrics);
     Lock.lockMetrics = null;
     return lock;
   }
 
+  private void release(Lock lock, String expectedTld, long expectedMillis) {
+    Lock.lockMetrics = mock(LockMetrics.class);
+    lock.release();
+    verify(Lock.lockMetrics)
+        .recordRelease(RESOURCE_NAME, expectedTld, Duration.millis(expectedMillis));
+    verifyNoMoreInteractions(Lock.lockMetrics);
+    Lock.lockMetrics = null;
+  }
+
 
   @Before public void setUp() {
+    inject.setStaticField(Ofy.class, "clock", clock);
     Lock.lockMetrics = null;
     when(requestStatusChecker.getLogId()).thenReturn("current-request-id");
     when(requestStatusChecker.isRunning("current-request-id")).thenReturn(true);
@@ -82,14 +93,13 @@ public class LockTest {
     // We can't get it again at the same time.
     assertThat(acquire("", ONE_DAY, IN_USE)).isEmpty();
     // But if we release it, it's available.
-    lock.get().release();
+    clock.advanceBy(Duration.millis(123));
+    release(lock.get(), "", 123);
     assertThat(acquire("", ONE_DAY, FREE)).isPresent();
   }
 
   @Test
   public void testReleasedAfterTimeout() throws Exception {
-    FakeClock clock = new FakeClock();
-    inject.setStaticField(Ofy.class, "clock", clock);
     assertThat(acquire("", TWO_MILLIS, FREE)).isPresent();
     // We can't get it again at the same time.
     assertThat(acquire("", TWO_MILLIS, IN_USE)).isEmpty();
@@ -121,7 +131,8 @@ public class LockTest {
     // We can't get lockB again at the same time.
     assertThat(acquire("b", ONE_DAY, IN_USE)).isEmpty();
     // Releasing lockA has no effect on lockB (even though we are still using the "b" tld).
-    lockA.get().release();
+    clock.advanceOneMilli();
+    release(lockA.get(), "a", 1);
     assertThat(acquire("b", ONE_DAY, IN_USE)).isEmpty();
   }