Displaying statistics about the components that take the most time to paint

Here is a small patch to juce that displays the list of components that are being repainted, with their name, class name, duration of the last paint(). Here is an example of it output:

TopLevelComponent: MyApp t=0.0282652 getClipBounds=0 0 1023 1123
 0  0.028265s  100.0% 4.002453s (self:  1.0% 0.041799s) "MyApp" class StandaloneGUI sz=1023x1123
 1  0.000142s   3.9% 0.155630s (self:  3.9% 0.155630s)    "" class juce::MenuBarComponent sz=1021x31
 1  0.028028s  95.1% 3.805024s (self:  0.1% 0.005474s)    "" class StandaloneContent sz=1021x1090
 2  0.028025s  94.9% 3.799550s (self:  4.4% 0.174195s)      "" class MyJuceGUI sz=1021x1090
 3  0.028002s  90.6% 3.625355s (self:  0.2% 0.006369s)        "" struct MultiPanelComponent sz=1021x1090
 4  0.025638s  68.1% 2.724584s (self:  2.9% 0.117924s)          "" class MainWindowComponent sz=1021x929
 5  0.005302s  11.3% 0.452992s (self:  2.3% 0.093038s)            "big_toolbar" class BigToolbar sz=1021x132
 6  0.002920s   4.3% 0.172991s (self:  4.3% 0.172991s)              "btn_preset" class PresetsMenuButton sz=407x38
 6  0.000820s   1.1% 0.045230s (self:  1.1% 0.045230s)              "logo" class LogoSection sz=552x72
 6  0.000124s   0.4% 0.017497s (self:  0.4% 0.017497s)              "spectro" class juce::TextButton sz=35x14
 4  0.001788s  19.6% 0.783831s (self: 19.5% 0.778567s)          "keyboard" class KeyboardComponent sz=1021x120
 4  0.000558s   2.8% 0.110571s (self:  0.0% 0.000745s)          "" struct TransportBarHolder sz=1021x41
 5  0.000556s   2.7% 0.109826s (self:  0.3% 0.010971s)            "standalone_transport_bar" class TransportBar sz=1021x41
 6  0.000192s   0.6% 0.023729s (self:  0.6% 0.023729s)              "sequence_display" class SequenceComponent sz=259x33

The patch is the below, in juce_gui_basics/components/juce_Component.cpp. By default the feature is off, but it is enabled with juce::juce_collectPaintTimings() = true;

+#if JUCE_PAINT_TIMING_PATCH
+
+bool &juce_collectPaintTimings() { static bool enabled = false; return enabled; } 
+int  &juce_collectPaintTimingsMaxDepth() { static int max_depth = 8; return max_depth; }
+
+static const Identifier id_component_paint_timing("component_timing_last_paint"),
+    id_component_paint_timing_sum("component_timing_sum");
+
+void dumpCollectedPaintTimings(Component *c, int depth=0, double tref = -1) {
+    double t      = c->getProperties()[id_component_paint_timing];
+    double t_all  = c->getProperties()[id_component_paint_timing_sum];
+    int max_depth = juce_collectPaintTimingsMaxDepth();
+    if (tref == -1) tref = t_all;
+    if (t > 1e-4) {
+        double t_self = t_all;
+        for (auto child: c->getChildren()) {
+            double t_child = child->getProperties()[id_component_paint_timing_sum];
+            t_self -= t_child;
+        }
+        std::cerr << String::formatted("%2d  %8fs  %4.1f%% %8fs (self: %4.1f%% %8fs)",
+                                       depth, t, t_all/tref*100, t_all, t_self/tref*100, t_self) << "\t";
+        for (int i=0; i < depth; ++i) std::cerr << "  ";
+        std::cerr << "\"" << c->getName() << "\" " << typeid(*c).name() << " sz=" << c->getWidth() << "x" << c->getHeight() << "\n";
+        if (depth < max_depth) {
+            for (auto child: c->getChildren()) {
+                dumpCollectedPaintTimings(child, depth+1, tref);
+            }
+        }
+    }
+}
+
+#endif // JUCE_PAINT_TIMING_PATCH
+
 void Component::paintEntireComponent (Graphics& g, bool ignoreAlphaLevel)
 {
+#if JUCE_PAINT_TIMING_PATCH
+    int64 tics;
+    if (juce_collectPaintTimings() > 0) { tics = Time::getHighResolutionTicks(); }
+#endif // JUCE_PAINT_TIMING_PATCH
+
     // If sizing a top-level-window and the OS paint message is delivered synchronously
     // before resized() is called, then we'll invoke the callback here, to make sure
     // the components inside have had a chance to sort their sizes out..
@@ -1999,6 +2037,21 @@
    #if JUCE_DEBUG
     flags.isInsidePaintCall = false;
    #endif
+
+#if JUCE_PAINT_TIMING_PATCH
+    if (juce_collectPaintTimings() > 0) {
+        tics = Time::getHighResolutionTicks() - tics;
+        double t = Time::highResolutionTicksToSeconds(tics);
+        double t_sum = getProperties().getWithDefault(id_component_paint_timing_sum, 0.0);
+        getProperties().set(id_component_paint_timing, t);
+        getProperties().set(id_component_paint_timing_sum, t + t_sum);
+        if (getParentComponent() == nullptr && t > 2e-2) {
+            std::cerr << "TopLevelComponent: " << getName() << " duration=" << t << "s"
+                      << " getClipBounds=" << g.getClipBounds().toString() << "\n";
+            dumpCollectedPaintTimings(this);
+        }
+    }
+#endif //JUCE_PAINT_TIMING_PATCH
 }
9 Likes

Thanks JPO.
That sounds very useful.

Hmmm… just tested to implement this on Mac OSX. Getting linker errors. Did you get them, too?:

duplicate symbol ‘juce::juce_collectPaintTimingsMaxDepth()’ in:
/Users/martin/Library/Developer/Xcode/DerivedData/TestProj-bgokkrmlaczeazecyfhkmoupgyka/Build/Intermediates.noindex/TestProj.build/Debug/TestProj - Standalone Plugin.build/Objects-normal/x86_64/include_juce_audio_plugin_client_Standalone.o
/Users/martin/Programming/Audio/TestProj/Builds/MacOSX/build/Debug/libTestProj.a(include_juce_gui_basics.o)

Have you put the body of the juce_collectPaintTimingsMaxDepth() function in a .h file ? if that’s the case, declaring it inline should solve the duplicate symbol issue.

I bet there’s a whole load more useful stuff that could be printed here. Number of repaints, most popular repaint areas, and whether a component is transparent.

Thanks, working now :slight_smile: