JS parsing and compiling takes too long on https://partnerportal.myntra.com/ |
||||||||||||||||||||||||||||
Issue descriptionThis site is not ideal, but apparently it was popular in India for at least one day. Time to first Contentul Paint takes 6 to 10 seconds with everything cached and network being very fast through ADB. Time depends on Android device I tested with. For example, there is a "HTMLScriptRunner ExecuteScript" task that takes >5 seconds, of which: V8.CompileCode: 3 seconds V8.ParseLazy: 1.2 seconds V8.CompileFullCode: 1 second MajorGC: 143ms V.Execute: 10ms (ta daa!)
,
Jun 15 2016
+rmcilroy, oth. Could this be a good test case for ignition?
,
Jun 15 2016
Could we take a look with the runtime callstats?
,
Jun 15 2016
,
Jun 15 2016
hablich: what are callstats? is it possible to enable them via tracing? do you want me to grab them or you want to do it yourself?
,
Jun 15 2016
FWIW, I'm also starting to see this a lot in WebPageTest where sites are CPU-constrained and the vast majority of that time is from JS (combination of parse and evaluate). It's becoming a common-enough problem that we accepted a talk for Velocity NY in the fall on it.
,
Jun 15 2016
Looks like this site is using React?
,
Jun 15 2016
I do not know reliable signs of React at all, but builtwith.com does _not_ report React for it, while it does sometimes find React on other websites.
,
Jun 15 2016
Inspecting their primary JS file in inspector reveals a lot of traces of React (the JS is unminified, making it particularly easy to peruse).
,
Jun 16 2016
Looking the runtime-stats on desktop M53 I don't see anything unusal on this page.
The page is heavily Parse+Compile bound (the first four entries below).
Pure JS_Execution is roughly 5% on desktop, which makes me believe that we must hit a pathological case on android that makes this so slow.
Runtime Function/C++ Builtin Time Count
========================================================================================
ParseLazy 228.44ms 30.51% 2258 0.99%
Parse 95.67ms 12.78% 38 0.02%
CompileLazy 67.86ms 9.06% 2353 1.03%
CompileFullCode 61.81ms 8.25% 2477 1.08%
JS_Execution 37.51ms 5.01% 3865 1.69%
FunctionCallback 24.05ms 3.21% 4899 2.14%
StoreIC_StoreTransition 21.21ms 2.83% 2733 1.20%
Map_TransitionToDataProperty 21.11ms 2.82% 25739 11.27%
GC 18.05ms 2.41% 121 0.05%
LoadIC_LoadFieldStub 10.21ms 1.36% 7926 3.47%
CallSiteGetLineNumberRT 10.01ms 1.34% 669 0.29%
PrototypeMap_TransitionToDataProperty 9.47ms 1.26% 4198 1.84%
LoadIC_Miss 8.66ms 1.16% 9970 4.36%
CreateObjectLiteral 8.55ms 1.14% 4310 1.89%
StoreIC_Miss 8.22ms 1.10% 9565 4.19%
API_ScriptCompiler_CompileUnbound 7.77ms 1.04% 32 0.01%
Compile 6.50ms 0.87% 39 0.02%
CompileOptimized_Concurrent 5.95ms 0.79% 47 0.02%
LoadIC_LoadConstantStub 5.92ms 0.79% 1927 0.84%
AccessorNameGetterCallback 5.23ms 0.70% 6253 2.74%
BinaryOpIC_Miss 5.04ms 0.67% 795 0.35%
API_ScriptCompiler_Compile 4.07ms 0.54% 1 0.00%
KeyedStoreIC_Miss 3.57ms 0.48% 6141 2.69%
API_Context_New 3.56ms 0.48% 4 0.00%
StoreIC_StoreFieldStub 3.38ms 0.45% 465 0.20%
StackGuard 3.32ms 0.44% 38 0.02%
KeyedStoreIC_StoreFastElementStub 2.58ms 0.34% 1083 0.47%
ToBooleanIC_Miss 2.53ms 0.34% 2002 0.88%
IC_HandlerCacheHit 2.44ms 0.33% 2506 1.10%
Map_SetPrototype 2.42ms 0.32% 21604 9.46%
AllocateInTargetSpace 2.05ms 0.27% 27 0.01%
SetProperty 1.93ms 0.26% 3396 1.49%
LoadIC_FunctionPrototypeStub 1.82ms 0.24% 4265 1.87%
API_Object_Get 1.76ms 0.23% 15390 6.74%
KeyedLoadIC_Miss 1.73ms 0.23% 2874 1.26%
RegExpExec 1.72ms 0.23% 111 0.05%
API_FunctionTemplate_GetFunction 1.70ms 0.23% 349 0.15%
API_String_NewFromUtf8 1.58ms 0.21% 10907 4.78%
LoadIC_LoadConstant 1.54ms 0.21% 249 0.11%
CreateArrayLiteral 1.49ms 0.20% 788 0.34%
CompareIC_Miss 1.47ms 0.20% 857 0.38%
CreateRegExpLiteral 1.30ms 0.17% 274 0.12%
API_Function_Call 1.23ms 0.16% 3252 1.42%
KeyedLoadIC_LoadFastElementStub 1.15ms 0.15% 375 0.16%
ForInEnumerate 1.08ms 0.14% 606 0.27%
HandleApiCall 1.05ms 0.14% 4323 1.89%
KeyedStoreIC_Polymorphic 1.04ms 0.14% 10 0.00%
NewObject 1.02ms 0.14% 99 0.04%
Map_TransitionToAccessorProperty 0.93ms 0.12% 1124 0.49%
... ... ...
----------------------------------------------------------------------------------------
Total 748.83ms 100.00% 228412 100.00%
,
Jun 17 2016
@cbruni, is it easy to collect the runtime stats for just a small portion of the load? Here's the module registration block on m.reddit.com
,
Jun 20 2016
you can do it if you have access to the sources: %GetAndResetRuntimeCallStats() with --js-flags=--allow-natives-syntax should esseentially do that. Otherwise we should give it a shot with the new v8-integrated traces :)
,
Jul 8 2016
I am seeing long parse problems even on Android from other traces people post, including on google.com, so I am wondering whether we regressed here. Can we bump priority for this please?
,
Jul 8 2016
Improving startup time, explicitly targeting the parse/compile time is on v8's radar. We did regress in certain cases due to the added complexity of ES6 which introduced several ambiguities to the grammar making parsing more challenging.
,
Sep 8 2016
paulirish@ could you try to rerun the traces using the new v8.runtime_stats category enabled? This should give us deeper insights on where we spend time.
,
Sep 9 2016
Yup. I've tried on a few sites recently and generally see Parse + Compile as 60-70% of the execute block for the bundles. Attached screenshots & traces for m.reddit.com, airbnb.com, and partnerportal.myntra.com
,
Sep 9 2016
Thanks. What stands out in these 3 pages is the high percentage of lazy parsing. It would be interesting to see how --js-flags="--nolazy" would change the performance characteristics on these pages.
,
Sep 10 2016
I'd also be interested to know how often we fully parse but don't compile, because the function isn't currently supported by our much faster preparser... I guess we don't have that info as a separate signal though. I wonder if that may be causing much of our problems.
,
Sep 12 2016
We're actually meeting with Reddit this week--I'll make sure that we bring this up.
,
Sep 30 2016
Seth: did anything come up from the meeting?
,
Oct 3 2016
We ran github.com/samccone/coverage-ext to get a better sense of what Reddit can trim out of the bundle itself. The V8 team also has a number of action items we're tracking as part of Q4 work to improve the parser.
,
Nov 28 2016
I did an updated version of the RCS on the live page.
Note that we now also include background parsing which makes the total time look much bigger:
Runtime Function/C++ Builtin Time Count
========================================================================================
ParseFunctionLiteral 311.61ms 23.90% 16148 6.94%
GC 178.73ms 13.71% 337 0.14%
PreParseWithVariableResolution 120.71ms 9.26% 9223 3.96%
CompileFullCode 87.97ms 6.75% 2739 1.18%
CompileCodeLazy 75.49ms 5.79% 2782 1.20%
JS_Execution 59.91ms 4.60% 3327 1.43%
FunctionCallback 45.38ms 3.48% 4440 1.91%
ParseBackgroundFunctionLiteral 37.01ms 2.84% 864 0.37%
PreParseNoVariableResolution 26.78ms 2.05% 1932 0.83%
CreateObjectLiteral 25.91ms 1.99% 4452 1.91%
StoreIC_Premonomorphic 24.00ms 1.84% 12564 5.40%
AccessorNameGetterCallback 20.56ms 1.58% 3489 1.50%
PreParseBackgroundWithVariableResolution 16.95ms 1.30% 1079 0.46%
API_Object_Get 15.93ms 1.22% 14092 6.05%
ParseProgram 15.10ms 1.16% 86 0.04%
KeyedStoreIC_Miss 13.63ms 1.05% 3863 1.66%
LoadIC_Premonomorphic 13.11ms 1.01% 12225 5.25%
BinaryOpIC_Miss 10.80ms 0.83% 832 0.36%
StoreIC_StoreTransitionDH 10.07ms 0.77% 2843 1.22%
CompileCode 10.02ms 0.77% 449 0.19%
Map_SetPrototype 8.83ms 0.68% 25254 10.85%
ParseFunction 8.70ms 0.67% 2368 1.02%
Map_TransitionToDataProperty 8.51ms 0.65% 25028 10.75%
API_FunctionTemplate_GetFunction 7.48ms 0.57% 625 0.27%
ToBooleanIC_Miss 6.96ms 0.53% 2120 0.91%
Compile 6.87ms 0.53% 87 0.04%
API_Context_New 6.75ms 0.52% 5 0.00%
API_ScriptCompiler_Compile 5.73ms 0.44% 1 0.00%
SetProperty 5.67ms 0.43% 4046 1.74%
API_ScriptCompiler_CompileUnbound 5.67ms 0.43% 98 0.04%
CompileLazy 5.22ms 0.40% 2566 1.10%
CreateArrayLiteral 4.84ms 0.37% 1389 0.60%
RecompileSynchronous 4.74ms 0.36% 47 0.02%
API_String_NewFromUtf8 4.13ms 0.32% 5831 2.50%
LoadIC_LoadConstantFromPrototypeDH 4.08ms 0.31% 2428 1.04%
Map_TransitionToAccessorProperty 3.49ms 0.27% 1581 0.68%
HandleApiCall 3.36ms 0.26% 3789 1.63%
LoadIC_LoadFieldDH 3.06ms 0.23% 2476 1.06%
CompileIgnition 2.88ms 0.22% 69 0.03%
API_JSON_Parse 2.85ms 0.22% 9 0.00%
KeyedStoreIC_StoreFastElementStub 2.56ms 0.20% 1165 0.50%
NewClosure_Tenured 2.49ms 0.19% 3571 1.53%
API_Function_Call 2.41ms 0.18% 2906 1.25%
KeyedLoadIC_Miss 2.35ms 0.18% 2714 1.17%
RegExpExec 2.26ms 0.17% 110 0.05%
LoadIC_LoadInterceptor 2.21ms 0.17% 174 0.07%
API_FunctionTemplate_New 2.18ms 0.17% 2274 0.98%
API_Object_SetPrivate 2.08ms 0.16% 1139 0.49%
....
----------------------------------------------------------------------------------------
Total 1303.69ms 100.00% 232793 100.00%
,
Jan 12 2017
@cbruni It looks like your last RCS statistics include 'CompileLazy' and 'CompileCodeLazy' functions. Would I be correct in concluding these numbers were for a trace without --js-flags="--nolazy"? Fwiw, the most recent perf studies we've completed on a corpus of React (and Webpack) based apps reached similar conclusions regarding a majority of time spent in parse/compile. It would be interesting to investigate whether lazy parsing is a prevalent contributor via RCS in some of those URL sets too.
,
Jan 12 2017
Not necessarily, CompileLazy is a deceptive name that just means CompileFunction, which I've renamed recently. We should again not fall in the trap thinking that lazy parsing isn't useful. If --nolazy shows any benefits at all, it is because of the reparsing that we're working to eliminate. Lazy parsing and compilation actually speed things up significantly and reduce memory usage. The latter part is why even concurrent compilation of bytecode needs to be done with care. Lazy, if all parts work properly, will limit parsing/compilation to what's needed exactly. That speeds up overall startup and gets the code running earlier; also on single core devices. And it doesn't preclude using heuristics if we have the resources to compile more possibly concurrently (such as ross' iife work).
,
Feb 8 2017
It seems like the website changed it's code signature significantly (or M55+ improved) that a comparison is hard.
Parser work has continued and yielded significant improvements on several sites.
Not sure this is still actionable.
M57:
Runtime Function/C++ Builtin Time Count
========================================================================================
ParseFunctionLiteral 176.35ms 30.76% 13808 6.21%
PreParseNoVariableResolution 85.28ms 14.88% 10467 4.71%
CompileFullCode 42.73ms 7.45% 2572 1.16%
CompileCodeLazy 40.94ms 7.14% 2612 1.17%
GC 37.97ms 6.62% 169 0.08%
JS_Execution 21.84ms 3.81% 3292 1.48%
FunctionCallback 21.60ms 3.77% 4554 2.05%
PreParseWithVariableResolution 15.71ms 2.74% 778 0.35%
CreateObjectLiteral 11.61ms 2.03% 4410 1.98%
StoreIC_Premonomorphic 9.95ms 1.74% 11976 5.38%
CompileCode 7.79ms 1.36% 433 0.19%
ParseProgram 6.60ms 1.15% 87 0.04%
KeyedStoreIC_Miss 6.58ms 1.15% 3749 1.69%
LoadIC_Premonomorphic 4.94ms 0.86% 12221 5.49%
AccessorNameGetterCallback 4.87ms 0.85% 3006 1.35%
StoreIC_StoreTransitionDH 4.65ms 0.81% 2700 1.21%
ParseFunction 3.99ms 0.70% 2209 0.99%
BinaryOpIC_Miss 3.69ms 0.64% 754 0.34%
API_ScriptCompiler_CompileUnbound 3.55ms 0.62% 101 0.05%
Compile 3.42ms 0.60% 87 0.04%
API_Context_New 3.39ms 0.59% 5 0.00%
RecompileSynchronous 2.85ms 0.50% 43 0.02%
API_FunctionTemplate_GetFunction 2.61ms 0.46% 629 0.28%
SetProperty 2.48ms 0.43% 3966 1.78%
CompileLazy 2.40ms 0.42% 2440 1.10%
CreateArrayLiteral 2.33ms 0.41% 1346 0.61%
LoadIC_LoadConstantFromPrototypeDH 2.15ms 0.38% 2406 1.08%
KeyedStoreIC_StoreFastElementStub 2.03ms 0.35% 1129 0.51%
ToBooleanIC_Miss 1.86ms 0.32% 2000 0.90%
LoadIC_LoadFieldDH 1.51ms 0.26% 2453 1.10%
LoadIC_LoadInterceptor 1.42ms 0.25% 171 0.08%
CompileIgnition 1.41ms 0.25% 62 0.03%
RegExpExec 1.35ms 0.24% 118 0.05%
API_Object_Get 1.33ms 0.23% 14373 6.46%
LoadIC_LoadNonexistentDH 1.27ms 0.22% 969 0.44%
----------------------------------------------------------------------------------------
Total 573.25ms 100.00% 222457 100.00%
,
Aug 2 2017
Closing as wontfix because comment# 26 mentions this may not be actionable and no action has been taken in a while. |
||||||||||||||||||||||||||||
►
Sign in to add a comment |
||||||||||||||||||||||||||||
Comment 1 by pasko@chromium.org
, Jun 15 2016