Bug 106393 – Parser/html-parser.html spends 3% of total time in WTF::currentTime() on Android

• Status: RESOLVED
• Resolution: INVALID
• Component: New Bugs

[Eric Seidel (no email)]

Created attachment 181785 [details]
gzip'd copy of the profile (was too large to attach plain)

Parser/html-parser.html spends 3% of total time in WTF::currentTime() on Android

There are 2 problems here.

1.  WTF::currentTime() is probably not as optimized as it should be on Android (we had this problem in the past for Mac OS X, many many years ago).

2.  Document::didAccessStyleResolver() should be using a timer and a bool instead of polling WTF::currentTime on every access! :)  It could set a "don't reschedule until" timer, which fires and schedules a throw-away.

void Document::didAccessStyleResolver()
{
    static const int timeBeforeThrowingAwayStyleResolverAfterLastUseInSeconds = 60;
    static const int holdOffTimeBeforeReschedulingTimerInSeconds = 5;

    double currentTime = WTF::currentTime();

    if (currentTime > m_lastStyleResolverAccessTime + holdOffTimeBeforeReschedulingTimerInSeconds) {
        m_styleResolverThrowawayTimer.startOneShot(timeBeforeThrowingAwayStyleResolverAfterLastUseInSeconds);
        m_lastStyleResolverAccessTime = currentTime;
    }
}

I guess I'll file separate bugs and relate those back to these?

[Eric Seidel (no email)]

I'll use this bug for the WTF::currentTime is slow on Chromium-Android bug, and break off a separate bug for the Document::didAccessStyleResolver issue.

It appears WTF::currentTime() ends up as a virtual call on Chromium?!?

http://code.google.com/searchframe#OAMlx_jo-ck/src/third_party/WebKit/Source/Platform/chromium/public/Platform.h&exact_package=chromium&q=currentTime&type=cs&l=329

That said, that sample shows us spending all our time in the kernel.  Suggesting that getTimeOfDay is just slow on Android.

http://code.google.com/searchframe#OAMlx_jo-ck/src/base/time_posix.cc&exact_package=chromium&q=Time::Now&type=cs&l=109

[Adam Barth]

> It appears WTF::currentTime() ends up as a virtual call on Chromium?!?

That's correct.  I believe it's related to the sandbox, but I've never investigated in detail.  It's likely something we designed for the Windows sandbox.  On other platforms, we might be able to do something smarter since the sandbox works differently on different platforms.

[Eric Seidel (no email)]

As I stare at that sample more, I'm wondering if all syscalls are getting lumped together by my lack of kernel symbols.  (Which would mean this is 3% of total time for syscalls, not just getTimeOfDay.)  Investigating.

[Eric Seidel (no email)]

Created attachment 181793 [details]
gzip'd copy of a profile from my fast linux desktop

Interestingly, the profile on linux also shows ~3% of time in the kernel, but that's all from syscalls made from tcmalloc.  The currentTime() bits account for 0.41%:

     0.41%  DumpRenderTree  [vdso]                       [.] 0x7fff58fff6d0  
            |
            --- 0x7fff58fff700
                webkit_glue::WebKitPlatformSupportImpl::currentTime()

It's still possible that my lack of kernel symbols on android is causing confusion here.

[Adam Barth]

I'd believe that 3% of time is spent dealing with malloc.

[Eric Seidel (no email)]

Now that I can see kernel symbols, I also think this is a red herring.  The kernel is no longer at the top of my samples:

     2.47%  SignalSender  libDumpRenderTree.so  [.] WebCore::HTMLTokenizer::nextToken(WebCore::SegmentedString&, WebCore::HTMLToken&)
     2.00%  SignalSender  libc.so               [.] pthread_mutex_lock_impl
     1.58%  SignalSender  libDumpRenderTree.so  [.] WebCore::StylePropertySet::PropertyReference::propertyMetadata() const
     1.29%  SignalSender  libc.so               [.] dlfree
     1.07%  SignalSender  libDumpRenderTree.so  [.] WebCore::SegmentedString::advanceAndUpdateLineNumber()
     0.98%  SignalSender  libc.so               [.] try_realloc_chunk.constprop.12
     0.93%  SignalSender  libDumpRenderTree.so  [.] WebCore::StyleResolver::collectMatchingRulesForList(WTF::Vector<WebCore::RuleData, 0u> const*, int&, int&, WebCore::StyleResolver::MatchOptions const&)
     0.87%  SignalSender  libDumpRenderTree.so  [.] v8::internal::ElementsAccessorBase<v8::internal::ExternalUnsignedShortElementsAccessor, v8::internal::ElementsKindTraits<(v8::internal::ElementsKind)11> >::CopyElements(v8::internal::JSObject*, unsigned int, v8::internal::ElementsKind, v8::internal::FixedArrayBase*, unsigned int, int, v8::internal::FixedArrayBase*)
     0.83%  SignalSender  libc.so               [.] pthread_mutexattr_settype
     0.82%  SignalSender  libDumpRenderTree.so  [.] bool WebCore::SelectorFilter::fastRejectSelector<4u>(unsigned int const*) const


I separately tested Date.now() on my desktop vs. Nexus 10, and found that I could get 22,000,000 calls per second on my desktop, but only 50,000 on my Nexus 10. :)