New issue
Advanced search Search tips

Issue 617004 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Jun 2016
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Android
Pri: 1
Type: Bug

Blocked on:
issue 617593
issue 617838



Sign in to add a comment

page_cycler_v2 benchmark have onload metrics for only 11 out of 25 pages

Project Member Reported by nedngu...@google.com, Jun 3 2016

Issue description

Looks like the issue is that the traces captured in PCv2 ends too early and don't wait until the onload event is triggered.
The problem is in telemetry side not the TBMv2 metric.
Looks like the next step for this bug is to add logic for typical_25 pages to wait for onload event triggered in https://cs.chromium.org/chromium/src/tools/perf/page_sets/typical_25.py?rcl=0&l=53
Project Member

Comment 3 by sheriffbot@chromium.org, Jun 3 2016

Labels: Hotlist-Google
Project Member

Comment 4 by bugdroid1@chromium.org, Jun 4 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/7289aea063487fc7f4ff64d8a7ce2c7f7a0e023b

commit 7289aea063487fc7f4ff64d8a7ce2c7f7a0e023b
Author: nednguyen <nednguyen@google.com>
Date: Sat Jun 04 04:57:49 2016

[tools/perf] Make pages in typical_25 page_set to wait for load event to triggered

BUG= 617004 

Review-Url: https://codereview.chromium.org/2033813005
Cr-Commit-Position: refs/heads/master@{#397905}

[modify] https://crrev.com/7289aea063487fc7f4ff64d8a7ce2c7f7a0e023b/tools/perf/page_sets/typical_25.py

Cc: sullivan@chromium.org
Annie, we do not get any data on the dashboard after June 3rd, can you check?
https://chromeperf.appspot.com/report?sid=4e9483f8e6c08e8a2f6fd63afd61b503497c4bd5369077689119f0a7d18b54db&start_rev=397725&end_rev=397902
Blockedon: 617593
Oh, thanks for the analysis Annie. It's strange that the single page failure stops the benchmark from having any data at all.
Cc: dtu@chromium.org
Looking at the log, seems like what happens is the telemetry test might be killed by some sort of timeout, hence no data produced at all:

[ RUN      ] http://money.cnn.com/
(INFO) 2016-06-06 05:03:34,565 cmd_helper._ValidateAndLogCommand:153  [host]> /b/build/slave/Android_Nexus5_Perf__1_/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s 0d88c7fd25995e62 shell '( echo -n '"'"'{"trace_config": {"enable_systrace": false, "included_categories": ["loading", "*", "navigation", "blink.user_timing", "blink.console"], "record_mode": "record-as-much-as-possible"}}'"'"' > /data/local/chrome-trace-config.json );echo %$?'
(INFO) 2016-06-06 05:03:34,812 tracing_backend.StartTracing:130  Start Tracing Request: {'params': {'transferMode': 'ReturnAsStream', 'traceConfig': {'enableSystrace': False, 'recordMode': 'recordAsMuchAsPossible', 'includedCategories': ['loading', '*', 'navigation', 'blink.user_timing', 'blink.console']}}, 'method': 'Tracing.start'}
(INFO) 2016-06-06 05:03:34,826 cache_temperature.EnsurePageCacheTemperature:55  PageCacheTemperature: pcv1-warm
(INFO) 2016-06-06 05:03:48,812 cmd_helper._ValidateAndLogCommand:153  [host]> /b/build/slave/Android_Nexus5_Perf__1_/build/src/third_party/catapult/devil/bin/deps/linux2/x86_64/bin/adb -s 0d88c7fd25995e62 shell '( rm -f /data/local/chrome-trace-config.json );echo %$?'

<Thread(Thread-1, started 140495195756288)> ProcessRead: proc.stdout finished.
<Thread(Thread-1, started 140495195756288)> ProcessRead: cleaning up.
<Thread(Thread-2, started daemon 140495187363584)> TimedFlush: Finished
<Thread(Thread-1, started 140495195756288)> ProcessRead: finished.
exit code (as seen by runtest.py): 255


*Dave: you have any idea what killed the telemetry test run in the middle?
Blockedon: 617838
Kouhei & I look more carefully at the log, we highly suspect that this is a test timed out problem.
In https://uberchromegw.corp.google.com/i/chromium.perf/builders/Android%20Nexus5%20Perf%20%281%29/builds/3246/steps/page_cycler_v2.typical_25/logs/stdio

the first line of the log is:
(INFO) 2016-06-06 13:48:16...
& the last one is:
(INFO) 2016-06-06 17:08:33...

So basically, it took more than 3 hours 20 minutes to run page_cycler_v2.typical_25. For comparison, page_cycler.typical_25 only took about 30 minutes to run in total.

Kouhei is looking at the cache preparation logic in pcv2 is to check whether we wait for too long..
Labels: -Pri-2 Pri-1
PCv2 takes about same as much time as PCv1 per page.
However, PCv2 seems to be cycling through >389 pages, where as PCv1 cycled 75 pages.

Wrong page_set repeat?
Page_set repeat was correct.

Looks like there is some time out timer in test_runner.py, and a single page_cycler_v2.typical25 run takes >60min.

What is happening on https://uberchromegw.corp.google.com/i/chromium.perf/builders/Android%20Nexus5%20Perf%20%281%29/builds/3246/steps/page_cycler_v2.typical_25/logs/stdio
1. The test_runner runs PCv2.typical_25(attempt 1).
2. After 60min, abort test run from timeout.
3. The test_runner tries again.
4. After 60min, abort test run from timeout.
5. The test_runner tries again.
6. Timeout again. Give up.
Great detective work, Kouhei!
As described in https://codereview.chromium.org/2041253002/ :
The issue is that a PCv2 run takes >60min.
This is because PCv2 cycles through a URL 6 times (cold -> warm, cold -> warm, cold -> warm), where as PCv2 cycles through a URL 3 times (cold -> warm -> warm)
The CL reduces 6x iterations to 4x, which should fix the issue. 
Project Member

Comment 16 by bugdroid1@chromium.org, Jun 7 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/d18e493aeedfcfaebfbf044e3725a5c3aaf3589d

commit d18e493aeedfcfaebfbf044e3725a5c3aaf3589d
Author: kouhei <kouhei@chromium.org>
Date: Tue Jun 07 05:26:30 2016

[PCv2] Reduce page_set repeat 3->2

This CL reduces number of page_set iterations in PCv2,
to make the test run fit <60min in slow bots such as "Nexus 5 Perf".

Before this CL, PCv2 ran a URL 6 times, where as PCv1 ran a URL 3 times.
Which made a single page_cycler_v2.typical25 run take >60min, which caused
timeout on the perf bots.

BUG= 617004 
TBR=nednguyen@google.com

Review-Url: https://codereview.chromium.org/2041253002
Cr-Commit-Position: refs/heads/master@{#398233}

[modify] https://crrev.com/d18e493aeedfcfaebfbf044e3725a5c3aaf3589d/tools/perf/benchmarks/page_cycler_v2.py

Status: Fixed (was: Assigned)
I confirmed that this is fixed:
https://chromeperf.appspot.com/report?sid=6cd58f7ab062844f56c8bd8abb4429e6c74e6b9732cf058fc26803f98a9acd48

now lists 25 pages

Sign in to add a comment