diff options
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 + } + +} |