Use high resolution time for profiling if it's available #14716, #18782.

Change-Id: Id45ccd47cac3bcdb14c5d4e93e4fb8225b1b2864

8 files changed, 277 insertions, 52 deletions

diff --git a/client/src/com/vaadin/client/ApplicationConnection.java b/client/src/com/vaadin/client/ApplicationConnection.java
index 01fe13a6ff..1ae52d71fc 100644
--- a/client/src/com/vaadin/client/ApplicationConnection.java
+++ b/client/src/com/vaadin/client/ApplicationConnection.java
@@ -42,7 +42,6 @@ import com.google.gwt.user.client.Timer;
 import com.google.gwt.user.client.ui.HasWidgets;
 import com.google.gwt.user.client.ui.Widget;
 import com.vaadin.client.ApplicationConfiguration.ErrorMessage;
-import com.vaadin.client.ApplicationConnection.ApplicationStoppedEvent;
 import com.vaadin.client.ResourceLoader.ResourceLoadEvent;
 import com.vaadin.client.ResourceLoader.ResourceLoadListener;
 import com.vaadin.client.communication.ConnectionStateHandler;
@@ -550,27 +549,27 @@ public class ApplicationConnection implements HasHandlers {
      */
     private native void initializeClientHooks()
     /*-{
-    	var app = this;
-    	var oldSync;
-    	if ($wnd.vaadin.forceSync) {
-    		oldSync = $wnd.vaadin.forceSync;
-    	}
-    	$wnd.vaadin.forceSync = $entry(function() {
-    		if (oldSync) {
-    			oldSync();
-    		}
-    		app.@com.vaadin.client.ApplicationConnection::sendPendingVariableChanges()();
-    	});
-    	var oldForceLayout;
-    	if ($wnd.vaadin.forceLayout) {
-    		oldForceLayout = $wnd.vaadin.forceLayout;
-    	}
-    	$wnd.vaadin.forceLayout = $entry(function() {
-    		if (oldForceLayout) {
-    			oldForceLayout();
-    		}
-    		app.@com.vaadin.client.ApplicationConnection::forceLayout()();
-    	});
+        var app = this;
+        var oldSync;
+        if ($wnd.vaadin.forceSync) {
+                oldSync = $wnd.vaadin.forceSync;
+        }
+        $wnd.vaadin.forceSync = $entry(function() {
+                if (oldSync) {
+                        oldSync();
+                }
+                app.@com.vaadin.client.ApplicationConnection::sendPendingVariableChanges()();
+        });
+        var oldForceLayout;
+        if ($wnd.vaadin.forceLayout) {
+                oldForceLayout = $wnd.vaadin.forceLayout;
+        }
+        $wnd.vaadin.forceLayout = $entry(function() {
+                if (oldForceLayout) {
+                        oldForceLayout();
+                }
+                app.@com.vaadin.client.ApplicationConnection::forceLayout()();
+        });
     }-*/;
 
     /**
diff --git a/client/src/com/vaadin/client/Profiler.java b/client/src/com/vaadin/client/Profiler.java
index 4b35427575..f3b449ae36 100644
--- a/client/src/com/vaadin/client/Profiler.java
+++ b/client/src/com/vaadin/client/Profiler.java
@@ -21,16 +21,18 @@ import java.util.Collection;
 import java.util.Collections;
 import java.util.Comparator;
 import java.util.HashMap;
+import java.util.HashSet;
 import java.util.LinkedHashMap;
 import java.util.LinkedList;
 import java.util.List;
 import java.util.Map;
+import java.util.Set;
 import java.util.logging.Logger;
 
 import com.google.gwt.core.client.Duration;
+import com.google.gwt.core.client.GWT;
 import com.google.gwt.core.client.JavaScriptObject;
 import com.google.gwt.core.client.JsArray;
-import com.google.gwt.core.shared.GWT;
 
 /**
  * Lightweight profiling tool that can be used to collect profiling data with
@@ -42,6 +44,13 @@ import com.google.gwt.core.shared.GWT;
  * @since 7.0.0
  */
 public class Profiler {
+
+    private static RelativeTimeSupplier RELATIVE_TIME_SUPPLIER;
+
+    private static final String evtGroup = "VaadinProfiler";
+
+    private static ProfilerResultConsumer consumer;
+
     /**
      * Class to include using deferred binding to enable the profiling.
      *
@@ -49,6 +58,7 @@ public class Profiler {
      * @since 7.0.0
      */
     public static class EnabledProfiler extends Profiler {
+
         @Override
         protected boolean isImplEnabled() {
             return true;
@@ -207,8 +217,8 @@ public class Profiler {
             if (getName() == null) {
                 return "";
             }
-            String msg = prefix + " " + getName() + " in " + getTimeSpent()
-                    + " ms.";
+            String msg = prefix + " " + getName() + " in "
+                    + roundToSignificantFigures(getTimeSpent()) + " ms.";
             if (getCount() > 1) {
                 msg += " Invoked "
                         + getCount()
@@ -222,7 +232,8 @@ public class Profiler {
             }
             if (!children.isEmpty()) {
                 double ownTime = getOwnTime();
-                msg += " " + ownTime + " ms spent in own code";
+                msg += " " + roundToSignificantFigures(ownTime)
+                        + " ms spent in own code";
                 if (getCount() > 1) {
                     msg += " ("
                             + roundToSignificantFigures(ownTime / getCount())
@@ -259,10 +270,10 @@ public class Profiler {
 
                 totalNode.time += getOwnTime();
                 totalNode.count += getCount();
-                totalNode.minTime = Math.min(totalNode.minTime,
-                        getMinTimeSpent());
-                totalNode.maxTime = Math.max(totalNode.maxTime,
-                        getMaxTimeSpent());
+                totalNode.minTime = roundToSignificantFigures(Math.min(
+                        totalNode.minTime, getMinTimeSpent()));
+                totalNode.maxTime = roundToSignificantFigures(Math.max(
+                        totalNode.maxTime, getMaxTimeSpent()));
             }
             for (Node node : children.values()) {
                 node.sumUpTotals(totals);
@@ -285,8 +296,6 @@ public class Profiler {
         }
     }
 
-    private static final String evtGroup = "VaadinProfiler";
-
     private static final class GwtStatsEvent extends JavaScriptObject {
         protected GwtStatsEvent() {
             // JSO constructor
@@ -317,6 +326,16 @@ public class Profiler {
             return this.moduleName;
         }-*/;
 
+        private native double getRelativeMillis()
+        /*-{
+            return this.relativeMillis;
+        }-*/;
+
+        private native boolean isExtendedEvent()
+        /*-{
+            return 'relativeMillis' in this;
+        }-*/;
+
         public final String getEventName() {
             String group = getEvtGroup();
             if (evtGroup.equals(group)) {
@@ -327,8 +346,6 @@ public class Profiler {
         }
     }
 
-    private static ProfilerResultConsumer consumer;
-
     /**
      * Checks whether the profiling gathering is enabled.
      *
@@ -369,6 +386,15 @@ public class Profiler {
         }
     }
 
+    /**
+     * Returns time relative to the particular page load time. The value should
+     * not be used directly but rather difference between two values returned by
+     * this method should be used to compare measurements.
+     */
+    public static double getRelativeTimeMillis() {
+        return RELATIVE_TIME_SUPPLIER.getRelativeTime();
+    }
+
     private static native final void logGwtEvent(String name, String type)
     /*-{
         $wnd.__gwtStatsEvent({
@@ -377,7 +403,8 @@ public class Profiler {
             millis: (new Date).getTime(),
             sessionId: undefined,
             subSystem: name,
-            type: type
+            type: type,
+            relativeMillis: @com.vaadin.client.Profiler::getRelativeTimeMillis()()
         });
     }-*/;
 
@@ -412,6 +439,11 @@ public class Profiler {
      * @since 7.0.2
      */
     public static void initialize() {
+        if (hasHighPrecisionTime()) {
+            RELATIVE_TIME_SUPPLIER = new HighResolutionTimeSupplier();
+        } else {
+            RELATIVE_TIME_SUPPLIER = new DefaultRelativeTimeSupplier();
+        }
         if (isEnabled()) {
             ensureLogger();
         } else {
@@ -440,10 +472,12 @@ public class Profiler {
             return;
         }
 
+        Set<Node> extendedTimeNodes = new HashSet<Node>();
         for (int i = 0; i < gwtStatsEvents.length(); i++) {
             GwtStatsEvent gwtStatsEvent = gwtStatsEvents.get(i);
             String eventName = gwtStatsEvent.getEventName();
             String type = gwtStatsEvent.getType();
+            boolean isExtendedEvent = gwtStatsEvent.isExtendedEvent();
             boolean isBeginEvent = "begin".equals(type);
 
             Node stackTop = stack.getLast();
@@ -454,7 +488,11 @@ public class Profiler {
                     && eventName.equals(stack.get(stack.size() - 2).getName())
                     && !isBeginEvent) {
                 // back out of sub event
-                stackTop.leave(gwtStatsEvent.getMillis());
+                if (extendedTimeNodes.contains(stackTop) && isExtendedEvent) {
+                    stackTop.leave(gwtStatsEvent.getRelativeMillis());
+                } else {
+                    stackTop.leave(gwtStatsEvent.getMillis());
+                }
                 stack.removeLast();
                 stackTop = stack.getLast();
 
@@ -470,17 +508,29 @@ public class Profiler {
                     return;
                 }
                 Node previousStackTop = stack.removeLast();
-                previousStackTop.leave(gwtStatsEvent.getMillis());
+                if (extendedTimeNodes.contains(previousStackTop)) {
+                    previousStackTop.leave(gwtStatsEvent.getRelativeMillis());
+                } else {
+                    previousStackTop.leave(gwtStatsEvent.getMillis());
+                }
             } else {
+                double millis = isExtendedEvent ? gwtStatsEvent
+                        .getRelativeMillis() : gwtStatsEvent.getMillis();
                 if (!inEvent) {
-                    stackTop = stackTop.enterChild(eventName,
-                            gwtStatsEvent.getMillis());
+                    stackTop = stackTop.enterChild(eventName, millis);
                     stack.add(stackTop);
+                    if (isExtendedEvent) {
+                        extendedTimeNodes.add(stackTop);
+                    }
                 }
                 if (!isBeginEvent) {
                     // Create sub event
-                    stack.add(stackTop.enterChild(eventName + "." + type,
-                            gwtStatsEvent.getMillis()));
+                    Node subNode = stackTop.enterChild(eventName + "." + type,
+                            millis);
+                    if (isExtendedEvent) {
+                        extendedTimeNodes.add(subNode);
+                    }
+                    stack.add(subNode);
                 }
             }
         }
@@ -636,4 +686,32 @@ public class Profiler {
         return Logger.getLogger(Profiler.class.getName());
     }
 
+    private static native boolean hasHighPrecisionTime()
+    /*-{
+       return $wnd.performance && (typeof $wnd.performance.now == 'function');
+    }-*/;
+
+    private interface RelativeTimeSupplier {
+        double getRelativeTime();
+    }
+
+    private static class DefaultRelativeTimeSupplier implements
+            RelativeTimeSupplier {
+
+        @Override
+        public native double getRelativeTime()
+        /*-{
+            return (new Date).getTime();
+        }-*/;
+    }
+
+    private static class HighResolutionTimeSupplier implements
+            RelativeTimeSupplier {
+
+        @Override
+        public native double getRelativeTime()
+        /*-{
+             return $wnd.performance.now();
+        }-*/;
+    }
 }
diff --git a/client/src/com/vaadin/client/Util.java b/client/src/com/vaadin/client/Util.java
index 43963e14c2..635efad796 100644
--- a/client/src/com/vaadin/client/Util.java
+++ b/client/src/com/vaadin/client/Util.java
@@ -1176,6 +1176,14 @@ public class Util {
         return JSON.parse(jsonAsString);
     }-*/;
 
+    /**
+     * Round {@code num} up to {@code exp} decimal positions.
+     */
+    public static native double round(double num, int exp)
+    /*-{
+        return +(Math.round(num + "e+" + exp)  + "e-" + exp);
+    }-*/;
+
     private static Logger getLogger() {
         return Logger.getLogger(Util.class.getName());
     }
diff --git a/client/src/com/vaadin/client/communication/MessageHandler.java b/client/src/com/vaadin/client/communication/MessageHandler.java
index eadfec8c99..e86c94c8c6 100644
--- a/client/src/com/vaadin/client/communication/MessageHandler.java
+++ b/client/src/com/vaadin/client/communication/MessageHandler.java
@@ -1716,12 +1716,13 @@ public class MessageHandler {
         if (jsonText == null) {
             return null;
         }
-        final Date start = new Date();
+        final double start = Profiler.getRelativeTimeMillis();
         try {
             ValueMap json = parseJSONResponse(jsonText);
             getLogger().info(
                     "JSON parsing took "
-                            + (new Date().getTime() - start.getTime()) + "ms");
+                            + Util.round(Profiler.getRelativeTimeMillis()
+                                    - start, 3) + "ms");
             return json;
         } catch (final Exception e) {
             getLogger().severe("Unable to parse JSON: " + jsonText);
diff --git a/client/src/com/vaadin/client/communication/XhrConnection.java b/client/src/com/vaadin/client/communication/XhrConnection.java
index aefdafec87..1de6fb15c8 100644
--- a/client/src/com/vaadin/client/communication/XhrConnection.java
+++ b/client/src/com/vaadin/client/communication/XhrConnection.java
@@ -15,7 +15,6 @@
  */
 package com.vaadin.client.communication;
 
-import java.util.Date;
 import java.util.logging.Logger;
 
 import com.google.gwt.http.client.Request;
@@ -33,6 +32,8 @@ import com.vaadin.client.ApplicationConnection.RequestStartingEvent;
 import com.vaadin.client.ApplicationConnection.ResponseHandlingEndedEvent;
 import com.vaadin.client.ApplicationConnection.ResponseHandlingStartedEvent;
 import com.vaadin.client.BrowserInfo;
+import com.vaadin.client.Profiler;
+import com.vaadin.client.Util;
 import com.vaadin.client.ValueMap;
 import com.vaadin.shared.ApplicationConstants;
 import com.vaadin.shared.JsonConstants;
@@ -111,7 +112,7 @@ public class XhrConnection {
     public class XhrResponseHandler implements RequestCallback {
 
         private JsonObject payload;
-        private Date requestStartTime;
+        private double requestStartTime;
 
         public XhrResponseHandler() {
         }
@@ -147,8 +148,8 @@ public class XhrConnection {
 
             getLogger().info(
                     "Server visit took "
-                            + String.valueOf((new Date()).getTime()
-                                    - requestStartTime.getTime()) + "ms");
+                            + Util.round(Profiler.getRelativeTimeMillis()
+                                    - requestStartTime, 3) + "ms");
 
             String contentType = response.getHeader("Content-Type");
             if (contentType == null
@@ -175,12 +176,13 @@ public class XhrConnection {
         }
 
         /**
-         * Sets the time when the request was sent
+         * Sets the relative time (see {@link Profiler#getRelativeTimeMillis()})
+         * when the request was sent.
          * 
          * @param requestStartTime
-         *            the time when the request was sent
+         *            the relative time when the request was sent
          */
-        public void setRequestStartTime(Date requestStartTime) {
+        private void setRequestStartTime(double requestStartTime) {
             this.requestStartTime = requestStartTime;
 
         }
@@ -204,7 +206,7 @@ public class XhrConnection {
 
         XhrResponseHandler responseHandler = createResponseHandler();
         responseHandler.setPayload(payload);
-        responseHandler.setRequestStartTime(new Date());
+        responseHandler.setRequestStartTime(Profiler.getRelativeTimeMillis());
 
         rb.setCallback(responseHandler);
 
diff --git a/client/src/com/vaadin/client/debug/internal/ProfilerSection.java b/client/src/com/vaadin/client/debug/internal/ProfilerSection.java
index 7fb0284f8e..2851563884 100644
--- a/client/src/com/vaadin/client/debug/internal/ProfilerSection.java
+++ b/client/src/com/vaadin/client/debug/internal/ProfilerSection.java
@@ -30,6 +30,7 @@ import com.vaadin.client.Profiler;
 import com.vaadin.client.Profiler.Node;
 import com.vaadin.client.Profiler.ProfilerResultConsumer;
 import com.vaadin.client.SimpleTree;
+import com.vaadin.client.Util;
 import com.vaadin.client.ValueMap;
 
 /**
@@ -73,7 +74,8 @@ public class ProfilerSection implements Section {
                 }
 
                 SimpleTree root = new SimpleTree(eventCount
-                        + " profiler events using " + totalTime + " ms");
+                        + " profiler events using " + Util.round(totalTime, 3)
+                        + " ms");
                 root.add(drillDownTree);
                 root.add(offendersTree);
                 root.open(false);
diff --git a/uitest/src/com/vaadin/tests/CurrentTimeMillis.java b/uitest/src/com/vaadin/tests/CurrentTimeMillis.java
new file mode 100644
index 0000000000..0937c53864
--- /dev/null
+++ b/uitest/src/com/vaadin/tests/CurrentTimeMillis.java
@@ -0,0 +1,42 @@
+/*
+ * Copyright 2000-2014 Vaadin Ltd.
+ * 
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may not
+ * use this file except in compliance with the License. You may obtain a copy of
+ * the License at
+ * 
+ * http://www.apache.org/licenses/LICENSE-2.0
+ * 
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations under
+ * the License.
+ */
+package com.vaadin.tests;
+
+import com.vaadin.server.VaadinRequest;
+import com.vaadin.tests.components.AbstractTestUI;
+
+/**
+ * Test UI (empty) to check high resolution time availability in browser.
+ * 
+ * @author Vaadin Ltd
+ */
+public class CurrentTimeMillis extends AbstractTestUI {
+
+    @Override
+    protected void setup(VaadinRequest request) {
+        // no need to add anything
+    }
+
+    @Override
+    protected Integer getTicketNumber() {
+        return 14716;
+    }
+
+    @Override
+    protected String getTestDescription() {
+        return "Use high precision time is available instead of Date.getTime().";
+    }
+}
diff --git a/uitest/src/com/vaadin/tests/CurrentTimeMillisTest.java b/uitest/src/com/vaadin/tests/CurrentTimeMillisTest.java
new file mode 100644
index 0000000000..656b269c06
--- /dev/null
+++ b/uitest/src/com/vaadin/tests/CurrentTimeMillisTest.java
@@ -0,0 +1,93 @@
+/*
+ * Copyright 2000-2014 Vaadin Ltd.
+ * 
+ * Licensed under the Apache License, Version 2.0 (the "License"); you may not
+ * use this file except in compliance with the License. You may obtain a copy of
+ * the License at
+ * 
+ * http://www.apache.org/licenses/LICENSE-2.0
+ * 
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
+ * WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
+ * License for the specific language governing permissions and limitations under
+ * the License.
+ */
+package com.vaadin.tests;
+
+import java.util.List;
+
+import org.junit.Assert;
+import org.junit.Test;
+import org.openqa.selenium.By;
+import org.openqa.selenium.Keys;
+import org.openqa.selenium.WebElement;
+import org.openqa.selenium.interactions.Actions;
+
+import com.vaadin.testbench.parallel.BrowserUtil;
+import com.vaadin.tests.tb3.MultiBrowserTest;
+
+/**
+ * Test to check high resolution time availability in browser (depending on
+ * browser).
+ * 
+ * @author Vaadin Ltd
+ */
+public class CurrentTimeMillisTest extends MultiBrowserTest {
+
+    @Test
+    public void testJsonParsing() {
+        setDebug(true);
+        openTestURL();
+
+        boolean highResTimeSupported = !BrowserUtil
+                .isIE8(getDesiredCapabilities())
+                && !BrowserUtil.isIE(getDesiredCapabilities(), 9)
+                && !BrowserUtil.isPhantomJS(getDesiredCapabilities())
+                && !BrowserUtil.isSafari(getDesiredCapabilities());
+
+        String time = getJsonParsingTime();
+        Assert.assertNotNull("JSON parsing time is not found", time);
+        time = time.trim();
+        if (time.endsWith("ms")) {
+            time = time.substring(0, time.length() - 2);
+        }
+        if (highResTimeSupported) {
+            if (BrowserUtil.isChrome(getDesiredCapabilities())) {
+                // Chrome (version 33 at least) sometimes doesn't use high res
+                // time if number of ms is less then 1
+                Assert.assertTrue("High resolution time is not used in "
+                        + "JSON parsing mesurement. Time=" + time,
+                        time.equals("0") || time.indexOf('.') > 0);
+            } else {
+                Assert.assertTrue("High resolution time is not used in "
+                        + "JSON parsing mesurement. Time=" + time,
+                        time.indexOf('.') > 0);
+            }
+        } else {
+            Assert.assertFalse("Unexpected dot is detected in browser "
+                    + "that doesn't support high resolution time and "
+                    + "should report time as integer number. Time=" + time,
+                    time.indexOf('.') > 0);
+        }
+    }
+
+    private String getJsonParsingTime() {
+        Actions actions = new Actions(getDriver());
+        actions.sendKeys(Keys.TAB);
+        actions.sendKeys(Keys.SPACE).perform();
+        findElement(By.className("v-debugwindow-tab")).click();
+
+        List<WebElement> messages = findElements(By
+                .className("v-debugwindow-message"));
+        for (WebElement message : messages) {
+            if (message.getAttribute("innerHTML").startsWith("JSON parsing")) {
+                String text = message.getAttribute("innerHTML");
+                int index = text.lastIndexOf(' ');
+                return text.substring(index);
+            }
+        }
+        return null;
+    }
+
+}