Add timing to old code and update the TestingResult to add the return code

src/mohawk/helper/SMVSpecHelper.java

@@ -85,18 +85,20 @@ public class SMVSpecHelper {
         }
 
         try {
-            WriteNuSMV nusmv = new WriteNuSMV(nusmvFile.getAbsolutePath(), "smvtemplate");
+            WriteNuSMV nusmv = new WriteNuSMV(nusmvFile.getAbsolutePath(), "smvtemplate", settings.timing,
+                    "convertSpecToSMVFormat(" + specFile.getName() + ")");
             RBACSpecReader reader = new RBACSpecReader(specFile.getAbsolutePath());
             RBACInstance rbac = reader.getRBAC();
 
             if (settings.sliceRBAC) {
                 logger.info("[Slicing] Slicing the Spec File");
 
-                RoleSlicer roleslicer = new RoleSlicer(rbac);
+                RoleSlicer roleslicer = new RoleSlicer(rbac, settings.timing,
+                        "convertSpecToSMVFormat(" + specFile.getName() + ")");
                 rbac = roleslicer.getSlicedPolicy();
 
-                logger.info("[DETAILS] After Slicing -> Number of Roles: " + rbac.getNumRoles() + "; Number of Rules: "
-                        + (rbac.getCA().size() + rbac.getCR().size()));
+                logger.info("[DETAILS] After Slicing -> Number of Roles: " + rbac.getNumRoles() +
+                        "; Number of Rules: " + (rbac.getCA().size() + rbac.getCR().size()));
             }
 
             if (settings.sliceRBACQuery) {
@@ -109,7 +111,8 @@ public class SMVSpecHelper {
             if (settings.skipRefine) {
                 nusmv.fillAttributes(rbac);
             } else {
-                RolesAbsRefine absrefine = new RolesAbsRefine(rbac);
+                RolesAbsRefine absrefine = new RolesAbsRefine(rbac, settings.timing,
+                        "convertSpecToSMVFormat(" + specFile.getName() + ")");
                 RBACInstance rbac_refined = absrefine.refineOnly();
 
                 nusmv.fillAttributes(rbac_refined);

src/mohawk/refine/RolesAbsRefine.java

@@ -12,6 +12,7 @@ import mohawk.collections.RoleDepTree;
 import mohawk.global.nusmv.NuSMV;
 import mohawk.global.pieces.mohawk.*;
 import mohawk.global.results.ExecutionResult;
+import mohawk.global.timing.MohawkTiming;
 import mohawk.math.CalculateDiameter;
 import mohawk.output.WriteNuSMV;
 import mohawk.output.WriteRBACSpec;
@@ -46,10 +47,15 @@ public class RolesAbsRefine {
     private NuSMVMode mode;// mode
 
     public boolean skipSMVFile = false;
-
     private Integer returnValue = null;
 
-    public RolesAbsRefine(RBACInstance inRbac) {
+    // Timing
+    public MohawkTiming timing;
+    public String timingPrefix;
+
+    public RolesAbsRefine(RBACInstance inRbac, MohawkTiming timing, String timingPrefix) {
+        this.timing = timing;
+        this.timingPrefix = timingPrefix;
 
         mode = NuSMVMode.BMC;// Default mode is BMC
         k = 2;
@@ -89,8 +95,9 @@ public class RolesAbsRefine {
         return sAdminRoles;
     }
 
-    public Boolean getResult(RBACInstance curInstance, Integer fileno) throws IOException, InterruptedException {
-        WriteNuSMV nusmv = new WriteNuSMV("logs/smvinstancefile" + fileno + ".txt", "smvtemplate");
+    public Boolean getResult(RBACInstance curInstance, Integer fileno) throws Exception {
+        WriteNuSMV nusmv = new WriteNuSMV("logs/smvinstancefile" + fileno + ".txt", "smvtemplate",
+                timing, timingPrefix);
         nusmv.fillAttributes(curInstance);
 
         if (!skipSMVFile) {
@@ -196,25 +203,25 @@ public class RolesAbsRefine {
     }
 
     public boolean refineRoles() {
-        if (nextsetroles.size() == allroles.size())
-            return false;
+        if (nextsetroles.size() == allroles.size()) { return false; }
 
         // Set<String> incrementRoles = rdeptree.getRoles(refinementstep);
-        Set<String> incrementRoles = new HashSet<String>();// =
-                                                           // rdeptree.getRoles(refinementstep);
+        Set<String> incrementRoles = new HashSet<String>();// = rdeptree.getRoles(refinementstep);
         for (int i = 0; i < k; i++) {
             Set<String> sNextQueue = this.rdeptree.getRoles(lastpriority);
             if (sNextQueue != null) {
                 incrementRoles.addAll(sNextQueue);
                 lastpriority++;
-            } else
+            } else {
                 break;
+            }
         }
 
-        if (incrementRoles.size() == 0)
+        if (incrementRoles.size() == 0) {
             return false;
-        else
+        } else {
             nextsetroles.addAll(incrementRoles);
+        }
 
         refinementstep++;
 

src/mohawk/slicer/RoleSlicer.java

@@ -7,6 +7,7 @@ import java.util.*;
 import java.util.logging.Logger;
 
 import mohawk.global.pieces.mohawk.*;
+import mohawk.global.timing.MohawkTiming;
 import mohawk.rbac.RBACInstance;
 
 /**
@@ -33,13 +34,18 @@ public class RoleSlicer {
     private Vector<String> vPositiveDeps;
     private Vector<String> vNegativeDeps;
 
+    // Timing
+    public MohawkTiming timing;
+    public String timingPrefix;
+
     /*
      * This is a map between role indices of unsliced roles and and sliced roles.
      */
     private Map<Integer, Integer> mapRoleIndex;
 
-    public RoleSlicer(RBACInstance inRbac) {
-
+    public RoleSlicer(RBACInstance inRbac, MohawkTiming timing, String timingPrefix) {
+        this.timing = timing;
+        this.timingPrefix = timingPrefix;
         unsliced = inRbac;
         strRole = unsliced.getSpec().get(1);
         strUser = unsliced.getSpec().get(0);
@@ -48,20 +54,41 @@ public class RoleSlicer {
     }
 
     public RBACInstance getSlicedPolicy() throws Exception {
+        /* TIMING */timing.startTimer(timingPrefix + " (slicingTotal)");
 
-        System.out.println("Slicing roles");
+        System.out.println("[START] getSlicedPolicy()");
+
+        System.out.println("[START] Slicing roles");
+        /* TIMING */timing.startTimer(timingPrefix + " (slicing roles)");
         slicedRoles = createSlicedRoles();
-        System.out.println("Slicing users");
+        /* TIMING */timing.stopTimer(timingPrefix + " (slicing roles)");
+
+        System.out.println("[START] Slicing users");
+        /* TIMING */timing.startTimer(timingPrefix + " (slicing users)");
         slicedUsers = sliceUsers();
-        System.out.println("Slicing admin");
+        /* TIMING */timing.stopTimer(timingPrefix + " (slicing users)");
+
+        System.out.println("[START] Slicing admin");
+        /* TIMING */timing.startTimer(timingPrefix + " (slicing admin)");
         slicedAdmin = unsliced.getAdmin();
-        System.out.println("Slicing UA");
+        /* TIMING */timing.stopTimer(timingPrefix + " (slicing admin)");
+
+        System.out.println("[START] Slicing UA");
+        /* TIMING */timing.startTimer(timingPrefix + " (slicing UA)");
         slicedUA = sliceUA();
-        System.out.println("Slicing CA");
+        /* TIMING */timing.stopTimer(timingPrefix + " (slicing UA)");
+
+        System.out.println("[START] Slicing CA");
+        /* TIMING */timing.startTimer(timingPrefix + " (slicing CA)");
         slicedCA = sliceCA();
-        System.out.println("Slicing CR");
+        /* TIMING */timing.stopTimer(timingPrefix + " (slicing CA)");
+
+        System.out.println("[START] Slicing CR");
+        /* TIMING */timing.startTimer(timingPrefix + " (slicing CR)");
         slicedCR = sliceCR();
+        /* TIMING */timing.stopTimer(timingPrefix + " (slicing CR)");
 
+        /* TIMING */timing.stopTimer(timingPrefix + " (slicingTotal)");
         return new RBACInstance(slicedRoles, slicedUsers, slicedAdmin, slicedUA, slicedCR, slicedCA,
                 unsliced.getSpec());
     }

src/mohawk/testing/TestRunner.java

@@ -45,7 +45,7 @@ public class TestRunner implements Callable<TestingResult> {
             logger.info("[TestRunner] Running the Abstraction-Refinement Step");
             result = absrefine.absrefineloop();
         }
-        return new TestingResult(result, (long) 0, "", "Return Result: " + absrefine.getReturnValue());
+        return new TestingResult(result, (long) 0, "", absrefine.getReturnValue(), "");
     }
 
 }

src/mohawk/testing/TestingSuite.java

@@ -108,7 +108,7 @@ public class TestingSuite {
                         logger.info("[Slicing] Slicing the Spec File");
                         /* TIMING */settings.timing.startTimer(timerName + " (slicing)");
 
-                        RoleSlicer roleslicer = new RoleSlicer(rbac);
+                        RoleSlicer roleslicer = new RoleSlicer(rbac, settings.timing, timerName);
                         rbac = roleslicer.getSlicedPolicy();
 
                         logger.info("[DETAILS] After Slicing -> Number of Roles: " + rbac.getNumRoles()
@@ -133,7 +133,7 @@ public class TestingSuite {
                     logger.severe(e.getMessage());
                 }
 
-                RolesAbsRefine absrefine = new RolesAbsRefine(rbac);
+                RolesAbsRefine absrefine = new RolesAbsRefine(rbac, settings.timing, timerName);
                 absrefine.setMode(modes.get(j));
 
                 // Setup Timeout Timer
@@ -142,20 +142,15 @@ public class TestingSuite {
                     logger.info("[RUNNING] Running Mohawk on testcase " + (i + 1) + "/" + numSpecFiles + " (mode="
                             + modes.get(j) + "):");
 
+                    /* TIMING */settings.timing.startTimer(timerName + " (TestRunner)");
                     if (settings.TIMEOUT_SECONDS == 0) {
                         settings.lastResult = future.get();
                     } else {
                         settings.lastResult = future.get(settings.TIMEOUT_SECONDS, TimeUnit.SECONDS);
                     }
-                    System.out
-                            .println("Result: " + settings.lastResult + " for role '" + absrefine.getSpecRole() + "'");
-                    logger.info("[COMPLETED] Result: " + settings.lastResult + ", for the Spec Role: '"
-                            + absrefine.getSpecRole()
-                            + "' in following spec file (in mode "
-                            + modes.get(j) + "): " + specFile);
+                    /* TIMING */settings.timing.stopTimer(timerName + " (TestRunner)");
 
                     /* TIMING */settings.timing.stopTimer(timerName);
-
                     settings.lastResult._duration = settings.timing.getLastElapsedTime();
                     settings.lastResult._filename = settings.smvHelper.specFiles.get(i).getAbsolutePath();
                     if (settings.lastResult._comment == null || settings.lastResult._comment.isEmpty()) {
@@ -163,6 +158,14 @@ public class TestingSuite {
                     } else {
                         settings.lastResult._comment += "; " + comment;
                     }
+
+                    System.out.println("Result: " + settings.lastResult +
+                            " for role '" + absrefine.getSpecRole() + "'");
+                    logger.info("[COMPLETED] Result: " + settings.lastResult + ", for the Spec Role: '"
+                            + absrefine.getSpecRole()
+                            + "' in following spec file (in mode "
+                            + modes.get(j) + "): " + specFile);
+
                     settings.results.add(settings.lastResult);
                     settings.results.writeOutLast(resultsFW);
                 } catch (TimeoutException e) {
@@ -172,8 +175,9 @@ public class TestingSuite {
                     settings.lastResult = new TestingResult(ExecutionResult.TIMEOUT,
                             settings.timing.getLastElapsedTime(),
                             settings.smvHelper.specFiles.get(i),
-                            comment + "; Retun Value: timeout");
+                            "timeout", comment);
 
+                    settings.results.writeOutLast(resultsFW);
                 } catch (OutOfMemoryError e) {
                     logger.warning("[OUT OF MEMORY] Mohawk has ran out of memory out for SPEC file: " + specFile);
                     /* TIMING */settings.timing.cancelTimer(timerName);
@@ -181,8 +185,9 @@ public class TestingSuite {
                     settings.lastResult = new TestingResult(ExecutionResult.OUT_OF_MEMORY,
                             settings.timing.getLastElapsedTime(),
                             settings.smvHelper.specFiles.get(i),
-                            comment + "; Retun Value: out_of_memory");
+                            "out_of_memory", comment);
 
+                    settings.results.writeOutLast(resultsFW);
                 } catch (InterruptedException e) {
                     if (logger.getLevel() == Level.FINEST) {
                         e.printStackTrace();