Tracing support

src/init.c

@@ -12,6 +12,7 @@
 #include "server.h"
 #include "signals.h"
 #include "tooltip.h"
+#include "tracing.h"
 #include "uevent.h"
 #include "version.h"
 
@@ -83,8 +84,13 @@ void handle_env_vars()
     debug_gradients = getenv("DEBUG_GRADIENTS") != NULL;
     debug_fps = getenv("DEBUG_FPS") != NULL;
     debug_frames = getenv("DEBUG_FRAMES") != NULL;
-    if (debug_fps)
+    if (debug_fps) {
         init_fps_distribution();
+        char *s = getenv("TRACING_FPS_THRESHOLD");
+        if (!s || sscanf(s, "%lf", &tracing_fps_threshold) != 1) {
+            tracing_fps_threshold = 60;
+        }
+    }
 }
 
 static timeout *detect_compositor_timer = NULL;
@@ -269,4 +275,8 @@ void cleanup()
 
     uevent_cleanup();
     cleanup_fps_distribution();
+
+#ifdef HAVE_TRACING
+    cleanup_tracing();
+#endif
 }

src/main.c

@@ -57,6 +57,7 @@
 #include "taskbar.h"
 #include "tooltip.h"
 #include "timer.h"
+#include "tracing.h"
 #include "uevent.h"
 #include "version.h"
 #include "window.h"
@@ -69,6 +70,7 @@ XSettingsClient *xsettings_client = NULL;
 gboolean debug_fps = FALSE;
 gboolean debug_frames = FALSE;
 static int frame = 0;
+double tracing_fps_threshold = 60;
 static double ts_event_read;
 static double ts_event_processed;
 static double ts_render_finished;
@@ -711,6 +713,12 @@ void handle_panel_refresh()
                 proc_ratio * 100,
                 render_ratio * 100,
                 flush_ratio * 100);
+#ifdef HAVE_TRACING
+        stop_tracing();
+        if (fps <= tracing_fps_threshold) {
+            print_tracing_events();
+        }
+#endif
     }
     if (debug_frames) {
         for (int i = 0; i < num_panels; i++) {
@@ -741,6 +749,9 @@ void run_tint2_event_loop()
         // Wait for an event and handle it
         ts_event_read = 0;
         if (XPending(server.display) > 0 || select(max_fd + 1, &fd_set, 0, 0, get_next_timeout()) >= 0) {
+#ifdef HAVE_TRACING
+            start_tracing((void*)run_tint2_event_loop);
+#endif
             uevent_handler();
             handle_sigchld_events();
             handle_execp_events();

src/panel.h

@@ -92,6 +92,7 @@ extern XSettingsClient *xsettings_client;
 extern gboolean startup_notifications;
 extern gboolean debug_geometry;
 extern gboolean debug_fps;
+extern double tracing_fps_threshold;
 extern gboolean debug_frames;
 
 typedef struct Panel {

src/server.c

@@ -23,6 +23,7 @@
 #include <X11/extensions/Xrandr.h>
 
 #include <stdio.h>
+#include <fcntl.h>
 #include <stdlib.h>
 #include <string.h>
 #include <unistd.h>

src/tracing.c

@@ -0,0 +1,164 @@
+#include "timer.h"
+
+#ifdef HAVE_TRACING
+
+#ifdef ENABLE_EXECINFO
+#include <execinfo.h>
+#endif
+#include <glib.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+
+#define GREEN "\033[1;32m"
+#define YELLOW "\033[1;33m"
+#define RED "\033[1;31m"
+#define BLUE "\033[1;34m"
+#define RESET "\033[0m"
+
+static GList *tracing_events = NULL;
+static sig_atomic_t tracing = FALSE;
+
+typedef struct TracingEvent {
+    void *address;
+    void *caller;
+    double time;
+    gboolean enter;
+} TracingEvent;
+
+void __attribute__ ((constructor)) init_tracing()
+{
+    tracing_events = NULL;
+    tracing = FALSE;
+}
+
+void cleanup_tracing()
+{
+    g_list_free_full(tracing_events, free);
+    tracing_events = NULL;
+    tracing = FALSE;
+}
+
+char *addr2name(void *func)
+{
+#ifdef ENABLE_EXECINFO
+    void *array[1];
+    array[0] = func;
+    char **strings = backtrace_symbols(array, 1);
+    char *result = strdup(strings[0] ? strings[0] : "??");
+    free(strings);
+    return result;
+#else
+    char *result = (char*) calloc(32, 1);
+    sprintf(result, "%p", func);
+    return result;
+#endif
+}
+
+void add_tracing_event(void *func, void *caller, gboolean enter)
+{
+    TracingEvent *entry = (TracingEvent *)calloc(sizeof(TracingEvent), 1);
+    entry->address = func;
+    entry->caller = caller;
+    entry->time = get_time();
+    entry->enter = enter;
+    tracing_events = g_list_append(tracing_events, entry);
+}
+
+void start_tracing(void *root)
+{
+    if (tracing_events)
+        cleanup_tracing();
+    add_tracing_event(root, NULL, TRUE);
+    tracing = TRUE;
+}
+
+void stop_tracing()
+{
+    tracing = FALSE;
+}
+
+void __cyg_profile_func_enter(void *func, void *caller)
+{
+    if (tracing)
+        add_tracing_event(func, caller, TRUE);
+}
+
+void __cyg_profile_func_exit(void *func, void *caller)
+{
+    if (tracing)
+        add_tracing_event(func, caller, FALSE);
+}
+
+void print_tracing_events()
+{
+    GList *stack = NULL;
+    int depth = 0;
+    double now = get_time();
+    for (GList *i = tracing_events; i; i = i->next) {
+        TracingEvent *e = (TracingEvent *)i->data;
+        if (e->enter) {
+            // Push a new function on the stack
+            for (int d = 0; d < depth; d++)
+                fprintf(stderr, " ");
+            char *name = addr2name(e->address);
+            char *caller = addr2name(e->caller);
+            fprintf(stderr,
+                    "%s called from %s\n",
+                    name,
+                    caller);
+            stack = g_list_append(stack, e);
+            depth++;
+        } else {
+            // Pop a function from the stack, if matching, and print
+            if (stack) {
+                TracingEvent *old = (TracingEvent *)g_list_last(stack)->data;
+                if (old->address == e->address) {
+                    depth--;
+                    for (int d = 0; d < depth; d++)
+                        fprintf(stderr, " ");
+                    char *name = addr2name(e->address);
+                    double duration = (e->time - old->time) * 1.0e3;
+                    fprintf(stderr,
+                            "-- %s exited after %.1f ms",
+                            name,
+                            duration);
+                    if (duration >= 1.0) {
+                        fprintf(stderr, YELLOW " ");
+                        for (int d = 0; d < duration; d++) {
+                            fprintf(stderr, "#");
+                        }
+                        fprintf(stderr, RESET);
+                    }
+                    fprintf(stderr, "\n");
+                    free(name);
+                    stack = g_list_delete_link(stack, g_list_last(stack));
+                }
+            }
+        }
+    }
+    while (stack) {
+        TracingEvent *old = (TracingEvent *)g_list_last(stack)->data;
+        depth--;
+        for (int d = 0; d < depth; d++)
+            fprintf(stderr, " ");
+        char *name = addr2name(old->address);
+        double duration = (now - old->time) * 1.0e3;
+        fprintf(stderr,
+                "-- %s exited after %.1f ms",
+                name,
+                duration);
+        if (duration >= 1.0) {
+            fprintf(stderr, YELLOW " ");
+            for (int d = 0; d < duration; d++) {
+                fprintf(stderr, "#");
+            }
+            fprintf(stderr, RESET);
+        }
+        fprintf(stderr, "\n");
+        free(name);
+        stack = g_list_delete_link(stack, g_list_last(stack));
+    }
+}
+
+#endif

src/tracing.h

@@ -0,0 +1,15 @@
+#ifndef TRACING_H
+#define TRACING_H
+
+#ifdef HAVE_TRACING
+
+void init_tracing();
+void cleanup_tracing();
+
+void start_tracing(void *root);
+void stop_tracing();
+void print_tracing_events();
+
+#endif
+
+#endif