Add a separate debug window section for profiler output (#11950)

Change-Id: I115f440d6dda5fac0788d3376f01e405e413c482

3 files changed, 400 insertions, 185 deletions

diff --git a/client/src/com/vaadin/client/ApplicationConfiguration.java b/client/src/com/vaadin/client/ApplicationConfiguration.java
index adf5e1de9d..9152e5ab23 100644
--- a/client/src/com/vaadin/client/ApplicationConfiguration.java
+++ b/client/src/com/vaadin/client/ApplicationConfiguration.java
@@ -38,6 +38,7 @@ import com.vaadin.client.debug.internal.ErrorNotificationHandler;
 import com.vaadin.client.debug.internal.HierarchySection;
 import com.vaadin.client.debug.internal.LogSection;
 import com.vaadin.client.debug.internal.NetworkSection;
+import com.vaadin.client.debug.internal.ProfilerSection;
 import com.vaadin.client.debug.internal.Section;
 import com.vaadin.client.debug.internal.VDebugWindow;
 import com.vaadin.client.metadata.BundleLoadCallback;
@@ -578,6 +579,9 @@ public class ApplicationConfiguration implements EntryPoint {
             }
             window.addSection((Section) GWT.create(HierarchySection.class));
             window.addSection((Section) GWT.create(NetworkSection.class));
+            if (Profiler.isEnabled()) {
+                window.addSection((Section) GWT.create(ProfilerSection.class));
+            }
 
             if (isQuietDebugMode()) {
                 window.close();
diff --git a/client/src/com/vaadin/client/Profiler.java b/client/src/com/vaadin/client/Profiler.java
index 95b3232723..caa512b34e 100644
--- a/client/src/com/vaadin/client/Profiler.java
+++ b/client/src/com/vaadin/client/Profiler.java
@@ -23,13 +23,14 @@ import java.util.HashMap;
 import java.util.LinkedHashMap;
 import java.util.LinkedList;
 import java.util.Map;
+import java.util.logging.Logger;
 
 import com.google.gwt.core.client.Duration;
 import com.google.gwt.core.client.JavaScriptObject;
 import com.google.gwt.core.client.JsArray;
 import com.google.gwt.core.shared.GWT;
-import com.google.gwt.user.client.ui.Label;
-import com.google.gwt.user.client.ui.Widget;
+import com.vaadin.client.debug.internal.ProfilerSection.Node;
+import com.vaadin.client.debug.internal.ProfilerSection.ProfilerResultConsumer;
 
 /**
  * Lightweight profiling tool that can be used to collect profiling data with
@@ -96,137 +97,7 @@ public class Profiler {
         }
     }
 
-    private static class Node {
-
-        private final String name;
-        private final LinkedHashMap<String, Node> children = new LinkedHashMap<String, Node>();
-        private double time = 0;
-        private int count = 0;
-
-        public Node(String name) {
-            this.name = name;
-        }
-
-        public String getName() {
-            return name;
-        }
-
-        private Node accessChild(String name, double time) {
-            Node child = children.get(name);
-            if (child == null) {
-                child = new Node(name);
-                children.put(name, child);
-            }
-            child.time -= time;
-            child.count++;
-            return child;
-        }
-
-        public double getTimeSpent() {
-            return time;
-        }
-
-        public int getCount() {
-            return count;
-        }
-
-        public double getOwnTime() {
-            double time = getTimeSpent();
-            for (Node node : children.values()) {
-                time -= node.getTimeSpent();
-            }
-            return time;
-        }
-
-        public Widget buildTree() {
-            String message = getStringRepresentation("");
-
-            if (getName() == null || !children.isEmpty()) {
-                SimpleTree tree = new SimpleTree(message);
-                for (Node node : children.values()) {
-                    Widget child = node.buildTree();
-                    tree.add(child);
-                }
-                return tree;
-            } else {
-                return new Label(message);
-            }
-        }
-
-        public void buildRecursiveString(StringBuilder builder, String prefix) {
-            if (getName() != null) {
-                String msg = getStringRepresentation(prefix);
-                builder.append(msg + '\n');
-            }
-            String childPrefix = prefix + "*";
-            for (Node node : children.values()) {
-                node.buildRecursiveString(builder, childPrefix);
-            }
-        }
-
-        @Override
-        public String toString() {
-            return getStringRepresentation("");
-        }
-
-        private String getStringRepresentation(String prefix) {
-            if (getName() == null) {
-                return "";
-            }
-            String msg = prefix + " " + getName() + " in " + getTimeSpent()
-                    + " ms.";
-            if (getCount() > 1) {
-                msg += " Invoked "
-                        + getCount()
-                        + " times ("
-                        + roundToSignificantFigures(getTimeSpent() / getCount())
-                        + " ms per time).";
-            }
-            if (!children.isEmpty()) {
-                double ownTime = getOwnTime();
-                msg += " " + ownTime + " ms spent in own code";
-                if (getCount() > 1) {
-                    msg += " ("
-                            + roundToSignificantFigures(ownTime / getCount())
-                            + " ms per time)";
-                }
-                msg += '.';
-            }
-            return msg;
-        }
-
-        public static double roundToSignificantFigures(double num) {
-            // Number of significant digits
-            int n = 3;
-            if (num == 0) {
-                return 0;
-            }
-
-            final double d = Math.ceil(Math.log10(num < 0 ? -num : num));
-            final int power = n - (int) d;
-
-            final double magnitude = Math.pow(10, power);
-            final long shifted = Math.round(num * magnitude);
-            return shifted / magnitude;
-        }
-
-        public void sumUpTotals(Map<String, Node> totals) {
-            String name = getName();
-            if (name != null) {
-                Node totalNode = totals.get(name);
-                if (totalNode == null) {
-                    totalNode = new Node(name);
-                    totals.put(name, totalNode);
-                }
-
-                totalNode.time += getOwnTime();
-                totalNode.count += getCount();
-            }
-            for (Node node : children.values()) {
-                node.sumUpTotals(totals);
-            }
-        }
-    }
+    private static ProfilerResultConsumer consumer;
 
     /**
      * Checks whether the profiling gathering is enabled.
@@ -323,7 +194,8 @@ public class Profiler {
      */
     public static void logTimings() {
         if (!isEnabled()) {
-            VConsole.log("Profiler is not enabled, no data has been collected.");
+            getLogger().warning(
+                    "Profiler is not enabled, no data has been collected.");
             return;
         }
 
@@ -332,7 +204,9 @@ public class Profiler {
         stack.add(rootNode);
         JsArray<GwtStatsEvent> gwtStatsEvents = getGwtStatsEvents();
         if (gwtStatsEvents.length() == 0) {
-            VConsole.log("No profiling events recorded, this might happen if another __gwtStatsEvent handler is installed.");
+            getLogger()
+                    .warning(
+                            "No profiling events recorded, this might happen if another __gwtStatsEvent handler is installed.");
             return;
         }
 
@@ -347,10 +221,10 @@ public class Profiler {
                     && !isBeginEvent;
 
             if (!inEvent && stack.size() >= 2
-                    && eventName.equals(stack.get(stack.size() - 2).name)
+                    && eventName.equals(stack.get(stack.size() - 2).getName())
                     && !isBeginEvent) {
                 // back out of sub event
-                stackTop.time += gwtStatsEvent.getMillis();
+                stackTop.addTime(gwtStatsEvent.getMillis());
                 stack.removeLast();
                 stackTop = stack.getLast();
 
@@ -359,41 +233,35 @@ public class Profiler {
 
             if (type.equals("end")) {
                 if (!inEvent) {
-                    VConsole.error("Got end event for " + eventName
-                            + " but is currently in " + stackTop.getName());
+                    getLogger().severe(
+                            "Got end event for " + eventName
+                                    + " but is currently in "
+                                    + stackTop.getName());
                     return;
                 }
                 Node previousStackTop = stack.removeLast();
-                previousStackTop.time += gwtStatsEvent.getMillis();
+                previousStackTop.addTime(gwtStatsEvent.getMillis());
             } else {
                 if (!inEvent) {
-                    stackTop = stackTop.accessChild(eventName,
+                    stackTop = stackTop.enterChild(eventName,
                             gwtStatsEvent.getMillis());
                     stack.add(stackTop);
                 }
                 if (!isBeginEvent) {
                     // Create sub event
-                    stack.add(stackTop.accessChild(eventName + "." + type,
+                    stack.add(stackTop.enterChild(eventName + "." + type,
                             gwtStatsEvent.getMillis()));
                 }
             }
         }
 
         if (stack.size() != 1) {
-            VConsole.log("Not all nodes are left, the last node is "
-                    + stack.getLast().getName());
+            getLogger().warning(
+                    "Not all nodes are left, the last node is "
+                            + stack.getLast().getName());
             return;
         }
 
-        StringBuilder stringBuilder = new StringBuilder();
-        rootNode.buildRecursiveString(stringBuilder, "");
-
-        /*
-         * Should really output to a separate section in the debug window, but
-         * just dump it to the log for now.
-         */
-        VConsole.log(stringBuilder.toString());
-
         Map<String, Node> totals = new HashMap<String, Node>();
         rootNode.sumUpTotals(totals);
 
@@ -405,27 +273,7 @@ public class Profiler {
             }
         });
 
-        double total = 0;
-        double top20total = 0;
-        for (int i = 0; i < totalList.size(); i++) {
-            Node node = totalList.get(i);
-            double timeSpent = node.getTimeSpent();
-            total += timeSpent;
-            if (i < 20) {
-                top20total += timeSpent;
-            }
-        }
-
-        VConsole.log("Largest individual contributors using " + top20total
-                + " ms out of " + total + " ms");
-        for (int i = 0; i < 20 && i < totalList.size(); i++) {
-            Node node = totalList.get(i);
-            double timeSpent = node.getTimeSpent();
-            total += timeSpent;
-            VConsole.log(" * " + node.getName() + ": " + timeSpent + " ms in "
-                    + node.getCount() + " invokations.");
-        }
-
+        getConsumer().addProfilerData(stack.getFirst(), totalList);
     }
 
     /**
@@ -460,28 +308,24 @@ public class Profiler {
                     "domContentLoadedEventStart", "domContentLoadedEventEnd",
                     "domComplete", "loadEventStart", "loadEventEnd" };
 
+            LinkedHashMap<String, Double> timings = new LinkedHashMap<String, Double>();
+
             for (String key : keys) {
                 double value = getPerformanceTiming(key);
                 if (value == 0) {
                     // Ignore missing value
                     continue;
                 }
-                String text = key + ": " + (now - value);
-                tree.add(new Label(text));
-                stringBuilder.append("\n * ");
-                stringBuilder.append(text);
+                timings.put(key, Double.valueOf(now - value));
             }
 
-            if (tree.getWidgetCount() == 0) {
-                VConsole.log("Bootstrap timings not supported, please ensure your browser supports performance.timing");
+            if (timings.isEmpty()) {
+                getLogger()
+                        .info("Bootstrap timings not supported, please ensure your browser supports performance.timing");
                 return;
             }
 
-            /*
-             * Should really output to a separate section in the debug window,
-             * but just dump it to the log for now.
-             */
-            VConsole.log(stringBuilder.toString());
+            getConsumer().addBootstrapData(timings);
         }
     }
 
@@ -535,4 +379,35 @@ public class Profiler {
         $wnd.vaadin.gwtStatsEvents = [];
     }-*/;
 
+    /**
+     * Sets the profiler result consumer that is used to output the profiler
+     * data to the user.
+     * <p>
+     * <b>Warning!</b> This is internal API and should not be used by
+     * applications or add-ons.
+     * 
+     * @since 7.1
+     * @param profilerResultConsumer
+     *            the consumer that gets profiler data
+     */
+    public static void setProfilerResultConsuer(
+            ProfilerResultConsumer profilerResultConsumer) {
+        if (consumer != null) {
+            throw new IllegalStateException("The consumer has already been set");
+        }
+        consumer = profilerResultConsumer;
+    }
+
+    private static ProfilerResultConsumer getConsumer() {
+        if (consumer == null) {
+            throw new IllegalStateException("No consumer has been registered");
+        } else {
+            return consumer;
+        }
+    }
+
+    private static Logger getLogger() {
+        return Logger.getLogger(Profiler.class.getName());
+    }
+
 }
diff --git a/client/src/com/vaadin/client/debug/internal/ProfilerSection.java b/client/src/com/vaadin/client/debug/internal/ProfilerSection.java
new file mode 100644
index 0000000000..f9d401de88
--- /dev/null
+++ b/client/src/com/vaadin/client/debug/internal/ProfilerSection.java
@@ -0,0 +1,336 @@
+package com.vaadin.client.debug.internal;
+
+import java.util.Collection;
+import java.util.Collections;
+import java.util.LinkedHashMap;
+import java.util.List;
+import java.util.Map;
+import java.util.Map.Entry;
+import java.util.Set;
+
+import com.google.gwt.user.client.ui.FlowPanel;
+import com.google.gwt.user.client.ui.HorizontalPanel;
+import com.google.gwt.user.client.ui.Label;
+import com.google.gwt.user.client.ui.Widget;
+import com.vaadin.client.ApplicationConnection;
+import com.vaadin.client.Profiler;
+import com.vaadin.client.SimpleTree;
+import com.vaadin.client.ValueMap;
+
+/**
+ * Debug window section for investigating {@link Profiler} data. This section is
+ * only visible if the profiler is enabled ({@link Profiler#isEnabled()}).
+ * 
+ * @since 7.1
+ * @author Vaadin Ltd
+ * 
+ * @see Profiler
+ */
+public class ProfilerSection implements Section {
+    /**
+     * Interface for getting data from the {@link Profiler}.
+     * <p>
+     * <b>Warning!</b> This interface is most likely to change in the future and
+     * is therefore defined in this class in an internal package instead of
+     * Profiler where it might seem more logical.
+     * 
+     * @since 7.1
+     * @author Vaadin Ltd
+     */
+    public interface ProfilerResultConsumer {
+        public void addProfilerData(Node rootNode, List<Node> totals);
+
+        public void addBootstrapData(LinkedHashMap<String, Double> timings);
+    }
+
+    /**
+     * A hierarchical representation of the time spent running a named block of
+     * code.
+     * <p>
+     * <b>Warning!</b> This class is most likely to change in the future and is
+     * therefore defined in this class in an internal package instead of
+     * Profiler where it might seem more logical.
+     */
+    public static class Node {
+        private final String name;
+        private final LinkedHashMap<String, Node> children = new LinkedHashMap<String, Node>();
+        private double time = 0;
+        private int count = 0;
+
+        /**
+         * Create a new node with the given name.
+         * 
+         * @param name
+         */
+        public Node(String name) {
+            this.name = name;
+        }
+
+        /**
+         * Gets the name of the node
+         * 
+         * @return the name of the node
+         */
+        public String getName() {
+            return name;
+        }
+
+        /**
+         * Creates a new child node or retrieves and existing child and updates
+         * its total time and hit count.
+         * 
+         * @param name
+         *            the name of the child
+         * @param time
+         *            the timestamp for when the node is entered
+         * @return the child node object
+         */
+        public Node enterChild(String name, double time) {
+            Node child = children.get(name);
+            if (child == null) {
+                child = new Node(name);
+                children.put(name, child);
+            }
+            child.time -= time;
+            child.count++;
+            return child;
+        }
+
+        /**
+         * Gets the total time spent in this node, including time spent in sub
+         * nodes
+         * 
+         * @return the total time spent, in milliseconds
+         */
+        public double getTimeSpent() {
+            return time;
+        }
+
+        /**
+         * Gets the number of times this node has been entered
+         * 
+         * @return the number of times the node has been entered
+         */
+        public int getCount() {
+            return count;
+        }
+
+        /**
+         * Gets the total time spent in this node, excluding time spent in sub
+         * nodes
+         * 
+         * @return the total time spent, in milliseconds
+         */
+        public double getOwnTime() {
+            double time = getTimeSpent();
+            for (Node node : children.values()) {
+                time -= node.getTimeSpent();
+            }
+            return time;
+        }
+
+        /**
+         * Gets the child nodes of this node
+         * 
+         * @return a collection of child nodes
+         */
+        public Collection<Node> getChildren() {
+            return Collections.unmodifiableCollection(children.values());
+        }
+
+        private void buildRecursiveString(StringBuilder builder, String prefix) {
+            if (getName() != null) {
+                String msg = getStringRepresentation(prefix);
+                builder.append(msg + '\n');
+            }
+            String childPrefix = prefix + "*";
+            for (Node node : children.values()) {
+                node.buildRecursiveString(builder, childPrefix);
+            }
+        }
+
+        @Override
+        public String toString() {
+            return getStringRepresentation("");
+        }
+
+        public String getStringRepresentation(String prefix) {
+            if (getName() == null) {
+                return "";
+            }
+            String msg = prefix + " " + getName() + " in " + getTimeSpent()
+                    + " ms.";
+            if (getCount() > 1) {
+                msg += " Invoked "
+                        + getCount()
+                        + " times ("
+                        + roundToSignificantFigures(getTimeSpent() / getCount())
+                        + " ms per time).";
+            }
+            if (!children.isEmpty()) {
+                double ownTime = getOwnTime();
+                msg += " " + ownTime + " ms spent in own code";
+                if (getCount() > 1) {
+                    msg += " ("
+                            + roundToSignificantFigures(ownTime / getCount())
+                            + " ms per time)";
+                }
+                msg += '.';
+            }
+            return msg;
+        }
+
+        private static double roundToSignificantFigures(double num) {
+            // Number of significant digits
+            int n = 3;
+            if (num == 0) {
+                return 0;
+            }
+
+            final double d = Math.ceil(Math.log10(num < 0 ? -num : num));
+            final int power = n - (int) d;
+
+            final double magnitude = Math.pow(10, power);
+            final long shifted = Math.round(num * magnitude);
+            return shifted / magnitude;
+        }
+
+        public void sumUpTotals(Map<String, Node> totals) {
+            String name = getName();
+            if (name != null) {
+                Node totalNode = totals.get(name);
+                if (totalNode == null) {
+                    totalNode = new Node(name);
+                    totals.put(name, totalNode);
+                }
+
+                totalNode.time += getOwnTime();
+                totalNode.count += getCount();
+            }
+            for (Node node : children.values()) {
+                node.sumUpTotals(totals);
+            }
+        }
+
+        /**
+         * @since
+         * @param time
+         */
+        public void addTime(double time) {
+            this.time += time;
+        }
+    }
+
+    private static final int MAX_ROWS = 10;
+
+    private final DebugButton tabButton = new DebugButton(Icon.RESET_TIMER,
+            "Profiler");
+
+    private final HorizontalPanel controls = new HorizontalPanel();
+    private final FlowPanel content = new FlowPanel();
+
+    public ProfilerSection() {
+        Profiler.setProfilerResultConsuer(new ProfilerResultConsumer() {
+            @Override
+            public void addProfilerData(Node rootNode, List<Node> totals) {
+                double totalTime = 0;
+                int eventCount = 0;
+                for (Node node : totals) {
+                    totalTime += node.getTimeSpent();
+                    eventCount += node.getCount();
+                }
+
+                SimpleTree drillDownTree = (SimpleTree) buildTree(rootNode);
+                drillDownTree.setText("Drill down");
+
+                SimpleTree offendersTree = new SimpleTree("Longest events");
+                for (int i = 0; i < totals.size() && i < 20; i++) {
+                    Node node = totals.get(i);
+                    offendersTree.add(new Label(node
+                            .getStringRepresentation("")));
+                }
+
+                SimpleTree root = new SimpleTree(eventCount
+                        + " profiler events using " + totalTime + " ms");
+                root.add(drillDownTree);
+                root.add(offendersTree);
+                root.open(false);
+
+                content.add(root);
+                applyLimit();
+            }
+
+            @Override
+            public void addBootstrapData(LinkedHashMap<String, Double> timings) {
+                SimpleTree tree = new SimpleTree(
+                        "Time since window.performance.timing events");
+                Set<Entry<String, Double>> entrySet = timings.entrySet();
+                for (Entry<String, Double> entry : entrySet) {
+                    tree.add(new Label(entry.getValue() + " " + entry.getKey()));
+                }
+
+                tree.open(false);
+                content.add(tree);
+                applyLimit();
+            }
+        });
+    }
+
+    private Widget buildTree(Node node) {
+        String message = node.getStringRepresentation("");
+
+        Collection<Node> children = node.getChildren();
+        if (node.getName() == null || !children.isEmpty()) {
+            SimpleTree tree = new SimpleTree(message);
+            for (Node childNode : children) {
+                Widget child = buildTree(childNode);
+                tree.add(child);
+            }
+            return tree;
+        } else {
+            return new Label(message);
+        }
+    }
+
+    private void applyLimit() {
+        while (content.getWidgetCount() > MAX_ROWS) {
+            content.remove(0);
+        }
+    }
+
+    @Override
+    public DebugButton getTabButton() {
+        return tabButton;
+    }
+
+    @Override
+    public Widget getControls() {
+        return controls;
+    }
+
+    @Override
+    public Widget getContent() {
+        return content;
+    }
+
+    @Override
+    public void show() {
+        // Nothing to do
+    }
+
+    @Override
+    public void hide() {
+        // Nothing to do
+    }
+
+    @Override
+    public void meta(ApplicationConnection ac, ValueMap meta) {
+        // Nothing to do
+    }
+
+    @Override
+    public void uidl(ApplicationConnection ac, ValueMap uidl) {
+        // Nothing to do
+    }
+
+}