diff --git a/java/google/registry/model/server/Lock.java b/java/google/registry/model/server/Lock.java index daf50d94d..f8579d97e 100644 --- a/java/google/registry/model/server/Lock.java +++ b/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" diff --git a/java/google/registry/model/server/LockMetrics.java b/java/google/registry/model/server/LockMetrics.java index 436efd70b..ee772fd0e 100644 --- a/java/google/registry/model/server/LockMetrics.java +++ b/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 LABEL_DESCRIPTORS = + private static final ImmutableSet 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 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); + } } diff --git a/javatests/google/registry/model/schema.txt b/javatests/google/registry/model/schema.txt index 8897d7620..22664bf20 100644 --- a/javatests/google/registry/model/schema.txt +++ b/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 { diff --git a/javatests/google/registry/model/server/LockTest.java b/javatests/google/registry/model/server/LockTest.java index c3e9d3b06..2f843a35f 100644 --- a/javatests/google/registry/model/server/LockTest.java +++ b/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 acquire(String tld, Duration leaseLength, LockState expectedLockState) { Lock.lockMetrics = mock(LockMetrics.class); Optional 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(); }