instrument event latency

(bzr r6231)

5 files changed, 133 insertions, 0 deletions

diff --git a/src/debug/CMakeLists.txt b/src/debug/CMakeLists.txt
index 88c8b8e29..5eb0b3cfe 100644
--- a/src/debug/CMakeLists.txt
+++ b/src/debug/CMakeLists.txt
@@ -5,5 +5,6 @@ log-display-config.cpp
 logger.cpp
 sysv-heap.cpp
 timestamp.cpp
+gdk-event-latency-tracker.cpp
 )
 
diff --git a/src/debug/Makefile_insert b/src/debug/Makefile_insert
index 96a12f3f4..699ceac84 100644
--- a/src/debug/Makefile_insert
+++ b/src/debug/Makefile_insert
@@ -14,5 +14,6 @@ debug_libinkdebug_a_SOURCES = \
 	debug/log-display-config.cpp debug/log-display-config.h \
 	debug/simple-event.h \
 	debug/sysv-heap.cpp debug/sysv-heap.h \
+	debug/gdk-event-latency-tracker.cpp debug/gdk-event-latency-tracker.h \
         debug/timestamp.cpp debug/timestamp.h
 
diff --git a/src/debug/gdk-event-latency-tracker.cpp b/src/debug/gdk-event-latency-tracker.cpp
new file mode 100644
index 000000000..8e34d2fc2
--- /dev/null
+++ b/src/debug/gdk-event-latency-tracker.cpp
@@ -0,0 +1,65 @@
+/*
+ * Inkscape::Debug::GdkEventLatencyTracker - tracks backlog of GDK events
+ *
+ * Authors:
+ *   MenTaLguY <mental@rydia.net>
+ *
+ * Copyright (C) 2008 MenTaLguY
+ *
+ * Released under GNU GPL, read the file 'COPYING' for more information
+ */
+
+#include "debug/gdk-event-latency-tracker.h"
+
+namespace Inkscape {
+namespace Debug {
+
+GdkEventLatencyTracker::GdkEventLatencyTracker()
+: start_seconds(0.0), max_latency(0.0)
+{
+    elapsed.stop();
+    elapsed.reset();
+}
+
+boost::optional<double> GdkEventLatencyTracker::process(GdkEvent const *event) {
+    guint32 const timestamp=gdk_event_get_time(const_cast<GdkEvent *>(event));
+    if (timestamp == GDK_CURRENT_TIME) {
+        return boost::optional<double>();
+    }
+    double const timestamp_seconds = timestamp / 1000.0;
+
+    if (start_seconds == 0.0) {
+        elapsed.start();
+        start_seconds = timestamp_seconds;
+        return boost::optional<double>(0.0);
+    } else {
+        double const current_seconds = elapsed.elapsed() + start_seconds;
+        double delta = current_seconds - timestamp_seconds;
+        if (delta < 0.0) {
+            start_seconds += -delta;
+            delta = 0.0;
+        } else if (delta > max_latency) {
+            max_latency = delta;
+        }
+        return boost::optional<double>(delta);
+    }
+}
+
+GdkEventLatencyTracker &GdkEventLatencyTracker::default_tracker() {
+    static GdkEventLatencyTracker tracker;
+    return tracker;
+}
+
+}
+}
+
+/*
+  Local Variables:
+  mode:c++
+  c-file-style:"stroustrup"
+  c-file-offsets:((innamespace . 0)(inline-open . 0)(case-label . +))
+  indent-tabs-mode:nil
+  fill-column:99
+  End:
+*/
+// vim: filetype=cpp:expandtab:shiftwidth=4:tabstop=8:softtabstop=4:encoding=utf-8:textwidth=99 :
diff --git a/src/debug/gdk-event-latency-tracker.h b/src/debug/gdk-event-latency-tracker.h
new file mode 100644
index 000000000..8a22fec82
--- /dev/null
+++ b/src/debug/gdk-event-latency-tracker.h
@@ -0,0 +1,52 @@
+/*
+ * Inkscape::Debug::GdkEventLatencyTracker - tracks backlog of GDK events
+ *
+ * Authors:
+ *   MenTaLguY <mental@rydia.net>
+ *
+ * Copyright (C) 2008 MenTaLguY
+ *
+ * Released under GNU GPL, read the file 'COPYING' for more information
+ */
+
+#ifndef SEEN_INKSCAPE_DEBUG_GDK_EVENT_LATENCY_TRACKER_H
+#define SEEN_INKSCAPE_DEBUG_GDK_EVENT_LATENCY_TRACKER_H
+
+#include <gdk/gdkevents.h>
+#include <glibmm/timer.h>
+#include <boost/optional.hpp>
+
+namespace Inkscape {
+namespace Debug {
+
+class GdkEventLatencyTracker {
+public:
+    GdkEventLatencyTracker();
+    boost::optional<double> process(GdkEvent const *e);
+    double maxLatency() const { return max_latency; }
+
+    static GdkEventLatencyTracker &default_tracker();
+
+private:
+    GdkEventLatencyTracker(GdkEventLatencyTracker const &); // no copy
+    void operator=(GdkEventLatencyTracker const &); // no assign
+
+    double start_seconds;
+    double max_latency;
+    Glib::Timer elapsed;
+};
+
+}
+}
+
+#endif
+/*
+  Local Variables:
+  mode:c++
+  c-file-style:"stroustrup"
+  c-file-offsets:((innamespace . 0)(inline-open . 0)(case-label . +))
+  indent-tabs-mode:nil
+  fill-column:99
+  End:
+*/
+// vim: filetype=cpp:expandtab:shiftwidth=4:tabstop=8:softtabstop=4:encoding=utf-8:textwidth=99 :
diff --git a/src/display/sp-canvas.cpp b/src/display/sp-canvas.cpp
index def126cd3..3d63d7cdd 100644
--- a/src/display/sp-canvas.cpp
+++ b/src/display/sp-canvas.cpp
@@ -43,6 +43,9 @@
 #include "display/rendermode.h"
 #include "libnr/nr-blit.h"
 #include "display/inkscape-cairo.h"
+#include "debug/gdk-event-latency-tracker.h"
+
+using Inkscape::Debug::GdkEventLatencyTracker;
 
 // GTK_CHECK_VERSION returns false on failure
 #define HAS_GDK_EVENT_REQUEST_MOTIONS GTK_CHECK_VERSION(2, 12, 0)
@@ -102,6 +105,7 @@ enum {ITEM_EVENT, ITEM_LAST_SIGNAL};
 
 static void sp_canvas_request_update (SPCanvas *canvas);
 
+static void track_latency(GdkEvent const *event);
 static void sp_canvas_item_class_init (SPCanvasItemClass *klass);
 static void sp_canvas_item_init (SPCanvasItem *item);
 static void sp_canvas_item_dispose (GObject *object);
@@ -1097,6 +1101,14 @@ sp_canvas_destroy (GtkObject *object)
         (* GTK_OBJECT_CLASS (canvas_parent_class)->destroy) (object);
 }
 
+static void track_latency(GdkEvent const *event) {
+    GdkEventLatencyTracker &tracker = GdkEventLatencyTracker::default_tracker();
+    boost::optional<double> latency = tracker.process(event);
+    if (latency && *latency > 2.0) {
+        g_warning("Event latency reached %f sec", *latency);
+    }
+}
+
 /**
  * Returns new canvas as widget.
  */
@@ -1564,6 +1576,8 @@ sp_canvas_motion (GtkWidget *widget, GdkEventMotion *event)
     int status;
     SPCanvas *canvas = SP_CANVAS (widget);
 
+    track_latency((GdkEvent *)event);
+
     if (event->window != SP_CANVAS_WINDOW (canvas))
         return FALSE;