Add primary time measurements to MusicCore 43/75043/3
authorMohammad Salehe <salehe@cs.toronto.edu>
Wed, 28 Nov 2018 00:07:34 +0000 (19:07 -0500)
committerMohammad Salehe <salehe@cs.toronto.edu>
Sat, 22 Dec 2018 20:07:11 +0000 (15:07 -0500)
Add time measurements to MusicCore.atomicPut and
dependent Cassandra execute path

Change-Id: I44455d7232e12d29a648c3d59d9aa102bf1ab232
Issue-ID: MUSIC-148
Signed-off-by: Mohammad Salehe <salehe@cs.toronto.edu>
src/main/java/org/onap/music/datastore/MusicDataStore.java
src/main/java/org/onap/music/lockingservice/cassandra/CassaLockStore.java
src/main/java/org/onap/music/service/impl/MusicCassaCore.java
src/main/java/org/onap/music/testruns/ComparisonPoints1.java

index 72385d1..a10f31e 100644 (file)
@@ -42,6 +42,7 @@ import com.datastax.driver.core.ColumnDefinitions.Definition;
 import com.datastax.driver.core.exceptions.AlreadyExistsException;
 import com.datastax.driver.core.exceptions.InvalidQueryException;
 import com.datastax.driver.core.exceptions.NoHostAvailableException;
+import org.onap.music.util.TimeMeasureInstance;
 
 /**
  * @author nelson24
@@ -308,58 +309,60 @@ public class MusicDataStore {
      */
     public boolean executePut(PreparedQueryObject queryObject, String consistencyLevel, long timeSlot)
             throws MusicServiceException, MusicQueryException {
-
-        boolean result = false;
-        long timeOfWrite = System.currentTimeMillis();
-
-        if (!MusicUtil.isValidQueryObject(!queryObject.getValues().isEmpty(), queryObject)) {
-               logger.error(EELFLoggerDelegate.errorLogger, queryObject.getQuery(),AppMessages.QUERYERROR, ErrorSeverity.ERROR, ErrorTypes.QUERYERROR);
-            throw new MusicQueryException("Ill formed queryObject for the request = " + "["
-                            + queryObject.getQuery() + "]");
-        }
-        logger.info(EELFLoggerDelegate.applicationLogger,
-                        "In preprared Execute Put: the actual insert query:"
-                                        + queryObject.getQuery() + "; the values"
-                                        + queryObject.getValues());
-        SimpleStatement statement;
+        TimeMeasureInstance.instance().enter("executePut");
         try {
+            boolean result;
+            long timeOfWrite = System.currentTimeMillis();
 
-             statement = new SimpleStatement(queryObject.getQuery(), queryObject.getValues().toArray());
-        } catch(InvalidQueryException iqe) {
-               logger.error(EELFLoggerDelegate.errorLogger, iqe.getMessage(),AppMessages.QUERYERROR, ErrorSeverity.CRITICAL, ErrorTypes.QUERYERROR);
-               throw new MusicQueryException(iqe.getMessage());
-        }catch(Exception e) {
-               logger.error(EELFLoggerDelegate.errorLogger, e.getMessage(),AppMessages.QUERYERROR, ErrorSeverity.CRITICAL, ErrorTypes.QUERYERROR);
-               throw new MusicQueryException(e.getMessage());
-        }
-        
-        try {
-            if (consistencyLevel.equalsIgnoreCase(MusicUtil.CRITICAL)) {
-                logger.info(EELFLoggerDelegate.applicationLogger, "Executing critical put query");
-                statement.setConsistencyLevel(ConsistencyLevel.QUORUM);
-            } else if (consistencyLevel.equalsIgnoreCase(MusicUtil.EVENTUAL)) {
-                logger.info(EELFLoggerDelegate.applicationLogger, "Executing simple put query");
-                statement.setConsistencyLevel(ConsistencyLevel.ONE);
+            if (!MusicUtil.isValidQueryObject(!queryObject.getValues().isEmpty(), queryObject)) {
+                logger.error(EELFLoggerDelegate.errorLogger, queryObject.getQuery(), AppMessages.QUERYERROR, ErrorSeverity.ERROR, ErrorTypes.QUERYERROR);
+                throw new MusicQueryException("Ill formed queryObject for the request = " + "["
+                        + queryObject.getQuery() + "]");
             }
+            logger.info(EELFLoggerDelegate.applicationLogger,
+                    "In preprared Execute Put: the actual insert query:"
+                            + queryObject.getQuery() + "; the values"
+                            + queryObject.getValues());
+            SimpleStatement statement;
+            try {
 
-            long timestamp = MusicUtil.v2sTimeStampInMicroseconds(timeSlot, timeOfWrite);
-            statement.setDefaultTimestamp(timestamp);
+                statement = new SimpleStatement(queryObject.getQuery(), queryObject.getValues().toArray());
+            } catch (InvalidQueryException iqe) {
+                logger.error(EELFLoggerDelegate.errorLogger, iqe.getMessage(), AppMessages.QUERYERROR, ErrorSeverity.CRITICAL, ErrorTypes.QUERYERROR);
+                throw new MusicQueryException(iqe.getMessage());
+            } catch (Exception e) {
+                logger.error(EELFLoggerDelegate.errorLogger, e.getMessage(), AppMessages.QUERYERROR, ErrorSeverity.CRITICAL, ErrorTypes.QUERYERROR);
+                throw new MusicQueryException(e.getMessage());
+            }
 
-            ResultSet rs = session.execute(statement);
-            result = rs.wasApplied();
-        }
-        catch (AlreadyExistsException ae) {
-            logger.error(EELFLoggerDelegate.errorLogger, ae.getMessage(),AppMessages.SESSIONFAILED+ " [" + queryObject.getQuery() + "]", ErrorSeverity.ERROR, ErrorTypes.QUERYERROR);
-               throw new MusicServiceException(ae.getMessage());
-        }
-        catch (Exception e) {
-               logger.error(EELFLoggerDelegate.errorLogger, e.getMessage(),AppMessages.SESSIONFAILED+ " [" + queryObject.getQuery() + "]", ErrorSeverity.ERROR, ErrorTypes.QUERYERROR);
-               throw new MusicQueryException("Executing Session Failure for Request = " + "["
-                            + queryObject.getQuery() + "]" + " Reason = " + e.getMessage());
-        }
+            try {
+                if (consistencyLevel.equalsIgnoreCase(MusicUtil.CRITICAL)) {
+                    logger.info(EELFLoggerDelegate.applicationLogger, "Executing critical put query");
+                    statement.setConsistencyLevel(ConsistencyLevel.QUORUM);
+                } else if (consistencyLevel.equalsIgnoreCase(MusicUtil.EVENTUAL)) {
+                    logger.info(EELFLoggerDelegate.applicationLogger, "Executing simple put query");
+                    statement.setConsistencyLevel(ConsistencyLevel.ONE);
+                }
 
+                long timestamp = MusicUtil.v2sTimeStampInMicroseconds(timeSlot, timeOfWrite);
+                statement.setDefaultTimestamp(timestamp);
+
+                ResultSet rs = session.execute(statement);
+                result = rs.wasApplied();
+            } catch (AlreadyExistsException ae) {
+                logger.error(EELFLoggerDelegate.errorLogger, ae.getMessage(), AppMessages.SESSIONFAILED + " [" + queryObject.getQuery() + "]", ErrorSeverity.ERROR, ErrorTypes.QUERYERROR);
+                throw new MusicServiceException(ae.getMessage());
+            } catch (Exception e) {
+                logger.error(EELFLoggerDelegate.errorLogger, e.getMessage(), AppMessages.SESSIONFAILED + " [" + queryObject.getQuery() + "]", ErrorSeverity.ERROR, ErrorTypes.QUERYERROR);
+                throw new MusicQueryException("Executing Session Failure for Request = " + "["
+                        + queryObject.getQuery() + "]" + " Reason = " + e.getMessage());
+            }
 
-        return result;
+            return result;
+        }
+        finally {
+            TimeMeasureInstance.instance().exit();
+        }
     }
 
     /**
@@ -405,7 +408,13 @@ public class MusicDataStore {
      */
     public ResultSet executeOneConsistencyGet(PreparedQueryObject queryObject)
                     throws MusicServiceException, MusicQueryException {
-        return executeGet(queryObject, CONSISTENCY_LEVEL_ONE);
+        TimeMeasureInstance.instance().enter("executeOneConsistencyGet");
+        try {
+            return executeGet(queryObject, CONSISTENCY_LEVEL_ONE);
+        }
+        finally {
+            TimeMeasureInstance.instance().exit();
+        }
     }
 
     /**
@@ -416,7 +425,13 @@ public class MusicDataStore {
      */
     public ResultSet executeQuorumConsistencyGet(PreparedQueryObject queryObject)
                     throws MusicServiceException, MusicQueryException {
-        return executeGet(queryObject, CONSISTENCY_LEVEL_QUORUM);
+        TimeMeasureInstance.instance().enter("executeQuorumConsistencyGet");
+        try {
+            return executeGet(queryObject, CONSISTENCY_LEVEL_QUORUM);
+        }
+        finally {
+            TimeMeasureInstance.instance().exit();
+        }
     }
 }
 
index 8065bf6..51a7826 100644 (file)
@@ -11,6 +11,7 @@ import org.onap.music.exceptions.MusicServiceException;
 
 import com.datastax.driver.core.ResultSet;
 import com.datastax.driver.core.Row;
+import org.onap.music.util.TimeMeasureInstance;
 
 /*
  * This is the lock store that is built on top of Cassandra that is used by MUSIC to maintain lock state. 
@@ -92,53 +93,59 @@ public class CassaLockStore {
         * @throws MusicQueryException
         */
        public String genLockRefandEnQueue(String keyspace, String table, String lockName, boolean isWriteLock)
-                       throws MusicServiceException, MusicQueryException {
-        logger.info(EELFLoggerDelegate.applicationLogger,
-                "Create lock reference for " +  keyspace + "." + table + "." + lockName);
-        table = table_prepend_name+table;
+               throws MusicServiceException, MusicQueryException {
+               TimeMeasureInstance.instance().enter("genLockRefandEnQueue");
+               try {
+                       logger.info(EELFLoggerDelegate.applicationLogger,
+                                       "Create lock reference for " + keyspace + "." + table + "." + lockName);
+                       table = table_prepend_name+table;
 
 
-               PreparedQueryObject queryObject = new PreparedQueryObject();
-               String selectQuery = "SELECT guard FROM " + keyspace + "." + table + " WHERE key=?;";
+                       PreparedQueryObject queryObject = new PreparedQueryObject();
+                       String selectQuery = "SELECT guard FROM " + keyspace + "." + table + " WHERE key=?;";
 
-               queryObject.addValue(lockName);
-               queryObject.appendQueryString(selectQuery);
-               ResultSet gqResult = dsHandle.executeOneConsistencyGet(queryObject);
-               List<Row> latestGuardRow = gqResult.all();
+                       queryObject.addValue(lockName);
+                       queryObject.appendQueryString(selectQuery);
+                       ResultSet gqResult = dsHandle.executeOneConsistencyGet(queryObject);
+                       List<Row> latestGuardRow = gqResult.all();
 
-               long prevGuard = 0;
-               long lockRef = 1;
-        if (latestGuardRow.size() > 0) {
-               prevGuard = latestGuardRow.get(0).getLong(0);
-               lockRef = prevGuard + 1;
-               }
+                       long prevGuard = 0;
+                       long lockRef = 1;
+                       if (latestGuardRow.size() > 0) {
+                               prevGuard = latestGuardRow.get(0).getLong(0);
+                               lockRef = prevGuard + 1;
+                       }
 
-        long lockEpochMillis = System.currentTimeMillis();
+                       long lockEpochMillis = System.currentTimeMillis();
 
 //        System.out.println("guard(" + lockName + "): " + prevGuard + "->" + lockRef);
-               logger.info(EELFLoggerDelegate.applicationLogger,
-                               "Created lock reference for " +  keyspace + "." + table + "." + lockName + ":" + lockRef);
+                       logger.info(EELFLoggerDelegate.applicationLogger,
+                                       "Created lock reference for " + keyspace + "." + table + "." + lockName + ":" + lockRef);
 
-        queryObject = new PreparedQueryObject();
-               String insQuery = "BEGIN BATCH" +
-                " UPDATE " + keyspace + "." + table +
-                               " SET guard=? WHERE key=? IF guard = " + (prevGuard == 0 ? "NULL" : "?") +";" +
-                " INSERT INTO " + keyspace + "." + table +
-                               "(key, lockReference, createTime, acquireTime, writeLock) VALUES (?,?,?,?,?) IF NOT EXISTS; APPLY BATCH;";
+                       queryObject = new PreparedQueryObject();
+                       String insQuery = "BEGIN BATCH" +
+                                       " UPDATE " + keyspace + "." + table +
+                                       " SET guard=? WHERE key=? IF guard = " + (prevGuard == 0 ? "NULL" : "?") + ";" +
+                                       " INSERT INTO " + keyspace + "." + table +
+                                       "(key, lockReference, createTime, acquireTime, writeLock) VALUES (?,?,?,?,?) IF NOT EXISTS; APPLY BATCH;";
 
-        queryObject.addValue(lockRef);
-        queryObject.addValue(lockName);
-        if (prevGuard != 0)
-               queryObject.addValue(prevGuard);
+                       queryObject.addValue(lockRef);
+                       queryObject.addValue(lockName);
+                       if (prevGuard != 0)
+                               queryObject.addValue(prevGuard);
 
-        queryObject.addValue(lockName);
-        queryObject.addValue(lockRef);
-        queryObject.addValue(String.valueOf(lockEpochMillis));
-        queryObject.addValue("0");
-        queryObject.addValue(isWriteLock);
-        queryObject.appendQueryString(insQuery);
-        boolean pResult = dsHandle.executePut(queryObject, "critical");
-               return String.valueOf(lockRef);
+                       queryObject.addValue(lockName);
+                       queryObject.addValue(lockRef);
+                       queryObject.addValue(String.valueOf(lockEpochMillis));
+                       queryObject.addValue("0");
+               queryObject.addValue(isWriteLock);
+                       queryObject.appendQueryString(insQuery);
+                       boolean pResult = dsHandle.executePut(queryObject, "critical");
+                       return String.valueOf(lockRef);
+               }
+               finally {
+                       TimeMeasureInstance.instance().exit();
+               }
        }
        
        /**
@@ -200,19 +207,25 @@ public class CassaLockStore {
         */
        public LockObject peekLockQueue(String keyspace, String table, String key)
                        throws MusicServiceException, MusicQueryException {
-        logger.info(EELFLoggerDelegate.applicationLogger,
-                "Peek in lock table for " +  keyspace+"."+table+"."+key);
-        table = table_prepend_name+table; 
-               String selectQuery = "select * from "+keyspace+"."+table+" where key='"+key+"' LIMIT 1;";       
-        PreparedQueryObject queryObject = new PreparedQueryObject();
-        queryObject.appendQueryString(selectQuery);
-               ResultSet results = dsHandle.executeOneConsistencyGet(queryObject);
-               Row row = results.one();
-               String lockReference = "" + row.getLong("lockReference");
-               String createTime = row.getString("createTime");
-               String acquireTime = row.getString("acquireTime");
+               TimeMeasureInstance.instance().enter("peekLockQueue");
+               try {
+                       logger.info(EELFLoggerDelegate.applicationLogger,
+                                       "Peek in lock table for " +  keyspace+"."+table+"."+key);
+               table = table_prepend_name+table; 
+                       String selectQuery = "select * from "+keyspace+"."+table+" where key='"+key+"' LIMIT 1;";
+                       PreparedQueryObject queryObject = new PreparedQueryObject();
+                       queryObject.appendQueryString(selectQuery);
+                       ResultSet results = dsHandle.executeOneConsistencyGet(queryObject);
+                       Row row = results.one();
+                       String lockReference = "" + row.getLong("lockReference");
+                       String createTime = row.getString("createTime");
+                       String acquireTime = row.getString("acquireTime");
 
-               return new LockObject(lockReference, createTime,acquireTime);
+                       return new LockObject(lockReference, createTime,acquireTime);
+               }
+               finally {
+                       TimeMeasureInstance.instance().exit();
+               }
        }
        
     public boolean isTopOfLockQueue(String keyspace, String table, String key, String lockRef)
@@ -255,23 +268,34 @@ public class CassaLockStore {
         * @throws MusicQueryException
         */     
        public void deQueueLockRef(String keyspace, String table, String key, String lockReference) throws MusicServiceException, MusicQueryException{
-               table = table_prepend_name+table; 
-        PreparedQueryObject queryObject = new PreparedQueryObject();
-        Long lockReferenceL = Long.parseLong(lockReference);
-        String deleteQuery = "delete from "+keyspace+"."+table+" where key='"+key+"' AND lockReference ="+lockReferenceL+" IF EXISTS;";
-        queryObject.appendQueryString(deleteQuery);
-               dsHandle.executePut(queryObject, "critical");   
+               TimeMeasureInstance.instance().enter("deQueueLockRef");
+               try {
+                          table = table_prepend_name+table; 
+                       PreparedQueryObject queryObject = new PreparedQueryObject();
+                       Long lockReferenceL = Long.parseLong(lockReference);
+                       String deleteQuery = "delete from "+keyspace+"."+table+" where key='"+key+"' AND lockReference ="+lockReferenceL+" IF EXISTS;";
+                       queryObject.appendQueryString(deleteQuery);
+                       dsHandle.executePut(queryObject, "critical");
+               }
+               finally {
+                       TimeMeasureInstance.instance().exit();
+               }
        }
        
 
        public void updateLockAcquireTime(String keyspace, String table, String key, String lockReference) throws MusicServiceException, MusicQueryException{
-               table = table_prepend_name+table;
-        PreparedQueryObject queryObject = new PreparedQueryObject();
-        Long lockReferenceL = Long.parseLong(lockReference);
-        String updateQuery = "update "+keyspace+"."+table+" set acquireTime='"+ System.currentTimeMillis()+"' where key='"+key+"' AND lockReference = "+lockReferenceL+" IF EXISTS;";
-        queryObject.appendQueryString(updateQuery);
-               dsHandle.executePut(queryObject, "eventual");   
-
+        TimeMeasureInstance.instance().enter("updateLockAcquireTime");
+        try {
+                       table = table_prepend_name+table;
+            PreparedQueryObject queryObject = new PreparedQueryObject();
+            Long lockReferenceL = Long.parseLong(lockReference);
+            String updateQuery = "update "+keyspace+"."+table+" set acquireTime='"+ System.currentTimeMillis()+"' where key='"+key+"' AND lockReference = "+lockReferenceL+";";
+            queryObject.appendQueryString(updateQuery);
+            dsHandle.executePut(queryObject, "eventual");
+        }
+        finally {
+            TimeMeasureInstance.instance().exit();
+        }
        }
        
 
index f897c18..7966282 100644 (file)
@@ -54,6 +54,7 @@ import com.datastax.driver.core.DataType;
 import com.datastax.driver.core.ResultSet;
 import com.datastax.driver.core.Row;
 import com.datastax.driver.core.TableMetadata;
+import org.onap.music.util.TimeMeasureInstance;
 
 
 /**
@@ -102,22 +103,28 @@ public class MusicCassaCore implements MusicCoreService {
     }
 
     public  String createLockReference(String fullyQualifiedKey, boolean isWriteLock) {
-        String[] splitString = fullyQualifiedKey.split("\\.");
-        String keyspace = splitString[0];
-        String table = splitString[1];
-        String lockName = splitString[2];
-
-        logger.info(EELFLoggerDelegate.applicationLogger,"Creating lock reference for lock name:" + lockName);
-        long start = System.currentTimeMillis();
-        String lockReference = null;
+        TimeMeasureInstance.instance().enter("createLockReference");
         try {
-                       lockReference = "" + getLockingServiceHandle().genLockRefandEnQueue(keyspace, table, lockName, isWriteLock);
-               } catch (MusicLockingException | MusicServiceException | MusicQueryException e) {
-                       e.printStackTrace();
-               }
-        long end = System.currentTimeMillis();
-        logger.info(EELFLoggerDelegate.applicationLogger,"Time taken to create lock reference:" + (end - start) + " ms");
-        return lockReference;
+            String[] splitString = fullyQualifiedKey.split("\\.");
+            String keyspace = splitString[0];
+            String table = splitString[1];
+            String lockName = splitString[2];
+
+            logger.info(EELFLoggerDelegate.applicationLogger, "Creating lock reference for lock name:" + lockName);
+            long start = System.currentTimeMillis();
+            String lockReference = null;
+            try {
+                lockReference = "" + getLockingServiceHandle().genLockRefandEnQueue(keyspace, table, lockName, isWriteLock);
+            } catch (MusicLockingException | MusicServiceException | MusicQueryException e) {
+                e.printStackTrace();
+            }
+            long end = System.currentTimeMillis();
+            logger.info(EELFLoggerDelegate.applicationLogger, "Time taken to create lock reference:" + (end - start) + " ms");
+            return lockReference;
+        }
+        finally {
+                TimeMeasureInstance.instance().exit();
+        }
     }
 
 
@@ -146,16 +153,17 @@ public class MusicCassaCore implements MusicCoreService {
     }
     
     private static ReturnType isTopOfLockStore(String keyspace, String table,
-            String primaryKeyValue, String lockReference)
-            throws MusicLockingException, MusicQueryException, MusicServiceException {
-
-        // return failure to lock holders too early or already evicted from the lock store
-        String topOfLockStoreS =
-                getLockingServiceHandle().peekLockQueue(keyspace, table, primaryKeyValue).lockRef;
-        long topOfLockStoreL = Long.parseLong(topOfLockStoreS);
-        long lockReferenceL = Long.parseLong(lockReference);
+                       String primaryKeyValue, String lockReference)
+                       throws MusicLockingException, MusicQueryException, MusicServiceException {
+        TimeMeasureInstance.instance().enter("isTopOfLockStore");
+        try {
+            // return failure to lock holders too early or already evicted from the lock store
+            String topOfLockStoreS =
+                                       getLockingServiceHandle().peekLockQueue(keyspace, table, primaryKeyValue).lockRef;
+            long topOfLockStoreL = Long.parseLong(topOfLockStoreS);
+            long lockReferenceL = Long.parseLong(lockReference);
 
-        if (lockReferenceL > topOfLockStoreL) {
+            if (lockReferenceL > topOfLockStoreL) {
             // only need to check if this is a read lock....
             if (getLockingServiceHandle().isTopOfLockQueue(keyspace, table, primaryKeyValue,
                     lockReference)) {
@@ -165,55 +173,65 @@ public class MusicCassaCore implements MusicCoreService {
                     lockReference + " is not the lock holder yet");
             return new ReturnType(ResultType.FAILURE,
                     lockReference + " is not the lock holder yet");
-        }
+            }
 
 
-        if (lockReferenceL < topOfLockStoreL) {
+            if (lockReferenceL < topOfLockStoreL) {
             logger.info(EELFLoggerDelegate.applicationLogger,
                     lockReference + " is no longer/or was never in the lock store queue");
             return new ReturnType(ResultType.FAILURE,
                     lockReference + " is no longer/or was never in the lock store queue");
-        }
+            }
 
-        return new ReturnType(ResultType.SUCCESS, lockReference + " is top of lock store");
+            return new ReturnType(ResultType.SUCCESS, lockReference + " is top of lock store");
+        }
+        finally {
+            TimeMeasureInstance.instance().exit();
+        }
     }
-    
+
     public  ReturnType acquireLock(String fullyQualifiedKey, String lockReference) throws MusicLockingException, MusicQueryException, MusicServiceException {
-        String[] splitString = fullyQualifiedKey.split("\\.");
-        String keyspace = splitString[0];
-        String table = splitString[1];
-        String primaryKeyValue = splitString[2];
+        TimeMeasureInstance.instance().enter("acquireLock");
+        try {
+            String[] splitString = fullyQualifiedKey.split("\\.");
+            String keyspace = splitString[0];
+            String table = splitString[1];
+            String primaryKeyValue = splitString[2];
 
-        ReturnType result = isTopOfLockStore(keyspace, table, primaryKeyValue, lockReference);
-        
-        if(result.getResult().equals(ResultType.FAILURE))
-                       return result;//not top of the lock store q
-               
-        //check to see if the value of the key has to be synced in case there was a forceful release
-        String syncTable = keyspace+".unsyncedKeys_"+table;
-               String query = "select * from "+syncTable+" where key='"+fullyQualifiedKey+"';";
-        PreparedQueryObject readQueryObject = new PreparedQueryObject();
-        readQueryObject.appendQueryString(query);
-               ResultSet results = MusicDataStoreHandle.getDSHandle().executeQuorumConsistencyGet(readQueryObject);                    
-               if (results.all().size() != 0) {
-                       logger.info("In acquire lock: Since there was a forcible release, need to sync quorum!");
-                       try {
-                               syncQuorum(keyspace, table, primaryKeyValue);
-                       } catch (Exception e) {
-                               StringWriter sw = new StringWriter();
-                       logger.error(EELFLoggerDelegate.errorLogger,e.getMessage(), "[ERR506E] Failed to aquire lock ",ErrorSeverity.CRITICAL, ErrorTypes.LOCKINGERROR);
-                   String exceptionAsString = sw.toString();
-                   return new ReturnType(ResultType.FAILURE, "Exception thrown while syncing key:\n" + exceptionAsString);                     
-               }
-                       String cleanQuery = "delete  from music_internal.unsynced_keys where key='"+fullyQualifiedKey+"';";
-               PreparedQueryObject deleteQueryObject = new PreparedQueryObject();
-               deleteQueryObject.appendQueryString(cleanQuery);
-               MusicDataStoreHandle.getDSHandle().executePut(deleteQueryObject, "critical");
-               }
-               
-               getLockingServiceHandle().updateLockAcquireTime(keyspace, table, primaryKeyValue, lockReference);
-               
-               return new ReturnType(ResultType.SUCCESS, lockReference+" is the lock holder for the key");
+            ReturnType result = isTopOfLockStore(keyspace, table, primaryKeyValue, lockReference);
+
+            if (result.getResult().equals(ResultType.FAILURE))
+                return result;//not top of the lock store q
+
+            //check to see if the value of the key has to be synced in case there was a forceful release
+            String syncTable = keyspace + ".unsyncedKeys_" + table;
+            String query = "select * from " + syncTable + " where key='" + fullyQualifiedKey + "';";
+            PreparedQueryObject readQueryObject = new PreparedQueryObject();
+            readQueryObject.appendQueryString(query);
+            ResultSet results = MusicDataStoreHandle.getDSHandle().executeQuorumConsistencyGet(readQueryObject);
+            if (results.all().size() != 0) {
+                logger.info("In acquire lock: Since there was a forcible release, need to sync quorum!");
+                try {
+                    syncQuorum(keyspace, table, primaryKeyValue);
+                } catch (Exception e) {
+                    StringWriter sw = new StringWriter();
+                    logger.error(EELFLoggerDelegate.errorLogger, e.getMessage(), "[ERR506E] Failed to aquire lock ", ErrorSeverity.CRITICAL, ErrorTypes.LOCKINGERROR);
+                    String exceptionAsString = sw.toString();
+                    return new ReturnType(ResultType.FAILURE, "Exception thrown while syncing key:\n" + exceptionAsString);
+                }
+                String cleanQuery = "delete  from music_internal.unsynced_keys where key='" + fullyQualifiedKey + "';";
+                PreparedQueryObject deleteQueryObject = new PreparedQueryObject();
+                deleteQueryObject.appendQueryString(cleanQuery);
+                MusicDataStoreHandle.getDSHandle().executePut(deleteQueryObject, "critical");
+            }
+
+            getLockingServiceHandle().updateLockAcquireTime(keyspace, table, primaryKeyValue, lockReference);
+
+            return new ReturnType(ResultType.SUCCESS, lockReference + " is the lock holder for the key");
+        }
+        finally {
+            TimeMeasureInstance.instance().exit();
+        }
     }
 
 
@@ -359,23 +377,35 @@ public class MusicCassaCore implements MusicCoreService {
     }
 
     public  MusicLockState destroyLockRef(String fullyQualifiedKey, String lockReference) {
-        long start = System.currentTimeMillis();
-        String[] splitString = fullyQualifiedKey.split("\\.");
-        String keyspace = splitString[0];
-        String table = splitString[1];
-        String primaryKeyValue = splitString[2];
+        TimeMeasureInstance.instance().enter("destroyLockRef");
         try {
-            getLockingServiceHandle().deQueueLockRef(keyspace, table, primaryKeyValue, lockReference);
-        } catch (MusicLockingException | MusicServiceException | MusicQueryException e) {
-               logger.error(EELFLoggerDelegate.errorLogger,e.getMessage(), AppMessages.DESTROYLOCK+lockReference  ,ErrorSeverity.CRITICAL, ErrorTypes.LOCKINGERROR);
-        } 
-        long end = System.currentTimeMillis();
-        logger.info(EELFLoggerDelegate.applicationLogger,"Time taken to destroy lock reference:" + (end - start) + " ms");
-        return getMusicLockState(fullyQualifiedKey);
+            long start = System.currentTimeMillis();
+            String[] splitString = fullyQualifiedKey.split("\\.");
+            String keyspace = splitString[0];
+            String table = splitString[1];
+            String primaryKeyValue = splitString[2];
+            try {
+                getLockingServiceHandle().deQueueLockRef(keyspace, table, primaryKeyValue, lockReference);
+            } catch (MusicLockingException | MusicServiceException | MusicQueryException e) {
+                logger.error(EELFLoggerDelegate.errorLogger, e.getMessage(), AppMessages.DESTROYLOCK + lockReference, ErrorSeverity.CRITICAL, ErrorTypes.LOCKINGERROR);
+            }
+            long end = System.currentTimeMillis();
+            logger.info(EELFLoggerDelegate.applicationLogger, "Time taken to destroy lock reference:" + (end - start) + " ms");
+            return getMusicLockState(fullyQualifiedKey);
+        }
+        finally {
+            TimeMeasureInstance.instance().exit();
+        }
     }
 
     public   MusicLockState  voluntaryReleaseLock(String fullyQualifiedKey, String lockReference) throws MusicLockingException{
-               return destroyLockRef(fullyQualifiedKey, lockReference);
+        TimeMeasureInstance.instance().enter("voluntaryReleaseLock");
+        try {
+            return destroyLockRef(fullyQualifiedKey, lockReference);
+        }
+        finally {
+            TimeMeasureInstance.instance().exit();
+        }
        }
 
     public  MusicLockState  forciblyReleaseLock(String fullyQualifiedKey, String lockReference) throws MusicLockingException, MusicServiceException, MusicQueryException{
@@ -384,14 +414,14 @@ public class MusicCassaCore implements MusicCoreService {
         String table = splitString[1];
 
                //leave a signal that this key could potentially be unsynchronized
-        String syncTable = keyspace+".unsyncedKeys_"+table;    
+        String syncTable = keyspace+".unsyncedKeys_"+table;
         PreparedQueryObject queryObject = new PreparedQueryObject();
                String values = "(?)";
                queryObject.addValue(fullyQualifiedKey);
                String insQuery = "insert into "+syncTable+" (key) values "+values+";";
         queryObject.appendQueryString(insQuery);
-        MusicDataStoreHandle.getDSHandle().executePut(queryObject, "critical");        
-        
+        MusicDataStoreHandle.getDSHandle().executePut(queryObject, "critical");
+
         //now release the lock
                return destroyLockRef(fullyQualifiedKey, lockReference);
        }
@@ -440,41 +470,47 @@ public class MusicCassaCore implements MusicCoreService {
      */
     public  ReturnType criticalPut(String keyspace, String table, String primaryKeyValue,
                     PreparedQueryObject queryObject, String lockReference, Condition conditionInfo) {
-        long start = System.currentTimeMillis();
+        TimeMeasureInstance.instance().enter("executePut");
         try {
-        ReturnType result = isTopOfLockStore(keyspace, table, primaryKeyValue, lockReference);
-        if(result.getResult().equals(ResultType.FAILURE))
-                       return result;//not top of the lock store q
-
-        if (conditionInfo != null)
+            long start = System.currentTimeMillis();
             try {
-              if (conditionInfo.testCondition() == false)
-                  return new ReturnType(ResultType.FAILURE,
-                                  "Lock acquired but the condition is not true");
-            } catch (Exception e) {
-              return new ReturnType(ResultType.FAILURE,
-                      "Exception thrown while checking the condition, check its sanctity:\n"
-                                      + e.getMessage());
+                ReturnType result = isTopOfLockStore(keyspace, table, primaryKeyValue, lockReference);
+                if (result.getResult().equals(ResultType.FAILURE))
+                    return result;//not top of the lock store q
+
+                if (conditionInfo != null)
+                    try {
+                        if (conditionInfo.testCondition() == false)
+                            return new ReturnType(ResultType.FAILURE,
+                                    "Lock acquired but the condition is not true");
+                    } catch (Exception e) {
+                        return new ReturnType(ResultType.FAILURE,
+                                "Exception thrown while checking the condition, check its sanctity:\n"
+                                        + e.getMessage());
+                    }
+
+                String query = queryObject.getQuery();
+                long timeOfWrite = System.currentTimeMillis();
+                long lockOrdinal = Long.parseLong(lockReference);
+                long ts = MusicUtil.v2sTimeStampInMicroseconds(lockOrdinal, timeOfWrite);
+                // TODO: use Statement instead of modifying query
+                query = query.replaceFirst("SET", "USING TIMESTAMP " + ts + " SET");
+                queryObject.replaceQueryString(query);
+                MusicDataStore dsHandle = MusicDataStoreHandle.getDSHandle();
+                dsHandle.executePut(queryObject, MusicUtil.CRITICAL);
+                long end = System.currentTimeMillis();
+                logger.info(EELFLoggerDelegate.applicationLogger, "Time taken for the critical put:" + (end - start) + " ms");
+            } catch (MusicQueryException | MusicServiceException | MusicLockingException e) {
+                logger.error(EELFLoggerDelegate.errorLogger, e.getMessage());
+                return new ReturnType(ResultType.FAILURE,
+                        "Exception thrown while doing the critical put\n"
+                                + e.getMessage());
             }
-                
-          String query = queryObject.getQuery();
-          long timeOfWrite = System.currentTimeMillis();
-          long lockOrdinal = Long.parseLong(lockReference);
-          long ts = MusicUtil.v2sTimeStampInMicroseconds(lockOrdinal, timeOfWrite);
-          // TODO: use Statement instead of modifying query
-          query = query.replaceFirst("SET", "USING TIMESTAMP "+ ts + " SET");
-         queryObject.replaceQueryString(query);
-          MusicDataStore dsHandle = MusicDataStoreHandle.getDSHandle();
-          dsHandle.executePut(queryObject, MusicUtil.CRITICAL);
-          long end = System.currentTimeMillis();
-          logger.info(EELFLoggerDelegate.applicationLogger,"Time taken for the critical put:" + (end - start) + " ms");
-        }catch (MusicQueryException | MusicServiceException | MusicLockingException  e) {
-            logger.error(EELFLoggerDelegate.errorLogger,e.getMessage());
-            return new ReturnType(ResultType.FAILURE,
-                            "Exception thrown while doing the critical put\n"
-                                            + e.getMessage());
+            return new ReturnType(ResultType.SUCCESS, "Update performed");
+        }
+        finally {
+            TimeMeasureInstance.instance().exit();
         }
-         return new ReturnType(ResultType.SUCCESS, "Update performed");
     }
 
     
@@ -559,31 +595,37 @@ public class MusicCassaCore implements MusicCoreService {
      */
     public  ReturnType atomicPut(String keyspaceName, String tableName, String primaryKey,
                     PreparedQueryObject queryObject, Condition conditionInfo) throws MusicLockingException, MusicQueryException, MusicServiceException {
-        long start = System.currentTimeMillis();
-        String fullyQualifiedKey = keyspaceName + "." + tableName + "." + primaryKey;
-        String lockReference = createLockReference(fullyQualifiedKey);
-        long lockCreationTime = System.currentTimeMillis();
-        ReturnType lockAcqResult = acquireLock(fullyQualifiedKey, lockReference);
-        long lockAcqTime = System.currentTimeMillis();
+        TimeMeasureInstance.instance().enter("atomicPut");
+        try {
+            long start = System.currentTimeMillis();
+            String fullyQualifiedKey = keyspaceName + "." + tableName + "." + primaryKey;
+            String lockReference = createLockReference(fullyQualifiedKey);
+            long lockCreationTime = System.currentTimeMillis();
+            ReturnType lockAcqResult = acquireLock(fullyQualifiedKey, lockReference);
+            long lockAcqTime = System.currentTimeMillis();
+
+            if (!lockAcqResult.getResult().equals(ResultType.SUCCESS)) {
+                logger.info(EELFLoggerDelegate.applicationLogger, "unable to acquire lock, id " + lockReference);
+                voluntaryReleaseLock(fullyQualifiedKey, lockReference);
+                return lockAcqResult;
+            }
 
-        if (!lockAcqResult.getResult().equals(ResultType.SUCCESS)) {
-            logger.info(EELFLoggerDelegate.applicationLogger,"unable to acquire lock, id " + lockReference);
-            voluntaryReleaseLock(fullyQualifiedKey,lockReference);
-            return lockAcqResult;
+            logger.info(EELFLoggerDelegate.applicationLogger, "acquired lock with id " + lockReference);
+            ReturnType criticalPutResult = criticalPut(keyspaceName, tableName, primaryKey,
+                    queryObject, lockReference, conditionInfo);
+            long criticalPutTime = System.currentTimeMillis();
+            voluntaryReleaseLock(fullyQualifiedKey, lockReference);
+            long lockDeleteTime = System.currentTimeMillis();
+            String timingInfo = "|lock creation time:" + (lockCreationTime - start)
+                    + "|lock accquire time:" + (lockAcqTime - lockCreationTime)
+                    + "|critical put time:" + (criticalPutTime - lockAcqTime)
+                    + "|lock delete time:" + (lockDeleteTime - criticalPutTime) + "|";
+            criticalPutResult.setTimingInfo(timingInfo);
+            return criticalPutResult;
+        }
+        finally {
+            TimeMeasureInstance.instance().exit();
         }
-
-        logger.info(EELFLoggerDelegate.applicationLogger,"acquired lock with id " + lockReference);
-        ReturnType criticalPutResult = criticalPut(keyspaceName, tableName, primaryKey,
-                        queryObject, lockReference, conditionInfo);
-        long criticalPutTime = System.currentTimeMillis();
-        voluntaryReleaseLock(fullyQualifiedKey,lockReference);
-        long lockDeleteTime = System.currentTimeMillis();
-        String timingInfo = "|lock creation time:" + (lockCreationTime - start)
-                        + "|lock accquire time:" + (lockAcqTime - lockCreationTime)
-                        + "|critical put time:" + (criticalPutTime - lockAcqTime)
-                        + "|lock delete time:" + (lockDeleteTime - criticalPutTime) + "|";
-        criticalPutResult.setTimingInfo(timingInfo);
-        return criticalPutResult;
     }
     
 
index 5b6c81d..6773d13 100644 (file)
@@ -268,7 +268,7 @@ public class ComparisonPoints1
            Map<String, ArrayList<Double>> e = tm.percentiles();
            Map<String, Pair<Double, Double>> m = tm.stats();
            DecimalFormat df = new DecimalFormat("000.000000");
-           e.forEach((k,v) -> System.out.println("" + k + "\t\t: " + Arrays.toString(v.stream().map(w -> "" + df.format(w)).toArray())));
+//           e.forEach((k,v) -> System.out.println("" + k + "\t\t: " + Arrays.toString(v.stream().map(w -> "" + df.format(w)).toArray())));
            m.forEach((k,v) -> System.out.println("" + k + "\t\t: " + df.format(v.getLeft()) + " (" + df.format(v.getRight()) + ")"));
 
            System.exit(0);