Bug fixes from testing.

9 files changed, 142 insertions, 30 deletions

diff --git a/common.py b/common.py
index 7abf0f2..ff0f986 100644
--- a/common.py
+++ b/common.py
@@ -200,13 +200,16 @@ def set_logged_list(logged):
     global __logged
     __logged = logged
 
-def log_once(id, msg = None, indent = True):
+def log_once(id, msg = None):
     global __logged
 
-    msg = msg if msg else id
+    # Indent if a multithreaded list was specified
+    indent = type(__logged) != type([])
+
+    msg = msg.strip('\n') if msg else id
 
     if id not in  __logged:
         __logged += [id]
         if indent:
             msg = '   ' + msg.strip('\t').replace('\n', '\n\t')
-        sys.stderr.write('\n' + msg.strip('\n') + '\n')
+        sys.stderr.write('\n' + msg + '\n')
diff --git a/config/config.py b/config/config.py
index 5e6f9e3..28e78c9 100644
--- a/config/config.py
+++ b/config/config.py
@@ -50,7 +50,15 @@ DEFAULTS = {'params_file' : 'params.py',
 SCHED_EVENTS = range(501, 513)
 
 '''Overhead events.'''
-OVH_BASE_EVENTS  = ['SCHED', 'RELEASE', 'SCHED2', 'TICK', 'CXS', 'LOCK', 'UNLOCK']
+OVH_BASE_EVENTS  = ['SCHED', 'RELEASE', 'SCHED2', 'TICK', 'CXS',
+                    'SEND_RESCHED', 'LOCK', 'UNLOCK']
+
+'''Mixed-criticality overheads.'''
+MC_EVENTS  = ['LVL{}_SCHED', 'LVL{}_RELEASE']
+MC_LEVELS  = ['A', 'B', 'C']
+OVH_BASE_EVENTS += [s.format(l) for (l,s) in
+                itertools.product(MC_LEVELS, MC_EVENTS)]
+
 OVH_ALL_EVENTS   = ["%s_%s" % (e, t) for (e,t) in
                     itertools.product(OVH_BASE_EVENTS, ["START","END"])]
 OVH_ALL_EVENTS  += ['RELEASE_LATENCY']
@@ -60,3 +68,6 @@ OVH_BASE_EVENTS += ['RELEASE_LATENCY']
 # If a task is missing more than this many records, its measurements
 # are not included in sched_trace summaries
 MAX_RECORD_LOSS = .2
+
+# Number of pages needed for each color before experiments are run
+PAGES_PER_COLOR = 1024
diff --git a/gen/color.py b/gen/color.py
index 8184b8b..46ec8dc 100644
--- a/gen/color.py
+++ b/gen/color.py
@@ -29,19 +29,22 @@ class BlockColorScheme(ColorScheme):
         if self.way_first:
             # Way first means maximize ways
             pages_per_color = min(self.ways, pages_needed)
-            colors_per_task = int(ceil(pages_needed/pages_per_color))
+            colors_per_task = int(ceil(float(pages_needed)/pages_per_color))
         else:
             # Color first means maximize colors
             colors_per_task = min(self.colors, pages_needed)
-            pages_per_color = int(ceil(pages_needed/colors_per_task))
+            pages_per_color = int(ceil(float(pages_needed)/colors_per_task))
 
         curr_color = 0
         for cpu, tasks in cpus.iteritems():
             # All tasks on a CPU have the same coloring scheme
             cpu_colors = defaultdict(int)
             for _ in xrange(colors_per_task):
-                curr_color = (curr_color + 1) % self.colors
                 cpu_colors[curr_color] = pages_per_color
+                curr_color = (curr_color + 1) % self.colors
+
+            if sum(cpu_colors.values()) < pages_needed:
+                raise Exception("Failed to block color cpu, %s" % cpu_colors)
 
             for t in tasks:
                 t.colors = cpu_colors
@@ -80,7 +83,6 @@ class EvilColorScheme(ColorScheme):
         for t in tasks:
             t.colors = colors
 
-
 INFO_FIELDS = ['cache', 'line', 'page', 'ways', 'sets', 'colors']
 INFO_PROC   = '/proc/sys/litmus/color/cache_info'
 
diff --git a/gen/mc_generators.py b/gen/mc_generators.py
index 8f5bd84..d8c172d 100644
--- a/gen/mc_generators.py
+++ b/gen/mc_generators.py
@@ -243,8 +243,9 @@ TP_TYPE = """#if $type != 'unmanaged'
 /proc/sys/litmus/color/preempt_cache{0}
 #end if"""
 
-# Always add some pages
-TP_ADD = """/proc/sys/litmus/color/add_pages{1}"""
+# Now done by experiment.py
+# # Always add some pages
+# TP_ADD = """/proc/sys/litmus/color/add_pages{1}"""
 
 # Use special spin for color tasks
 TP_COLOR_BASE = """colorspin -y $t.id -x $t.colorcsv -q $t.wss -l $t.loops """
@@ -253,8 +254,8 @@ TP_COLOR_B = TP_BASE.format("b", TP_COLOR_BASE + "-p $t.cpu ")
 TP_COLOR_C = TP_BASE.format("c", TP_COLOR_BASE)
 
 # Not even sure job splitting is still possible
-TP_CHUNK = """#if $chunk_size > 0
-/proc/sys/litmus/color/chunk_size{$chunk_size}
+TP_CHUNK = """#if $chunk_size_ns > 0
+/proc/sys/litmus/color/chunk_size{$chunk_size_ns}
 #end if"""
 
 COLOR_TYPES = ['scheduling', 'locking', 'unmanaged']
@@ -264,7 +265,7 @@ class ColorMcGenerator(McGenerator):
 
     def __init__(self, params = {}):
         super(ColorMcGenerator, self).__init__("MC",
-            templates=[TP_ADD, TP_TYPE, TP_CHUNK, TP_COLOR_B, TP_COLOR_C],
+            templates=[TP_TYPE, TP_CHUNK, TP_COLOR_B, TP_COLOR_C],
             options=self.__make_options(),
             params=self.__extend_params(params))
 
@@ -336,7 +337,7 @@ class ColorMcGenerator(McGenerator):
                           'System colors (cache size / ways).'),
                 GenOption('page_size', int, self.cache.page,
                           'System page size.'),
-                GenOption('wss', [float, int], .5,
+                GenOption('wss', [float, int], .25,
                           'Task working set sizes. Can be expressed as a fraction ' +
                           'of the cache.')]
 
@@ -359,7 +360,8 @@ class ColorMcGenerator(McGenerator):
             if pages > cache_pages:
                 raise Exception('WSS (%d) larger than the cache!' % (wss))
 
-        return pages
+        # Divide in half for HRT, SRT divide
+        return pages / 2
 
 
     def __make_csv(self, task):
@@ -410,11 +412,23 @@ class ColorMcGenerator(McGenerator):
             hrt_colorer = EvilColorScheme(c, w)
             srt_colorer = hrt_colorer
         else:
+            # Divide cache between hrt and srt
+            c /= 2
             srt_colorer = RandomColorScheme(c, w)
             hrt_colorer = BlockColorScheme(c, w, way_first=True)
 
         hrt_colorer.color(task_system['lvlb'], pages_needed)
         srt_colorer.color(task_system['lvlc'], pages_needed)
 
+        # This check has saved me a lot of trouble already, leave it in
+        for t in task_system['lvlb'] + task_system['lvlc']:
+            if sum(t.colors.values()) * params['page_size'] < real_wss:
+                raise Exception("Didn't color enough pages for %s" % params)
+
+        if params['type'] != 'unmanaged':
+            # Bump srt into the second half of the cache
+            for t in task_system['lvlc']:
+                t.colors = {colors+c:w for colors, w in t.colors.iteritems()}
+
         for t in all_tasks:
             self.__make_csv(t)
diff --git a/gen_exps.py b/gen_exps.py
index b847661..65f50d8 100755
--- a/gen_exps.py
+++ b/gen_exps.py
@@ -59,7 +59,7 @@ def main():
     if opts.list_gens or opts.described:
         return 0
 
-    params = filter(lambda x : re.match("\w+=\w+", x), args)
+    params = filter(lambda x : re.match("\w+=[\.\w]+", x), args)
 
     # Ensure some generator is loaded
     args = list(set(args) - set(params))
diff --git a/parse/sched.py b/parse/sched.py
index 1033989..5a36da9 100644
--- a/parse/sched.py
+++ b/parse/sched.py
@@ -26,9 +26,11 @@ ScaleData = namedtuple('ScaleData', ['reg_tasks', 'base_tasks'])
 
 class TimeTracker:
     '''Store stats for durations of time demarcated by sched_trace records.'''
-    def __init__(self):
+    def __init__(self, join_job = False):
         self.begin = self.avg = self.max = self.num = self.next_job = 0
 
+        self.join_job = join_job
+
         # Count of times the job in start_time matched that in store_time
         self.matches = 0
         # And the times it didn't
@@ -39,9 +41,12 @@ class TimeTracker:
         # any task is always skipped
         self.last_record = None
 
+        self.stored_dur = 0
+
     def store_time(self, next_record):
         '''End duration of time.'''
-        dur = (self.last_record.when - self.begin) if self.last_record else -1
+        dur  = (self.last_record.when - self.begin) if self.last_record else -1
+        dur += self.stored_dur
 
         if self.next_job == next_record.job:
             self.last_record = next_record
@@ -49,13 +54,16 @@ class TimeTracker:
             if self.last_record:
                 self.matches += 1
 
-            if dur > 0:
+            if self.join_job and self.next_job == self.last_record.job:
+                self.stored_dur += dur
+            elif dur > 0:
                 self.max  = max(self.max, dur)
                 self.avg *= float(self.num / (self.num + 1))
                 self.num += 1
                 self.avg += dur / float(self.num)
 
                 self.begin = 0
+                self.stored_dur = 0
                 self.next_job   = 0
         else:
             self.disjoints += 1
@@ -70,7 +78,6 @@ class TimeTracker:
 
         self.next_job = record.job
 
-
 class LeveledArray(object):
     """Groups statistics by the level of the task to which they apply"""
     def __init__(self):
diff --git a/run/experiment.py b/run/experiment.py
index b0e46b6..4667cb1 100644
--- a/run/experiment.py
+++ b/run/experiment.py
@@ -1,8 +1,13 @@
+import config.config as conf
 import os
-import time
+import re
 import run.litmus_util as lu
 import shutil as sh
+import sys
+import time
+
 from operator import methodcaller
+from run.proc_entry import ProcEntry
 
 class ExperimentException(Exception):
     '''Used to indicate when there are problems with an experiment.'''
@@ -17,6 +22,10 @@ class ExperimentDone(ExperimentException):
 class SystemCorrupted(Exception):
     pass
 
+PROC_ADD_PAGES = '/proc/sys/litmus/color/add_pages'
+PROC_NR_PAGES  = '/proc/sys/litmus/color/nr_pages'
+REG_NR_PAGES   = re.compile(r'\s*\d+\s*:\s*(\d+)', re.M)
+
 class Experiment(object):
     '''Execute one task-set and save the results. Experiments have unique IDs.'''
     INTERRUPTED_DIR = ".interrupted"
@@ -100,7 +109,7 @@ class Experiment(object):
         for e in self.executables:
             status = e.poll()
             if status != None and status:
-                err_msg = "Task %s failed with status: %s" % (e.wait(), status)
+                err_msg = "Task %s failed with status: %s" % (e, status)
                 msgs += [err_msg]
 
         if msgs:
@@ -108,7 +117,7 @@ class Experiment(object):
             # up the terminal
             if len(msgs) > 3:
                 num_errs = len(msgs) - 3
-                msgs = msgs[0:4] + ["...%d more task errors..." % num_errs]
+                msgs = msgs[0:3] + ["...%d more task errors..." % num_errs]
 
             out_name = self.__strip_path(self.exec_out.name)
             err_name = self.__strip_path(self.exec_err.name)
@@ -138,7 +147,7 @@ class Experiment(object):
             now_ready = lu.waiting_tasks()
             if now_ready != num_ready:
                 wait_start = time.time()
-                num_ready  = lu.now_ready
+                num_ready  = now_ready
 
     def __run_tasks(self):
         self.log("Starting %d tasks" % len(self.executables))
@@ -197,11 +206,67 @@ class Experiment(object):
         if msgs:
             raise SystemCorrupted("\n".join(msgs))
 
+    def __get_nr_pages(self):
+        with open(PROC_NR_PAGES, 'r') as f:
+            data = f.read()
+
+        pages = map(int, REG_NR_PAGES.findall(data))
+        return pages
+
+    def __create_colored_pages(self):
+        if self.scheduler != 'COLOR' and self.scheduler != 'MC':
+            return
+
+        self.log("Creating colored pages...")
+
+        # On system startup, it takes some time for these entries to appear
+        start = time.time()
+        while not os.path.exists(PROC_ADD_PAGES) or\
+              not os.path.exists(PROC_NR_PAGES):
+
+            if time.time() - start > 30.0:
+                raise Exception("Cannot find %s or %s!" %
+                                (PROC_ADD_PAGES, PROC_NR_PAGES))
+            time.sleep(1)
+
+        start_pages = self.__get_nr_pages()
+        num_started = sum(start_pages)
+        num_created = 0
+        num_needed  = len(start_pages) * conf.PAGES_PER_COLOR
+
+        ProcEntry(PROC_ADD_PAGES, 1).write_proc()
+
+        # Spin until pages are done adding
+        start = time.time()
+        while True:
+            if time.time() - start > 30.0:
+                raise Exception("Too much time spent creating pages!")
+
+            pages = sum(self.__get_nr_pages())
+
+            if pages == num_needed:
+                break
+            else:
+                if pages > num_created:
+                    num_created = pages
+                    start = time.time()
+                sys.stderr.write('\rPages needed: {0: 4}'.format(num_needed - pages))
+
+            # Unknown why this has to be done again....
+            ProcEntry(PROC_ADD_PAGES, 1).write_proc()
+            time.sleep(1)
+
+        if num_created:
+            sys.stderr.write('\n')
+        self.log("Created %d colored pages." % (num_needed - num_started))
+
     def __setup(self):
         self.__make_dirs()
         self.__assign_executable_cwds()
         self.__setup_tracers()
 
+        self.__create_colored_pages()
+
         self.log("Writing %d proc entries" % len(self.proc_entries))
         map(methodcaller('write_proc'), self.proc_entries)
 
@@ -229,6 +294,8 @@ class Experiment(object):
         self.log("Stopping regular tracers")
         map(methodcaller('stop_tracing'), self.regular_tracers)
 
+        os.system('sync')
+
     def log(self, msg):
         print("[Exp %s]: %s" % (self.name, msg))
 
@@ -253,8 +320,11 @@ class Experiment(object):
                 self.__teardown()
         finally:
             self.log("Switching back to Linux scheduler")
-            self.__to_linux()
-
+            try:
+                self.__to_linux()
+            except Exception as e:
+                print(e)
+                
         if succ:
             self.__save_results()
             self.log("Experiment done!")
diff --git a/run/proc_entry.py b/run/proc_entry.py
index 56f7c24..e222c3d 100644
--- a/run/proc_entry.py
+++ b/run/proc_entry.py
@@ -1,9 +1,10 @@
 import os
+import traceback
 
 class ProcEntry(object):
     def __init__(self, proc, data):
         self.proc = proc
-        self.data = data
+        self.data = str(data)
 
         if not os.path.exists(self.proc):
             raise ValueError("Invalid proc entry %s" % self.proc)
@@ -13,4 +14,10 @@ class ProcEntry(object):
             with open(self.proc, 'w') as entry:
                 entry.write(self.data)
         except:
-            print("Failed to write into %s value:\n%s" % (self.proc, self.data))
+            traceback.print_exc()
+
+            val = str(self.data)
+            val = val if '\n' not in val else '\n'+val
+
+            raise IOError("Failed to write into %s value: %s" %
+                          (self.proc, val))
diff --git a/run_exps.py b/run_exps.py
index a15018d..afabca8 100755
--- a/run_exps.py
+++ b/run_exps.py
@@ -356,10 +356,8 @@ def make_paths(exp, out_base_dir, opts):
 
     return sched_file, out_dir
 
-
 def main():
     opts, args = parse_args()
-
     exps = get_exps(opts, args)
 
     jabber = setup_jabber(opts.jabber) if opts.jabber else None