From 9e9366950ed1795fdde4bfeedd1c77ad3c0f5db5 Mon Sep 17 00:00:00 2001
From: Uli Schlachter <psychon@znc.in>
Date: Fri, 7 Mar 2014 10:39:49 +0100
Subject: [PATCH] Measure the time a main loop iteration takes

This commit makes awesome measure how long all the event handling takes. That
is, this measure the time between waking up from poll and going to sleep again.
If that time is above 0.1 seconds, we print a warning and increase the limit for
this warning to the last duration to avoid flooding messages.

This should help figuring out cases were people do stupid things in their
config, like synchronously contacting an IMAP server and getting the number of
unread mails.

Signed-off-by: Uli Schlachter <psychon@znc.in>
---
 awesome.c | 32 +++++++++++++++++++++++++++++---
 1 file changed, 29 insertions(+), 3 deletions(-)

diff --git a/awesome.c b/awesome.c
index 75e1b9956..3cef91e1c 100644
--- a/awesome.c
+++ b/awesome.c
@@ -25,6 +25,7 @@
 #include <stdio.h>
 #include <unistd.h>
 #include <signal.h>
+#include <sys/time.h>
 
 #include <xcb/bigreq.h>
 #include <xcb/randr.h>
@@ -57,6 +58,12 @@ awesome_t globalconf;
 /** argv used to run awesome */
 static char *awesome_argv;
 
+/** time of last main loop wakeup */
+static struct timeval last_wakeup;
+
+/** current limit for the main loop's runtime */
+static float main_loop_iteration_limit = 0.1;
+
 /** Call before exiting.
  */
 void
@@ -217,9 +224,27 @@ static gint
 a_glib_poll(GPollFD *ufds, guint nfsd, gint timeout)
 {
     guint res;
+    struct timeval now, length_time;
+    float length;
+
+    /* Do all deferred work now */
     awesome_refresh();
+
+    /* Check how long this main loop iteration took */
+    gettimeofday(&now, NULL);
+    timersub(&now, &last_wakeup, &length_time);
+    length = length_time.tv_sec + length_time.tv_usec * 1.0f / 1e6;
+    if (length > main_loop_iteration_limit) {
+        warn("Last main loop iteration took %.6f seconds! Increasing limit for "
+                "this warning to that value.", length);
+        main_loop_iteration_limit = length;
+    }
+
+    /* Actually do the polling, record time of wakeup and check for new xcb events */
     res = g_poll(ufds, nfsd, timeout);
+    gettimeofday(&last_wakeup, NULL);
     a_xcb_check();
+
     return res;
 }
 
@@ -410,9 +435,6 @@ main(int argc, char **argv)
     if (xcb_cursor_context_new(globalconf.connection, globalconf.screen, &globalconf.cursor_ctx) < 0)
         fatal("Failed to initialize xcb-cursor");
 
-    /* Setup the main context */
-    g_main_context_set_poll_func(g_main_context_default(), &a_glib_poll);
-
     /* initialize dbus */
     a_dbus_init();
 
@@ -517,6 +539,10 @@ main(int argc, char **argv)
 
     xcb_flush(globalconf.connection);
 
+    /* Setup the main context */
+    g_main_context_set_poll_func(g_main_context_default(), &a_glib_poll);
+    gettimeofday(&last_wakeup, NULL);
+
     /* main event loop */
     globalconf.loop = g_main_loop_new(NULL, FALSE);
     g_main_loop_run(globalconf.loop);