diff mbox series

[1/4] runqueue: Add timing warnings around slow loops

Message ID 20240528204420.2845521-1-richard.purdie@linuxfoundation.org
State Accepted, archived
Commit 6c357ede08e0b2a93bdaad2c1d631994faf2b784
Headers show
Series [1/4] runqueue: Add timing warnings around slow loops | expand

Commit Message

Richard Purdie May 28, 2024, 8:44 p.m. UTC 
With hashserve enabled, there are two slow paths/loops, one at initial runqueue
generation and also during the rehash process when new outhashes are found.

Add timing information at the hashserve log level for when these loops
take longer than 30s or 60s overall. This will leave evidence in the logs when
things are running particularly slowly.

Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
---
 lib/bb/runqueue.py | 22 ++++++++++++++++++++++
 1 file changed, 22 insertions(+)
diff mbox series

Patch

diff --git a/lib/bb/runqueue.py b/lib/bb/runqueue.py
index 6b43f303d5..83e5273449 100644
--- a/lib/bb/runqueue.py
+++ b/lib/bb/runqueue.py
@@ -1273,6 +1273,9 @@  class RunQueueData:
 
         bb.parse.siggen.set_setscene_tasks(self.runq_setscene_tids)
 
+        starttime = time.time()
+        lasttime = starttime
+
         # Iterate over the task list and call into the siggen code
         dealtwith = set()
         todeal = set(self.runtaskentries)
@@ -1284,6 +1287,14 @@  class RunQueueData:
                     self.prepare_task_hash(tid)
                 bb.event.check_for_interrupts(self.cooker.data)
 
+            if time.time() > (lasttime + 30):
+                lasttime = time.time()
+                hashequiv_logger.verbose("Initial setup loop progress: %s of %s in %s" % (len(todeal), len(self.runtaskentries), lasttime - starttime))
+
+        endtime = time.time()
+        if (endtime-starttime > 60):
+            hashequiv_logger.verbose("Initial setup loop took: %s" % (endtime-starttime))
+
         bb.parse.siggen.writeout_file_checksum_cache()
 
         #self.dump_data()
@@ -2557,6 +2568,9 @@  class RunQueueExecute:
             elif self.rqdata.runtaskentries[p].depends.isdisjoint(total):
                 next.add(p)
 
+        starttime = time.time()
+        lasttime = starttime
+
         # When an item doesn't have dependencies in total, we can process it. Drop items from total when handled
         while next:
             current = next.copy()
@@ -2589,6 +2603,14 @@  class RunQueueExecute:
                 total.remove(tid)
                 next.intersection_update(total)
 
+                if time.time() > (lasttime + 30):
+                    lasttime = time.time()
+                    hashequiv_logger.verbose("Rehash loop slow progress: %s in %s" % (len(total), lasttime - starttime))
+
+        endtime = time.time()
+        if (endtime-starttime > 60):
+            hashequiv_logger.verbose("Rehash loop took more than 60s: %s" % (endtime-starttime))
+
         if changed:
             for mc in self.rq.worker:
                 RunQueue.send_pickled_data(self.rq.worker[mc].process, bb.parse.siggen.get_taskhashes(), "newtaskhashes")