diff mbox series

server/process: Add more timing debug

Message ID 20230905071446.2784798-1-richard.purdie@linuxfoundation.org
State Accepted, archived
Commit 65969a7a8f5ae22c230431d2db080eb187a27708
Headers show
Series server/process: Add more timing debug | expand

Commit Message

Richard Purdie Sept. 5, 2023, 7:14 a.m. UTC 
It is helpful to have timestamps on the ping failures so that they
can be matched against the bitbake logs. It is also useful to understand
how long the server takes for form a reply verses when it is sent.

Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
---
 lib/bb/server/process.py | 13 +++++++++----
 1 file changed, 9 insertions(+), 4 deletions(-)
diff mbox series

Patch

diff --git a/lib/bb/server/process.py b/lib/bb/server/process.py
index f62faed000..40cb99bc97 100644
--- a/lib/bb/server/process.py
+++ b/lib/bb/server/process.py
@@ -38,8 +38,11 @@  logger = logging.getLogger('BitBake')
 class ProcessTimeout(SystemExit):
     pass
 
+def currenttime():
+    return datetime.datetime.now().strftime('%H:%M:%S.%f')
+
 def serverlog(msg):
-    print(str(os.getpid()) + " " +  datetime.datetime.now().strftime('%H:%M:%S.%f') + " " + msg)
+    print(str(os.getpid()) + " " +  currenttime() + " " + msg)
     sys.stdout.flush()
 
 #
@@ -289,7 +292,9 @@  class ProcessServer():
                     continue
                 try:
                     serverlog("Running command %s" % command)
-                    self.command_channel_reply.send(self.cooker.command.runCommand(command, self))
+                    reply = self.cooker.command.runCommand(command, self)
+                    serverlog("Sending reply %s" % repr(reply))
+                    self.command_channel_reply.send(reply)
                     serverlog("Command Completed (socket: %s)" % os.path.exists(self.sockname))
                 except Exception as e:
                    stack = traceback.format_exc()
@@ -502,9 +507,9 @@  class ServerCommunicator():
     def runCommand(self, command):
         self.connection.send(command)
         if not self.recv.poll(30):
-            logger.info("No reply from server in 30s (for command %s)" % command[0])
+            logger.info("No reply from server in 30s (for command %s at %s)" % (command[0], currenttime()))
             if not self.recv.poll(30):
-                raise ProcessTimeout("Timeout while waiting for a reply from the bitbake server (60s)")
+                raise ProcessTimeout("Timeout while waiting for a reply from the bitbake server (60s at %s)" % currenttime())
         ret, exc = self.recv.get()
         # Should probably turn all exceptions in exc back into exceptions?
         # For now, at least handle BBHandledException