Add extra logging to debug the event loop

This should make tracking down the root cause of the
event loop pauses on X11 easier. And the infrastructure
should come in handy in the future as well.

Author: kovidgoyal

Makefile

@@ -18,6 +18,9 @@ clean:
 debug:
 	python3 setup.py build $(VVAL) --debug
 
+debug-event-loop:
+	python3 setup.py build $(VVAL) --debug --extra-logging=event-loop
+
 # Build with the ASAN and UBSAN sanitizers
 asan:
 	python3 setup.py build $(VVAL) --debug --sanitize

glfw/init.c

@@ -193,6 +193,20 @@ void _glfwInputError(int code, const char* format, ...)
         _glfwErrorCallback(code, description);
 }
 
+void
+_glfwDebug(const char *format, ...) {
+    if (format)
+    {
+        va_list vl;
+
+        fprintf(stderr, "[%.4f] ", glfwGetTime());
+        va_start(vl, format);
+        vfprintf(stderr, format, vl);
+        va_end(vl);
+        fprintf(stderr, "\n");
+    }
+
+}
 
 //////////////////////////////////////////////////////////////////////////
 //////                        GLFW public API                       //////

glfw/internal.h

@@ -743,13 +743,21 @@ void _glfwInputJoystickHat(_GLFWjoystick* js, int hat, char value);
 void _glfwInputMonitor(_GLFWmonitor* monitor, int action, int placement);
 void _glfwInputMonitorWindow(_GLFWmonitor* monitor, _GLFWwindow* window);
 
-#if defined(__GNUC__)
+#if defined(__GNUC__) || defined(__clang__)
 void _glfwInputError(int code, const char* format, ...)
     __attribute__((format(printf, 2, 3)));
+void _glfwDebug(const char* format, ...)
+    __attribute__((format(printf, 1, 2)));
 #else
 void _glfwInputError(int code, const char* format, ...);
+void _glfwDebug(const char* format, ...);
 #endif
 
+#ifdef DEBUG_EVENT_LOOP
+#define EVDBG(...) _glfwDebug(__VA_ARGS__)
+#else
+#define EVDBG(...)
+#endif
 
 //////////////////////////////////////////////////////////////////////////
 //////                       GLFW internal API                      //////

glfw/main_loop.h

@@ -29,6 +29,7 @@ void _glfwPlatformRunMainLoop(GLFWtickcallback callback, void* data) {
     keep_going = GLFW_TRUE;
     tick_callback_requested = GLFW_FALSE;
     while(keep_going) {
+		EVDBG("tick_callback_requested: %d", tick_callback_requested);
         while (tick_callback_requested) {
             tick_callback_requested = GLFW_FALSE;
             callback(data);

glfw/x11_window.c

@@ -59,10 +59,16 @@ GLFWbool _glfwDispatchX11Events(void);
 
 static void
 handleEvents(double timeout) {
+    EVDBG("starting handleEvents(%.2f)", timeout);
     int display_read_ok = pollForEvents(&_glfw.x11.eventLoopData, timeout);
-    if (display_read_ok) _glfwDispatchX11Events();
+    EVDBG("display_read_ok: %d", display_read_ok);
+    if (display_read_ok) {
+        _glfwDispatchX11Events();
+        EVDBG("_glfwDispatchX11Events() done");
+    }
     glfw_ibus_dispatch(&_glfw.x11.xkb.ibus);
     glfw_dbus_session_bus_dispatch();
+    EVDBG("other dispatch done");
 }
 
 static GLFWbool

setup.py

@@ -178,7 +178,8 @@ def copy(self):
 
 
 def init_env(
-    debug=False, sanitize=False, native_optimizations=True, profile=False
+    debug=False, sanitize=False, native_optimizations=True, profile=False,
+    extra_logging=()
 ):
     native_optimizations = native_optimizations and not sanitize and not debug
     cc, ccver = cc_version()
@@ -200,6 +201,8 @@ def init_env(
         )
     )
     cppflags = shlex.split(cppflags)
+    for el in extra_logging:
+        cppflags.append('-DDEBUG_{}'.format(el.upper().replace('-', '_')))
     cflags = os.environ.get(
         'OVERRIDE_CFLAGS', (
             '-Wextra -Wno-missing-field-initializers -Wall -std=c11'
@@ -508,7 +511,7 @@ def build(args, native_optimizations=True):
     compilation_database = {
         (k['file'], k.get('output')): k['arguments'] for k in compilation_database
     }
-    env = init_env(args.debug, args.sanitize, native_optimizations, args.profile)
+    env = init_env(args.debug, args.sanitize, native_optimizations, args.profile, args.extra_logging)
     try:
         compile_c_extension(
             kitty_env(), 'kitty/fast_data_types', args.incremental, compilation_database, all_keys, *find_c_files()
@@ -842,6 +845,13 @@ def option_parser():  # {{{
         default='lib',
         help='The name of the directory inside --prefix in which to store compiled files. Defaults to "lib"'
     )
+    p.add_argument(
+        '--extra-logging',
+        action='append',
+        choices=('event-loop',),
+        help='Turn on extra logging for debugging in this build. Can be specified multiple times, to turn'
+        'on different types of logging.'
+    )
     return p
 # }}}