a fix and a bunch of debugging changes
diff --git a/asterix-app/src/main/resources/asterix-build-configuration.xml b/asterix-app/src/main/resources/asterix-build-configuration.xml
index d798cd5..5af3372 100644
--- a/asterix-app/src/main/resources/asterix-build-configuration.xml
+++ b/asterix-app/src/main/resources/asterix-build-configuration.xml
@@ -36,7 +36,7 @@
<property>
<name>log.level</name>
- <value>WARNING</value>
+ <value>INFO</value>
<description>Log level for running tests/build</description>
</property>
<property>
diff --git a/asterix-installer/src/test/resources/transactionts/testsuite.xml b/asterix-installer/src/test/resources/transactionts/testsuite.xml
index f2bd2b5..01d5329 100644
--- a/asterix-installer/src/test/resources/transactionts/testsuite.xml
+++ b/asterix-installer/src/test/resources/transactionts/testsuite.xml
@@ -22,89 +22,7 @@
</compilation-unit>
</test-case>
- <test-case FilePath="recover_after_abort">
- <compilation-unit name="primary_plus_default_secondary_index">
- <output-dir compare="Text">primary_plus_default_secondary_index</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recover_after_abort">
- <compilation-unit name="primary_plus_rtree_index">
- <output-dir compare="Text">primary_plus_rtree_index</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recover_after_abort">
- <compilation-unit name="primary_plus_keyword_secondary_index">
- <output-dir compare="Text">primary_plus_keyword_secondary_index</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recover_after_abort">
- <compilation-unit name="primary_plus_ngram_index">
- <output-dir compare="Text">primary_plus_ngram_index</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recover_after_abort">
- <compilation-unit name="primary_plus_multiple_secondary_indices">
- <output-dir compare="Text">primary_plus_multiple_secondary_indices</output-dir>
- </compilation-unit>
- </test-case>
-
</test-group>
- <test-group name="recovery_ddl">
-
- <test-case FilePath="recovery_ddl">
- <compilation-unit name="dataverse_recovery">
- <output-dir compare="Text">dataverse_recovery</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recovery_ddl">
- <compilation-unit name="datatype_recovery">
- <output-dir compare="Text">datatype_recovery</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recovery_ddl">
- <compilation-unit name="dataset_recovery">
- <output-dir compare="Text">dataset_recovery</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recovery_ddl">
- <compilation-unit name="secondary_index_recovery">
- <output-dir compare="Text">secondary_index_recovery</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recovery_ddl">
- <compilation-unit name="load_after_recovery">
- <output-dir compare="Text">load_after_recovery</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recovery_ddl">
- <compilation-unit name="insert_after_recovery">
- <output-dir compare="Text">insert_after_recovery</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recovery_ddl">
- <compilation-unit name="delete_after_recovery">
- <output-dir compare="Text">delete_after_recovery</output-dir>
- </compilation-unit>
- </test-case>
-
- <test-case FilePath="recovery_ddl">
- <compilation-unit name="function_recovery">
- <output-dir compare="Text">function_recovery</output-dir>
- </compilation-unit>
- </test-case>
-
- </test-group>
-
</test-suite>
diff --git a/asterix-maven-plugins/record-manager-generator-maven-plugin/src/main/resources/RecordManager.java b/asterix-maven-plugins/record-manager-generator-maven-plugin/src/main/resources/RecordManager.java
index 39a344e..ee66969 100644
--- a/asterix-maven-plugins/record-manager-generator-maven-plugin/src/main/resources/RecordManager.java
+++ b/asterix-maven-plugins/record-manager-generator-maven-plugin/src/main/resources/RecordManager.java
@@ -23,7 +23,7 @@
public static final boolean CHECK_SLOTS = @DEBUG@;
public static final boolean TRACK_ALLOC_LOC = @DEBUG@;
- static final int NO_SLOTS = 1000;
+ static final int NO_SLOTS = 20;
@CONSTS@
diff --git a/asterix-transactions/pom.xml b/asterix-transactions/pom.xml
index 27a1de4..5e6b741 100644
--- a/asterix-transactions/pom.xml
+++ b/asterix-transactions/pom.xml
@@ -38,7 +38,7 @@
<artifactId>record-manager-generator-maven-plugin</artifactId>
<version>0.8.4-SNAPSHOT</version>
<configuration>
- <debug>false</debug>
+ <debug>true</debug>
<inputFiles>
<param>src/main/java/edu/uci/ics/asterix/transaction/management/service/locking/Job.json</param>
<param>src/main/java/edu/uci/ics/asterix/transaction/management/service/locking/Resource.json</param>
diff --git a/asterix-transactions/src/main/java/edu/uci/ics/asterix/transaction/management/service/locking/ConcurrentLockManager.java b/asterix-transactions/src/main/java/edu/uci/ics/asterix/transaction/management/service/locking/ConcurrentLockManager.java
index ba8d86d..9597ca9 100644
--- a/asterix-transactions/src/main/java/edu/uci/ics/asterix/transaction/management/service/locking/ConcurrentLockManager.java
+++ b/asterix-transactions/src/main/java/edu/uci/ics/asterix/transaction/management/service/locking/ConcurrentLockManager.java
@@ -45,7 +45,7 @@
private static final Logger LOGGER
= Logger.getLogger(ConcurrentLockManager.class.getName());
- private static final Level LVL = Level.FINER;
+ private static final Level LVL = Level.INFO;
public static final boolean DEBUG_MODE = false;//true
@@ -159,10 +159,25 @@
} finally {
group.releaseLatch();
}
+
+ assertLocksCanBefound();
+
+ //assertLockCanBeFound(dsId, entityHashValue, lockMode, jobId);
}
private void enqueueWaiter(final ResourceGroup group, final long reqSlot, final long resSlot, final long jobSlot,
final LockAction act, ITransactionContext txnContext) throws ACIDException {
+ if (LOGGER.isLoggable(LVL)) {
+ StringBuilder sb = new StringBuilder();
+ final int jobId = jobArenaMgr.getJobId(jobSlot);
+ final int datasetId = resArenaMgr.getDatasetId(resSlot);
+ final int pkHashVal = resArenaMgr.getPkHashVal(resSlot);
+ sb.append("job " + jobId + " wants to ");
+ sb.append(act.modify ? "upgrade lock" : "wait");
+ sb.append(" for [" + datasetId + ", " + pkHashVal + "]");
+ LOGGER.log(LVL, sb.toString());
+ }
+
final Queue queue = act.modify ? upgrader : waiter;
if (introducesDeadlock(resSlot, jobSlot, NOPTracker.INSTANCE)) {
DeadlockTracker tracker = new CollectingTracker();
@@ -478,7 +493,10 @@
if (resource < 0) {
throw new IllegalStateException("resource (" + dsId + ", " + entityHashValue + ") not found");
}
-
+
+ assertLocksCanBefound();
+ //assertLockCanBeFound(dsId, entityHashValue, lockMode, jobArenaMgr.getJobId(jobSlot));
+
long holder = removeLastHolder(resource, jobSlot, lockMode);
// deallocate request
@@ -548,9 +566,15 @@
jobArenaMgr.deallocate(jobSlot);
jobIdSlotMap.remove(jobId);
stats.logCounters(LOGGER, Level.INFO, true);
+ if (LOGGER.isLoggable(LVL)) {
+ LOGGER.log(LVL, "after releaseLocks");
+ LOGGER.log(LVL, "jobArenaMgr " + jobArenaMgr.addTo(new RecordManagerStats()).toString());
+ LOGGER.log(LVL, "resArenaMgr " + resArenaMgr.addTo(new RecordManagerStats()).toString());
+ LOGGER.log(LVL, "reqArenaMgr " + reqArenaMgr.addTo(new RecordManagerStats()).toString());
+ }
//LOGGER.info(toString());
}
-
+
private long findOrAllocJobSlot(int jobId) {
Long jobSlot = jobIdSlotMap.get(jobId);
if (jobSlot == null) {
@@ -604,10 +628,11 @@
private LockAction determineLockAction(long resSlot, long jobSlot, byte lockMode) {
final int curLockMode = resArenaMgr.getMaxMode(resSlot);
- final LockAction act = ACTION_MATRIX[curLockMode][lockMode];
+ LockAction act = ACTION_MATRIX[curLockMode][lockMode];
if (act == LockAction.WAIT) {
- return updateActionForSameJob(resSlot, jobSlot, lockMode);
+ act = updateActionForSameJob(resSlot, jobSlot, lockMode);
}
+ LOGGER.info("determineLockAction(" + resSlot + ", " + jobSlot + ", " + lockMode + ") -> " + act);
return act;
}
@@ -669,6 +694,7 @@
insertIntoJobQueue(request, lastJobHolder);
jobArenaMgr.setLastHolder(job, request);
}
+ //assertLocksCanBefound();
}
private long removeLastHolder(long resource, long jobSlot, byte lockMode) {
@@ -676,7 +702,8 @@
if (holder < 0) {
throw new IllegalStateException("no holder for resource " + resource);
}
-
+ assertLocksCanBefound();
+ LOGGER.info(resQueueToString(resource));
// remove from the list of holders for a resource
if (requestMatches(holder, jobSlot, lockMode)) {
// if the head of the queue matches, we need to update the resource
@@ -685,12 +712,10 @@
} else {
holder = removeRequestFromQueueForJob(holder, jobSlot, lockMode);
}
-
- synchronized (jobArenaMgr) {
- // remove from the list of requests for a job
- long newHead = removeRequestFromJob(jobSlot, holder);
- jobArenaMgr.setLastHolder(jobSlot, newHead);
- }
+ LOGGER.info(resQueueToString(resource));
+ removeRequestFromJob(jobSlot, holder);
+ LOGGER.info(resQueueToString(resource));
+ assertLocksCanBefound();
return holder;
}
@@ -699,17 +724,19 @@
&& (lockMode == LockMode.ANY || lockMode == reqArenaMgr.getLockMode(holder));
}
- private long removeRequestFromJob(long jobSlot, long holder) {
- long prevForJob = reqArenaMgr.getPrevJobRequest(holder);
- long nextForJob = reqArenaMgr.getNextJobRequest(holder);
- if (nextForJob != -1) {
- reqArenaMgr.setPrevJobRequest(nextForJob, prevForJob);
- }
- if (prevForJob == -1) {
- return nextForJob;
- } else {
- reqArenaMgr.setNextJobRequest(prevForJob, nextForJob);
- return -1;
+ private void removeRequestFromJob(long jobSlot, long holder) {
+ synchronized (jobArenaMgr) {
+ long prevForJob = reqArenaMgr.getPrevJobRequest(holder);
+ long nextForJob = reqArenaMgr.getNextJobRequest(holder);
+ if (nextForJob != -1) {
+ reqArenaMgr.setPrevJobRequest(nextForJob, prevForJob);
+ }
+ if (prevForJob == -1) {
+ // this was the first request for the job
+ jobArenaMgr.setLastHolder(jobSlot, nextForJob);
+ } else {
+ reqArenaMgr.setNextJobRequest(prevForJob, nextForJob);
+ }
}
}
@@ -733,6 +760,7 @@
insertIntoJobQueue(request, waiter);
jobArenaMgr.setLastWaiter(job, request);
}
+ //assertLocksCanBefound();
}
public void remove(long request, long resource, long job) {
@@ -743,11 +771,8 @@
} else {
waiter = removeRequestFromQueueForSlot(waiter, request);
}
- synchronized (jobArenaMgr) {
- // remove from the list of requests for a job
- long newHead = removeRequestFromJob(job, waiter);
- jobArenaMgr.setLastWaiter(job, newHead);
- }
+ removeRequestFromJob(job, waiter);
+ //assertLocksCanBefound();
}
};
@@ -765,6 +790,7 @@
insertIntoJobQueue(request, upgrader);
jobArenaMgr.setLastUpgrader(job, request);
}
+ //assertLocksCanBefound();
}
public void remove(long request, long resource, long job) {
@@ -775,15 +801,13 @@
} else {
upgrader = removeRequestFromQueueForSlot(upgrader, request);
}
- synchronized (jobArenaMgr) {
- // remove from the list of requests for a job
- long newHead = removeRequestFromJob(job, upgrader);
- jobArenaMgr.setLastUpgrader(job, newHead);
- }
+ removeRequestFromJob(job, upgrader);
+ //assertLocksCanBefound();
}
};
private void insertIntoJobQueue(long newRequest, long oldRequest) {
+ LOGGER.info("insertIntoJobQueue(" + newRequest + ", " + oldRequest + ")");
reqArenaMgr.setNextJobRequest(newRequest, oldRequest);
reqArenaMgr.setPrevJobRequest(newRequest, -1);
if (oldRequest >= 0) {
@@ -820,7 +844,7 @@
/**
* remove the first request for a given job and lock mode from a request queue.
- * If the value of the parameter lockMode is LockMode.NL the first request
+ * If the value of the parameter lockMode is LockMode.ANY the first request
* for the job is removed - independent of the LockMode.
*
* @param head
@@ -849,6 +873,106 @@
return holder;
}
+ private String resQueueToString(long head) {
+ return appendResQueue(new StringBuilder(), head).toString();
+ }
+
+ private StringBuilder appendResQueue(StringBuilder sb, long resSlot) {
+ appendResource(sb, resSlot);
+ sb.append("\n");
+ appendReqQueue(sb, resArenaMgr.getLastHolder(resSlot));
+ return sb;
+ }
+
+ private StringBuilder appendReqQueue(StringBuilder sb, long head) {
+ while (head != -1) {
+ appendRequest(sb, head);
+ sb.append("\n");
+ head = reqArenaMgr.getNextRequest(head);
+ }
+ return sb;
+ }
+
+ private void appendResource(StringBuilder sb, long resSlot) {
+ sb.append("{ ");
+
+ sb.append(" \"dataset id\"");
+ sb.append(" : \"");
+ sb.append(resArenaMgr.getDatasetId(resSlot));
+
+ sb.append("\", ");
+
+ sb.append(" \"pk hash val\"");
+ sb.append(" : \"");
+ sb.append(resArenaMgr.getPkHashVal(resSlot));
+
+ sb.append("\", ");
+
+ sb.append(" \"max mode\"");
+ sb.append(" : \"");
+ sb.append(LockMode.toString((byte)resArenaMgr.getMaxMode(resSlot)));
+
+ sb.append("\", ");
+
+ sb.append(" \"last holder\"");
+ sb.append(" : \"");
+ TypeUtil.Global.append(sb, resArenaMgr.getLastHolder(resSlot));
+
+ sb.append("\", ");
+
+ sb.append(" \"first waiter\"");
+ sb.append(" : \"");
+ TypeUtil.Global.append(sb, resArenaMgr.getFirstWaiter(resSlot));
+
+ sb.append("\", ");
+
+ sb.append(" \"first upgrader\"");
+ sb.append(" : \"");
+ TypeUtil.Global.append(sb, resArenaMgr.getFirstUpgrader(resSlot));
+
+ sb.append("\", ");
+
+ sb.append(" \"next\"");
+ sb.append(" : \"");
+ TypeUtil.Global.append(sb, resArenaMgr.getNext(resSlot));
+
+ sb.append("\" }");
+ }
+
+ private void appendRequest(StringBuilder sb, long reqSlot) {
+ sb.append("{ ");
+
+ sb.append(" \"resource id\"");
+ sb.append(" : \"");
+ TypeUtil.Global.append(sb, reqArenaMgr.getResourceId(reqSlot));
+
+ sb.append("\", ");
+
+ sb.append(" \"lock mode\"");
+ sb.append(" : \"");
+ sb.append(LockMode.toString((byte)reqArenaMgr.getLockMode(reqSlot)));
+
+ sb.append("\", ");
+
+ sb.append(" \"job slot\"");
+ sb.append(" : \"");
+ TypeUtil.Global.append(sb, reqArenaMgr.getJobSlot(reqSlot));
+
+ sb.append("\", ");
+
+ sb.append(" \"prev job request\"");
+ sb.append(" : \"");
+ TypeUtil.Global.append(sb, reqArenaMgr.getPrevJobRequest(reqSlot));
+
+ sb.append("\", ");
+
+ sb.append(" \"next job request\"");
+ sb.append(" : \"");
+ TypeUtil.Global.append(sb, reqArenaMgr.getNextJobRequest(reqSlot));
+
+ sb.append("\" }");
+ }
+
private int determineNewMaxMode(long resource, int oldMaxMode) {
int newMaxMode = LockMode.NL;
long holder = resArenaMgr.getLastHolder(resource);
@@ -865,6 +989,8 @@
case GET:
break;
case WAIT:
+ case CONV:
+ case ERR:
throw new IllegalStateException("incompatible locks in holder queue");
}
holder = reqArenaMgr.getNextRequest(holder);
@@ -895,6 +1021,7 @@
if (txnContext != null) {
sb.append(" , jobId : ").append(txnContext.getJobId());
}
+ sb.append(" , thread : ").append(Thread.currentThread().getName());
sb.append(" }");
LOGGER.log(LVL, sb.toString());
}
@@ -913,6 +1040,71 @@
+ " should abort (requested by the Lock Manager)" + ":\n" + msg);
}
+ private void assertLocksCanBefound() {
+ for (int i = 0; i < ResourceGroupTable.TABLE_SIZE; ++i) {
+ final ResourceGroup group = table.table[i];
+ group.getLatch();
+ long resSlot = group.firstResourceIndex.get();
+ while (resSlot != -1) {
+ int dsId = resArenaMgr.getDatasetId(resSlot);
+ int entityHashValue = resArenaMgr.getPkHashVal(resSlot);
+ long reqSlot = resArenaMgr.getLastHolder(resSlot);
+ while (reqSlot != -1) {
+ byte lockMode = (byte) reqArenaMgr.getLockMode(reqSlot);
+ long jobSlot = reqArenaMgr.getJobSlot(reqSlot);
+ int jobId = jobArenaMgr.getJobId(jobSlot);
+ assertLockCanBeFound(dsId, entityHashValue, lockMode, jobId);
+ reqSlot = reqArenaMgr.getNextRequest(reqSlot);
+ }
+ resSlot = resArenaMgr.getNext(resSlot);
+ }
+ group.releaseLatch();
+ }
+ }
+
+ private void assertLockCanBeFound(int dsId, int entityHashValue, byte lockMode, int jobId) {
+ if (!findLock(dsId, entityHashValue, jobId, lockMode)) {
+ String msg = "request for " + LockMode.toString(lockMode) + " lock on dataset " + dsId + " entity "
+ + entityHashValue + " not found for job " + jobId + " in thread " + Thread.currentThread().getName();
+ LOGGER.severe(msg);
+ throw new IllegalStateException(msg);
+ }
+ }
+
+ /**
+ * tries to find a lock request searching though the job queue
+ * @param dsId dataset id
+ * @param entityHashValue primary key hash value
+ * @param jobId job id
+ * @param lockMode lock mode
+ * @return true, if the lock request is found, false otherwise
+ */
+ private boolean findLock(final int dsId, final int entityHashValue, final int jobId, byte lockMode) {
+ Long jobSlot = jobIdSlotMap.get(jobId);
+ if (jobSlot == null) {
+ return false;
+ }
+
+ long holder;
+ synchronized (jobArenaMgr) {
+ holder = jobArenaMgr.getLastHolder(jobSlot);
+ }
+ while (holder != -1) {
+ long resource = reqArenaMgr.getResourceId(holder);
+ if (dsId == resArenaMgr.getDatasetId(resource)
+ && entityHashValue == resArenaMgr.getPkHashVal(resource)
+ && jobSlot == reqArenaMgr.getJobSlot(holder)
+ && (lockMode == reqArenaMgr.getLockMode(holder)
+ || lockMode == LockMode.ANY)) {
+ return true;
+ }
+ synchronized (jobArenaMgr) {
+ holder = reqArenaMgr.getNextJobRequest(holder);
+ }
+ }
+ return false;
+ }
+
public StringBuilder append(StringBuilder sb) {
table.getAllLatches();
try {
@@ -1015,7 +1207,7 @@
private static class ResourceGroupTable {
public static final int TABLE_SIZE = 1024; // TODO increase?
- private ResourceGroup[] table;
+ ResourceGroup[] table;
public ResourceGroupTable() {
table = new ResourceGroup[TABLE_SIZE];
@@ -1023,6 +1215,7 @@
table[i] = new ResourceGroup();
}
}
+
ResourceGroup get(int dId, int entityHashValue) {
// TODO ensure good properties of hash function
int h = Math.abs(dId ^ entityHashValue);
@@ -1101,13 +1294,13 @@
}
void log(String s) {
- if (LOGGER.isLoggable(LVL)) {
+ if (LOGGER.isLoggable(Level.FINER)) {
LOGGER.log(LVL, s + " " + toString());
}
}
public String toString() {
- return "{ id : " + hashCode() + ", first : " + firstResourceIndex.toString() + ", waiters : "
+ return "{ id : " + hashCode() + ", first : " + TypeUtil.Global.toString(firstResourceIndex.get()) + ", waiters : "
+ (hasWaiters() ? "true" : "false") + " }";
}
}