Issue 310: improving boot times (#311)

* Repaired the FSM

Removed the navel gazing state because it was taking so long and tried to make it asynchronous. This causes problems elsewhere when states are changed by the user with a reset. So, back into the state machine.

* Reduce processing time

While processing time for navel gazing is fixed by the number of metric data values (50 ms per state vector or 14 values), it was possible to clean up the navel gazing to properly load the diary it has been keeping.

* Reduce loaded metrics

The next tall tent pole in the processing is retrieving millions of metrics when only a few hundred are new. By find the latest run ID in the diary, can have the DB retrieve just the newer run IDs and run ID 0 since they are overwritten.

Author: al-niessner

.github/workflows/pylint.rc

@@ -582,6 +582,7 @@ contextmanager-decorators=contextlib.contextmanager
 generated-members=dawgie.context.fsm,
                   logging.handlers.StreamHandler,
                   self.archiving_trigger,
+                  self.contemplation_trigger,
                   self.running_trigger,
                   self.state,
                   self.update_trigger,

Python/dawgie/db/__init__.py

@@ -148,8 +148,8 @@ def gather(anz, ans) -> dawgie.Aspect:
     return _db_in_use().gather(anz, ans)
 
 
-def metrics() -> [MetricData]:
-    return _db_in_use().metrics()
+def metrics(after_runid: int = -1) -> [MetricData]:
+    return _db_in_use().metrics(after_runid)
 
 
 def next():

Python/dawgie/db/post.py

@@ -1499,7 +1499,7 @@ def gather(anz, ans):
     return Interface(anz, ans, '__all__')
 
 
-def metrics() -> '[dawgie.db.MetricData]':
+def metrics(after_runid: int = -1) -> '[dawgie.db.MetricData]':
     if not dawgie.db.post._db:
         raise RuntimeError('called metrics before open')
 
@@ -1508,7 +1508,15 @@ def metrics() -> '[dawgie.db.MetricData]':
     cur = dawgie.db.post._cur(conn)
     cur.execute('SELECT PK from StateVector WHERE name = %s;', ('__metric__',))
     sv_IDs = [t[0] for t in cur.fetchall()]
-    cur.execute('SELECT * from Prime WHERE sv_ID = ANY(%s);', (sv_IDs,))
+    if after_runid is None or after_runid < 0:
+        cur.execute('SELECT * from Prime WHERE sv_ID = ANY(%s);', (sv_IDs,))
+    else:
+        cur.execute(
+            'SELECT * from Prime WHERE sv_ID = ANY(%s) '
+            'AND (run_ID > %s OR run_ID = %s);',
+            (sv_IDs, after_runid, 0),
+        )
+
     rows = cur.fetchall()
     md = dawgie.util.metrics.filled(-2)
     svs = {

Python/dawgie/db/shelve/__init__.py

@@ -211,7 +211,8 @@ def gather(anz, ans) -> dawgie.Aspect:
     return Interface(anz, ans, '__all__')
 
 
-def metrics() -> [dawgie.db.MetricData]:
+def metrics(after_runid: int = -1) -> [dawgie.db.MetricData]:
+    # pylint: disable=too-many-locals
     if not DBI().is_open:
         raise RuntimeError('called metrics before open')
     if DBI().is_reopened:
@@ -260,14 +261,17 @@ def metrics() -> [dawgie.db.MetricData]:
         mn = '.'.join([str(runid), target, task, alg[0], sv[0], val[0]])
         log.debug('metrics() - working on %s', mn)
 
-        if not result or any(
-            [
-                result[-1].run_id != runid,
-                result[-1].target != target,
-                result[-1].task != task,
-                result[-1].alg_name != alg[0],
-                result[-1].alg_ver != alg[1].version,
-            ]
+        if runid > after_runid and (
+            not result
+            or any(
+                [
+                    result[-1].run_id != runid,
+                    result[-1].target != target,
+                    result[-1].task != task,
+                    result[-1].alg_name != alg[0],
+                    result[-1].alg_ver != alg[1].version,
+                ]
+            )
         ):
             log.debug('metrics() - make new reuslt')
             msv = dawgie.util.MetricStateVector(

Python/dawgie/pl/resources.py

@@ -66,7 +66,7 @@ def _read_diary():
             ):
                 for timelines in past.values():
                     if not all(
-                        isinstance(k, dict) and isinstance(v, (list, set))
+                        isinstance(k, str) and isinstance(v, (list, set))
                         for k, v in timelines.items()
                     ):
                         past = {}
@@ -128,6 +128,14 @@ def distribution(metric: [dawgie.db.MetricData]) -> {str: HINT}:
     return dst
 
 
+def last_runid() -> int:
+    reg = _read_diary()
+    runids = {-1}
+    for val in reg.values():
+        runids.update(val['rids'])
+    return max(runids)
+
+
 def regress(metric: [dawgie.db.MetricData]) -> {str: [dawgie.db.MetricData]}:
     log.debug('regress() - regress back across metric data %d', len(metric))
     keys = [

Python/dawgie/pl/state.dot

@@ -38,25 +38,30 @@ POSSIBILITY OF SUCH DAMAGE.
 NTR:
 */
         node [shape = circle];
-        starting[id=starting]
+        starting[id=starting, label=start]
         loading[id=loading]
+        contemplation[id=contemplation, label="navel\ngazing"]
         updating[id=updating]
         running[id=running]
         gitting[id=gitting]
         archiving[id=archiving];
-        { rank=same loading updating }
+        { rank=same contemplation loading updating }
         rankdir=TB;
-        starting -> loading [label=start,
+        starting -> loading [label=boot,
                              trigger=starting_trigger,
                              source=starting,
                              dest=loading,
                              before=start,
                              after=load];
-        loading -> running[label=run,
-                           trigger=running_trigger,
-                           source=loading,
-                           dest=running,
-                           before=navel_gaze];
+        loading -> contemplation[label=introspect,
+                                 trigger=contemplation_trigger,
+                                 source=loading,
+                                 dest=contemplation,
+                                 after=navel_gaze];
+        contemplation -> running[label=run,
+                                 trigger=running_trigger,
+                                 source=contemplation,
+                                 dest=running];
         running -> gitting[label=submit,
                            trigger=gitting_trigger,
                            source=running,
@@ -74,14 +79,13 @@ NTR:
         archiving -> running[label=run,
                              trigger=running_trigger,
                              source=archiving,
-                             dest=running,
-                             before=navel_gaze];
+                             dest=running];
         running -> updating[label=update,
                             trigger=update_trigger,
                             source=running,
                             dest=updating,
                             after=reload];
-        updating -> loading[label=load,
+        updating -> loading[label=refresh,
                             trigger=loading_trigger,
                             source=updating,
                             dest=loading,

Python/dawgie/pl/state.py

@@ -142,6 +142,7 @@ class FSM:
     args = None
     states = [
         'archiving',
+        'contemplation',
         'gitting',
         'loading',
         'running',
@@ -281,11 +282,13 @@ def _logging(self):
 
     def _navel_gaze(self, *_args, **_kwds):
         log.info('entering state navel gaze')
-        dawgie.pl.farm.insights = dawgie.pl.resources.distribution(
-            dawgie.db.metrics()
-        )
+        if not self.__doctest:
+            dawgie.pl.farm.insights = dawgie.pl.resources.distribution(
+                dawgie.db.metrics(dawgie.pl.resources.last_runid())
+            )
         log.info('exiting state navel gaze')
         self.transitioning = Status.active
+        self.running_trigger()
         return
 
     def _pipeline(self, *_args, **_kwds):
@@ -408,7 +411,7 @@ def is_todo_done(self):
     def load(self):
         def done(*_args, **_kwds):
             self.transitioning = Status.active
-            self.running_trigger()
+            self.contemplation_trigger()
 
         log.info('entering state loading')
 
@@ -434,9 +437,14 @@ def done(*_args, **_kwds):
         return
 
     def navel_gaze(self):
-        self.transitioning = Status.exiting
-        d = twisted.internet.threads.deferToThread(self._navel_gaze, 2)
-        d.addErrback(dawgie.pl.LogFailure('while navel gazing', __name__).log)
+        self.transitioning = Status.entering
+        if self.__doctest:
+            self._navel_gaze()
+        else:
+            d = twisted.internet.threads.deferToThread(self._navel_gaze, 2)
+            d.addErrback(
+                dawgie.pl.LogFailure('while navel gazing', __name__).log
+            )
         return
 
     def reload(self):

Test/test_21.py

@@ -61,6 +61,8 @@ def test_archiving(self):
         )
         with self.assertRaises(MachineError):
             dawgie.context.fsm.archiving_trigger()
+        with self.assertRaises(MachineError):
+            dawgie.context.fsm.contemplation_trigger()
         with self.assertRaises(MachineError):
             dawgie.context.fsm.gitting_trigger()
         with self.assertRaises(MachineError):
@@ -83,6 +85,8 @@ def test_gitting(self):
         )
         with self.assertRaises(MachineError):
             dawgie.context.fsm.archiving_trigger()
+        with self.assertRaises(MachineError):
+            dawgie.context.fsm.contemplation_trigger()
         with self.assertRaises(MachineError):
             dawgie.context.fsm.gitting_trigger()
         with self.assertRaises(MachineError):
@@ -106,13 +110,15 @@ def test_loading(self):
             dawgie.context.fsm.gitting_trigger()
         with self.assertRaises(MachineError):
             dawgie.context.fsm.loading_trigger()
+        with self.assertRaises(MachineError):
+            dawgie.context.fsm.running_trigger()
         with self.assertRaises(MachineError):
             dawgie.context.fsm.starting_trigger()
         with self.assertRaises(MachineError):
             dawgie.context.fsm.update_trigger()
         with self.assertRaises(MachineError):
             dawgie.context.fsm.updating_trigger()
-        dawgie.context.fsm.running_trigger()
+        dawgie.context.fsm.contemplation_trigger()
         self.assertEqual('running', dawgie.context.fsm.state)
 
     def test_running(self):
@@ -146,6 +152,8 @@ def test_starting(self):
         )
         with self.assertRaises(MachineError):
             dawgie.context.fsm.archiving_trigger()
+        with self.assertRaises(MachineError):
+            dawgie.context.fsm.contemplation_trigger()
         with self.assertRaises(MachineError):
             dawgie.context.fsm.gitting_trigger()
         with self.assertRaises(MachineError):
@@ -163,6 +171,8 @@ def test_updating(self):
         dawgie.context.fsm = dawgie.pl.state.FSM(
             doctest_=True, initial_state='updating'
         )
+        with self.assertRaises(MachineError):
+            dawgie.context.fsm.contemplation_trigger()
         with self.assertRaises(MachineError):
             dawgie.context.fsm.gitting_trigger()
         with self.assertRaises(MachineError):