Add info printouts for lock acquisition / release

Trying to debug lock acquisition issues with RdeStaging.

-------------
Created by MOE: https://github.com/google/moe
MOE_MIGRATED_REVID=161966189
This commit is contained in:
guyben 2017-07-14 09:28:49 -07:00 committed by Ben McIlwain
parent 7d7048ac12
commit bfde7dac0b

View file

@ -126,12 +126,20 @@ public class Lock extends ImmutableObject {
return ofy().transactNew(new Work<Lock>() { return ofy().transactNew(new Work<Lock>() {
@Override @Override
public Lock run() { public Lock run() {
Lock lock = ofy().load().type(Lock.class).id(makeLockId(resourceName, tld)).now(); String lockId = makeLockId(resourceName, tld);
Lock lock = ofy().load().type(Lock.class).id(lockId).now();
if (lock == null || isAtOrAfter(ofy().getTransactionTime(), lock.expirationTime)) { if (lock == null || isAtOrAfter(ofy().getTransactionTime(), lock.expirationTime)) {
String requesterName = (requester == null) ? "" : requester.getCanonicalName(); String requesterName = (requester == null) ? "" : requester.getCanonicalName();
if (!getFirst(nullToEmpty((lock == null) ? null : lock.queue), requesterName) String firstInQueue =
.equals(requesterName)) { getFirst(nullToEmpty((lock == null) ? null : lock.queue), requesterName);
if (!firstInQueue.equals(requesterName)) {
// Another class is at the top of the queue; we can't acquire the lock. // Another class is at the top of the queue; we can't acquire the lock.
logger.infofmt(
"Another class %s is first in queue (size %d) instead of requested %s for lock: %s",
firstInQueue,
lock.queue.size(),
requesterName,
lockId);
return null; return null;
} }
Lock newLock = create( Lock newLock = create(
@ -143,8 +151,17 @@ public class Lock extends ImmutableObject {
// Locks are not parented under an EntityGroupRoot (so as to avoid write contention) and // Locks are not parented under an EntityGroupRoot (so as to avoid write contention) and
// don't need to be backed up. // don't need to be backed up.
ofy().saveWithoutBackup().entity(newLock); ofy().saveWithoutBackup().entity(newLock);
logger.infofmt(
"acquire succeeded %s lock: %s",
newLock,
lockId);
return newLock; return newLock;
} }
logger.infofmt(
"Existing lock is still valid now %s (until %s) lock: %s",
ofy().getTransactionTime(),
lock.expirationTime,
lockId);
return null; return null;
}}); }});
} }
@ -161,7 +178,10 @@ public class Lock extends ImmutableObject {
Lock loadedLock = ofy().load().type(Lock.class).id(lockId).now(); Lock loadedLock = ofy().load().type(Lock.class).id(lockId).now();
if (Lock.this.equals(loadedLock)) { if (Lock.this.equals(loadedLock)) {
// Use noBackupOfy() so that we don't create a commit log entry for deleting the lock. // 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); ofy().deleteWithoutBackup().entity(Lock.this);
} else {
logger.infofmt("Not deleting lock: %s - someone else has it: %s", lockId, loadedLock);
} }
}}); }});
} }