[logging] add a statistics class to collect timing info

we currently do not always get runtime info about the jobs, this change
collects them explicitly.

Author: mutax

networking_nsxv3/common/synchronization.py

@@ -177,6 +177,39 @@ def _put(self, item):
     def _get(self):
         return heapq.heappop(self.queue)
 
+class JobStats():
+    """
+    lets collect some stats for debugging, we might rip it out again,
+    so I am not embedding it too deep into Runnable or the _running dict
+    """
+
+    def __init__(self, jid: str):
+        self._jobid = jid
+        self._created = time.time()
+        self._done = None
+        self._popped = None
+
+    def done(self):
+        self._done = time.time()
+
+    def restarted(self):
+        self._popped = time.time()
+
+    def __repr__(self):
+
+        now = time.time()
+        age = now - self._created
+        runtime = None
+        restart = None
+
+        if self._done:
+            runtime = f"{self._done - self._created:0.4f}"
+
+        if self._popped:
+            restart = f"{self._popped - self._done:0.4f}"
+
+        return f"job {self._jobid} age: {age:0.4f}s time until done: {runtime or '-'} wait for restart: {restart or '-'}"
+
 
 class JobRerunner():
     """ Thread save data structure to reschedule jobs when it is already running
@@ -214,22 +247,40 @@ class JobRerunner():
     def __init__(self):
         self._ready = collections.deque()
         self._running = dict()
+        self._stats = dict()
 
     def pop(self) -> Runnable:
         # Let's also use the LockManager that is used for locking
         # in the code already. A simpler lock might do fine, but
         # for the LockManager we know it is working.
 
+
         with LockManager.get_lock("JobRerunner-deque"):
             try:
                 job = self._ready.popleft()
                 LOG.debug("JobRerunner had rerunnable job: %s", job)
             except IndexError:
                 job = None
                 LOG.debug("JobRerunner had no rerunnable job")
+
+        if job:
+            # no nested locks if not necessary
+            with LockManager.get_lock("JobRerunner-stats"):
+                stats = self._stats.get(job)
+                if stats is not None:
+                    stats.restarted()
+                    LOG.debug("JobRerunner stats: %s", stats)
+                    del self._stats[job]
         return job
 
     def job_done(self, job: Runnable):
+
+        with LockManager.get_lock("JobRerunner-stats"):
+            stats = self._stats.get(job)
+            if stats is not None:
+                stats.done()
+                LOG.info("JobRerunner stats: %s", stats)
+
         LOG.debug("JobRerunner job_done called for %s", job)
         with LockManager.get_lock("JobRerunner-running"):
             count = self._running.get(job, 0)
@@ -261,12 +312,7 @@ def add_job(self, job: Runnable) -> bool:
         """
         with LockManager.get_lock("JobRerunner-running"):
             count = self._running.get(job, 0)
-            if count == 0:
-                # no job running, we can run the job
-                self._running[job] = 1
-                LOG.debug("JobRerunner no identical job is currently running, can start %s", job)
-                return True
-            elif count > 0:
+            if count > 0:
                 count += 1
                 self._running[job] = count
                 LOG.debug("JobRerunner job %s already running, marked for rescheduling, count: %d ", job, count)
@@ -279,8 +325,21 @@ def add_job(self, job: Runnable) -> bool:
                 # to find issues with the JobRerunner:
                 LOG.info("JobRerunner stat: %d jobs waiting, total submission count: %d", len(self._running), sum)
                 LOG.info("JobRerunner stat: %d jobs ready for re-execution", len(self._ready))
+                return False
 
-        return False
+            # no job running, we can run the job
+            self._running[job] = 1
+
+        LOG.debug("JobRerunner no identical job is currently running, can start %s", job)
+
+        with LockManager.get_lock("JobRerunner-stats"):
+            stats = self._stats.get(job)
+            self._stats[job] = JobStats(str(job))
+
+        if stats:
+            LOG.error("JobRerunner stats should not exist when adding a new job: %s", stats)
+
+        return True
 
 
 class Runner(object):