W3C home > Mailing lists > Public > public-web-perf@w3.org > June 2013

Issues in user-timing draft

From: Kiran Lonikar <klonikar@yahoo-inc.com>
Date: Tue, 4 Jun 2013 05:51:59 +0000
To: "public-web-perf@w3.org" <public-web-perf@w3.org>
CC: "jmann@microsoft.com" <jmann@microsoft.com>, "zhihengw@google.com" <zhihengw@google.com>, Puneet Sangal <pmsangal@yahoo-inc.com>
Message-ID: <265540D260BE19479CF0658A541693FD1B7FE615@KR3-EX10-MB02.y.corp.yahoo.com>
Hi,

I wanted to bring to everyone's notice an important finding regarding the user-timing<http://www.w3.org/TR/user-timing/> w3c draft. When performing mark/measure across async functions, you get incorrect results. As everyone is aware, async functions/closures is very common in javascript for event handling, ajax requests etc. and thus this issue will affect almost the entire users of these APIs. I also have a proposed solution and I have implemented it in our in-house instrumentation API and it works. But it needs changes in the user-timing draft, which need to be ratified.

It may be noted that the same issue exists in the google chrome implementation of window.performance.webkitMark and window.performance.webkitMeasure.

Below is the explanation with an example:

function foo(someArg) {
    mark("startM1"); // associate current time with startM1
    someLongRunningFunction(function callback() {
        mark("endM1"); // associate current time with endM1
        measure("m1", "startM1", "endM1"); // associate m1.duration with diff of endM1 and startM1 and set m1.startTime = startM1.startTime
    });
}

foo("1"); // should set startM1.startTime == t1, endM1.startTime == t2, and m1.duration = t2 - t1
// some code
foo("2"); // should set startM1.startTime == t3, endM1.startTime == t4, and m1.duration = t4 - t3

what happens in reality is different: you get two instances of meaure m1 for each invocation of foo. But the duration for first instance of m1 is t2-t3 and not t2-t1. This is because the callback is not invoked immediately, and in the meanwhile the foo("2") runs and effectively resets the startM1.startTime to t3. This will always happen in async callback invocations.

My proposed solution: Make the mark function return an object and use that when calling measure rather than passing the start and end mark names. However, this involves changing the simple callback to a closure which is almost always the case anyway when doing event handling in javascript. Hence it should not be a major issue with most javascript developers.

function foo(someArg) {
    var startM1 = mark("startM1"); // associate current time with startM1
    someLongRunningFunction(function(m) {
        var startMark = m;
        return function callback() {
            var endM1 = mark("endM1"); // associate current time with endM1
            measure("m1", startMark, endM1); // associate m1.duration with diff of endM1 and startM1 and set m1.startTime = startM1.startTime
        };
    }(startM1));
}

foo("1"); // Now it should set startM1.startTime == t1, endM1.startTime == t2, and m1.duration = t2 - t1
// some code
foo("2"); // Now it should set startM1.startTime == t3, endM1.startTime == t4, and m1.duration = t4 - t3

Let me know if this is indeed an issue and needs changes in the draft.

-Kiran
Received on Tuesday, 4 June 2013 07:17:38 UTC

This archive was generated by hypermail 2.3.1 : Tuesday, 6 January 2015 21:04:35 UTC