RE: Issues in user-timing draft

Kiran,

I wasn't able to reproduce the problem using the code sample below. Can you please provide a test case that shows this issue?

That being said, there do seem to be simple workarounds for asynchronous functions. For example, one can just make a performance.measure('name') call without a start mark and measure the time from navigationStart until the asynchronous call has been made. If you desire to see the deltas, you can always subtract the measure's duration from the mark's duration.

Unless there are no good workarounds, I would argue we shouldn't change the existing behavior. I would still love to see the test case to understand this problem better.

Thanks,
Jatinder

From: Kiran Lonikar [mailto:klonikar@yahoo-inc.com]
Sent: Monday, June 3, 2013 10:52 PM
To: public-web-perf@w3.org
Cc: Jatinder Mann; zhihengw@google.com; Puneet Sangal
Subject: Issues in user-timing draft

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