1260587 - performance.now() is 6x slower than native Win32 QueryPerformanceCounter()

Status: NEW

(Core :: DOM: Core & HTML, defect, P3)

Description

[Jukka Jylänki]

Attachment: geckoprofiler_performance_now.png

(Please don't hate me for filing this, marking this minor so treat it with that little importance)

As part of micro-optimizing Emscripten's high performance timer functions at https://github.com/kripken/emscripten/pull/4209, I noticed that performance.now() is 9x slower in asm.js JavaScript than it is compared to native Win32 QueryPerformanceCounter().

The rationale is that some native codebases have built-in profiling build modes, which inject tons of high performance tick() calls in function prologs and epilogs (either by manual placement or via some build tool), so these profiling modes generate outputs that can have hundreds of thousands of calls to performance.now() when compiled with Emscripten. Therefore there is some value in optimizing performance.now() to be as fast as possible in asm.js codebases.

emscripten_get_now() does generally show up in gecko profiler benchmark of these kinds of pages, although not at all as the highest spender (which is typically WebGL), but still up there on the list. So we were doing some diligence in measuring its cost.

A synthetic testcase is at https://dl.dropboxusercontent.com/u/40949268/dump/performance_now/performance_now.html

Looking at the gecko profile of that page, see https://cleopatra.io/#report=c2e35e554088d73a0b39f31c4de1835ae7ac6c52&filter=%5B%7B%22type%22%3A%22RangeSampleFilter%22,%22start%22%3A18332,%22end%22%3A33629%7D,%7B%22type%22%3A%22RangeSampleFilter%22,%22start%22%3A24763,%22end%22%3A31535%7D,%7B%22type%22%3A%22FocusedCallstackPrefixSampleFilter%22,%22name%22%3A%22_emscripten_get_now()%20%40%20performance_now.js%3A1888%22,%22focusedCallstack%22%3A%5B0,2336,2340,175,4,2341,2342,4,2343,2344,2345,2346,2347,2348,2349%5D,%22appliesToJS%22%3Afalse%7D%5D&selection=2349,2350,2351,2352,2307,2355,2358

or the attached screenshot.

It looks like the 0x4a7xx lines in ntdll.pdb correspond to the calls of the native QueryPerformanceCounter(). These account for 6.8%+1.1%+0.9%+0.8%+0.4%+0.3% = 10.3% of time spent in QueryPerformanceCounter(), giving 89.7% of the total time in performance.now() be about the overhead to wrap it.

There is a chain of multiple function calls mozilla::dom::PerformanceBinding::now -> nsPerformance::now -> mozilla::TimeStamp::Now -> mozilla::TimeStamp::Now(bool), followed by nsDOMNavigationTiming::TimeStampToDOMHighRes -> mozilla::TimeStamp::operator- -> mozilla::TimeStampValue::operator- needed to provide the time stamp value, which is nicely organized, but might be a bit excessive amount of nested calls to fast track to returning a timestamp.

Benchmarking against Date.now() surprisingly showed that Date.now() was 10%-15% faster to call than performance.now(), although obviously not as precise as performance.now(), so not very useful.

Noticed that Vlad had reported https://bugzilla.mozilla.org/show_bug.cgi?id=824495 a long time ago, which is related.

Just wanted to write this down, since the findings suggest there might be some slack here. Perhaps it might be interesting for someone on a rainy day to optimize the code path to return timestamps quicker. There was also some discussion about adding performance.now() to the list of asm.js built-ins, which would likely help performance a bit as well.

Comment 1

[Jukka Jylänki]

In microbenchmark numbers, time taken to run 600k performance.now()s:
   - Firefox Nightly 48.0a1 2016-03-28: 30.3 msecs
   - Chrome 49.0.2623.87: 126.5 msecs
   - Edge 25.10586.0.0: 127.9 msecs

so we are still fastest by far.

Comment 2

[Jan de Mooij [:jandem]]

performance.now is implemented outside SpiderMonkey.