BrowserOptions.CreateParser() is a very expensive operation

[Ned Nguyen]

Hi all,

Today when I am running measurement_smoke_test on local, I notice that the test takes very long time to run although I expect it not to touch actual browser. When I do a dump debugging with time.time(), it turns out that the options.CreateParser() takes about 15s, and I make that call inside a for loop!  (Fix here: https://codereview.chromium.org/928573003/)

Looking closely at the implementation of BrowserOptions.CreateParser(), the reason it tooks very long time to run is because it tries using adb to communicate with the devices in order to list out all available browser.

I profile the  BrowserOptions.CreateParser() and here is the top results (sorted by cummulative time):

         121346 function calls (118797 primitive calls) in 19.613 seconds
   Ordered by: cumulative time
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   19.615   19.615 run.py:1(<module>)
        1    0.000    0.000   19.343   19.343 run.py:9(CreateParser)
        1    0.000    0.000   19.343   19.343 browser_options.py:61(CreateParser)
        1    0.000    0.000   19.338   19.338 profiler_finder.py:26(GetAllAvailableProfilers)
        5    0.000    0.000   19.238    3.848 android_browser_finder.py:146(CanFindAvailableBrowsers)
        5    0.000    0.000   19.238    3.848 android_device.py:99(CanDiscoverDevices)
        5    0.000    0.000   19.177    3.835 subprocess.py:768(communicate)
        5    0.000    0.000   19.177    3.835 subprocess.py:1392(_communicate)
        5    0.000    0.000   19.176    3.835 subprocess.py:1425(_communicate_with_poll)
       15   19.175    1.278   19.175    1.278 {built-in method poll}

(see https://codereview.chromium.org/928643002)

Here are all the places in telemetry codebase that we call BrowserOptions.CreateParser():

https://code.google.com/p/chromium/codesearch#search/&q=CreateParser%20f:(telemetry%7Cperf)&type=cs&sq=package:chromium

I suspect there is some implementation bug here since the android_device.CanDiscoverDevices() is called 5 times. 

[zh...@google.com]

https://code.google.com/p/chromium/codesearch#chromium/src/tools/telemetry/telemetry/core/browser_options.py&l=112

This will call to profiler_finder and will check if the profiler is supporting browser_type='any'. Then each profiler will check if they can find available browsers. And that involves checking if there are Android devices.

This problem should be there for a long time, right? Does anyone see this before? I am not familiar about the profiler logic and do not have enough credibility to comment on how to change it yet.

Here are the call stacks for the 5 calls to CanDiscoverDevices():

CanDiscoverDevices=====================
File "tools/telemetry/run.py", line 14, in <module>
CreateParser()
File "tools/telemetry/run.py", line 10, in CreateParser
options.CreateParser()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/browser_options.py", line 112, in CreateParser
profiler_choices = profiler_finder.GetAllAvailableProfilers()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/profiler/profiler_finder.py", line 28, in GetAllAvailableProfilers
if p.is_supported(browser_type='any')])
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/profiler/android_traceview_profiler.py", line 51, in is_supported
return android_browser_finder.CanFindAvailableBrowsers()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/backends/chrome/android_browser_finder.py", line 147, in CanFindAvailableBrowsers
return android_device.CanDiscoverDevices()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/android_device.py", line 102, in CanDiscoverDevices
traceback.print_stack()
CanDiscoverDevices=====================
File "tools/telemetry/run.py", line 14, in <module>
CreateParser()
File "tools/telemetry/run.py", line 10, in CreateParser
options.CreateParser()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/browser_options.py", line 112, in CreateParser
profiler_choices = profiler_finder.GetAllAvailableProfilers()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/profiler/profiler_finder.py", line 28, in GetAllAvailableProfilers
if p.is_supported(browser_type='any')])
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/profiler/android_screen_recorder_profiler.py", line 35, in is_supported
return android_browser_finder.CanFindAvailableBrowsers()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/backends/chrome/android_browser_finder.py", line 147, in CanFindAvailableBrowsers
return android_device.CanDiscoverDevices()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/android_device.py", line 102, in CanDiscoverDevices
traceback.print_stack()
CanDiscoverDevices=====================
File "tools/telemetry/run.py", line 14, in <module>
CreateParser()
File "tools/telemetry/run.py", line 10, in CreateParser
options.CreateParser()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/browser_options.py", line 112, in CreateParser
profiler_choices = profiler_finder.GetAllAvailableProfilers()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/profiler/profiler_finder.py", line 28, in GetAllAvailableProfilers
if p.is_supported(browser_type='any')])
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/profiler/oomkiller_profiler.py", line 60, in is_supported
return android_browser_finder.CanFindAvailableBrowsers()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/backends/chrome/android_browser_finder.py", line 147, in CanFindAvailableBrowsers
return android_device.CanDiscoverDevices()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/android_device.py", line 102, in CanDiscoverDevices
traceback.print_stack()
CanDiscoverDevices=====================
File "tools/telemetry/run.py", line 14, in <module>
CreateParser()
File "tools/telemetry/run.py", line 10, in CreateParser
options.CreateParser()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/browser_options.py", line 112, in CreateParser
profiler_choices = profiler_finder.GetAllAvailableProfilers()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/profiler/profiler_finder.py", line 28, in GetAllAvailableProfilers
if p.is_supported(browser_type='any')])
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/profiler/android_systrace_profiler.py", line 55, in is_supported
return android_browser_finder.CanFindAvailableBrowsers()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/backends/chrome/android_browser_finder.py", line 147, in CanFindAvailableBrowsers
return android_device.CanDiscoverDevices()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/android_device.py", line 102, in CanDiscoverDevices
traceback.print_stack()
CanDiscoverDevices=====================
File "tools/telemetry/run.py", line 14, in <module>
CreateParser()
File "tools/telemetry/run.py", line 10, in CreateParser
options.CreateParser()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/browser_options.py", line 112, in CreateParser
profiler_choices = profiler_finder.GetAllAvailableProfilers()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/profiler/profiler_finder.py", line 28, in GetAllAvailableProfilers
if p.is_supported(browser_type='any')])
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/profiler/java_heap_profiler.py", line 45, in is_supported
return android_browser_finder.CanFindAvailableBrowsers()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/backends/chrome/android_browser_finder.py", line 147, in CanFindAvailableBrowsers
return android_device.CanDiscoverDevices()
File "/media/myssd/chromium/src/tools/telemetry/telemetry/core/platform/android_device.py", line 102, in CanDiscoverDevices
traceback.print_stack()

[Ned]

The fix here may be changing the method Profiler.is_supported(cls, browser_type) of profiler to  accept a list of available browser type so the act of checking browser doesn't need to be repeated by multiple profilers.

[Zhen Wang]

Add "@decorators.Cache" before CanDiscoverDevices() seems to solve the problem.

Best

-Zhen

[Ned]

We should not use that "@decorators.Cache" pattern. It's evil. It has bitten us many times before.

[Zhen Wang]

Oh, I see. This may be off the topic. What are the problems with "@decorators.Cache" pattern you have seen before?

Best

-Zhen

[Nat Duca]

There was a thread on telemetry@ about this that you might be able to find in the archive. I support not using the @cache decorator.

We could always add explicit caching code to the function. Its just the decorator thats the problem.

[Ned]

Hi Zhen,

The problem with @decorators.Cache is that usually, you usually feel attempted to apply this on functions with side effects, because they are also the most expensive. However, if a function has side effect, it can do different things and return different values between calls.

Some example bugs:

_testUserAgent in page_run_end_to_end_unittest used to be flaky because it tries to open a new browser with 'tablet' useragent. However, it ends up reopening the same browser instance because Tony added @decorators.Cache to some browser_finder method to reduce the cycle time. (slamm@ can add more details)

_https://code.google.com/p/chromium/issues/detail?id=358655

Hence as Nat said, it's ok to add Caching behavior, but it should be done from the the callsite with a specific context instead of "caching for all caller" pattern in @decorators.Cache.

[Annie Sullivan]

Is there a bug on removing decorators.Cache? Should there be?

[Zhen Wang]

I see. Thanks for the explanations!

Best

-Zhen