New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 845878 link

Starred by 2 users

Issue metadata

Status: Fixed
Owner:
Last visit > 30 days ago
Closed: May 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 3
Type: Bug



Sign in to add a comment

Telemetry perf story log is not covering all the log for story

Project Member Reported by nednguyen@chromium.org, May 23 2018

Issue description

An example per story log of failing story smoothness.top_25_smooth/gmail:
https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/53888c1e-5e5c-11e8-912f-d4ae52d28fb6

Compared with the full benchmark log in https://chrome-swarming.appspot.com/task?id=3da418181f9cbc10&refresh=10&show_raw=1, we are losing this part: 

Traceback (most recent call last):
  File "c:\b\s\w\ir\third_party\catapult\telemetry\telemetry\internal\story_runner.py", line 125, in _RunStoryAndProcessErrorIfNeeded
    state.RunStory(results)
  File "c:\b\s\w\ir\third_party\catapult\common\py_trace_event\py_trace_event\trace_event_impl\decorators.py", line 52, in traced_function
    return func(*args, **kwargs)
  File "c:\b\s\w\ir\third_party\catapult\telemetry\telemetry\page\shared_page_state.py", line 310, in RunStory
    self._current_page.Run(self)
  File "c:\b\s\w\ir\third_party\catapult\telemetry\telemetry\page\__init__.py", line 99, in Run
    self.RunPageInteractions(action_runner)
  File "c:\b\s\w\ir\tools\perf\page_sets\top_25_smooth.py", line 44, in RunPageInteractions
    'window.__scrollableElementForTelemetry != null')
  File "c:\b\s\w\ir\third_party\catapult\common\py_trace_event\py_trace_event\trace_event_impl\decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "c:\b\s\w\ir\third_party\catapult\telemetry\telemetry\internal\actions\action_runner.py", line 261, in WaitForJavaScriptCondition
    return self._tab.WaitForJavaScriptCondition(*args, **kwargs)
  File "c:\b\s\w\ir\third_party\catapult\common\py_trace_event\py_trace_event\trace_event_impl\decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "c:\b\s\w\ir\third_party\catapult\telemetry\telemetry\internal\browser\web_contents.py", line 239, in WaitForJavaScriptCondition
    return self._inspector_backend.WaitForJavaScriptCondition(*args, **kwargs)
  File "c:\b\s\w\ir\third_party\catapult\common\py_trace_event\py_trace_event\trace_event_impl\decorators.py", line 75, in traced_function
    return func(*args, **kwargs)
  File "c:\b\s\w\ir\third_party\catapult\telemetry\telemetry\internal\backends\chrome_inspector\inspector_backend.py", line 302, in WaitForJavaScriptCondition
    e.message + '\n' + debug_message)
TimeoutException: Timed out while waiting 60s for IsJavaScriptExpressionTrue.
Console output:

 
The root cause of this is because these exception strings are handled by gtest_progress_reporter which prints to stdout stream. I think some of ways to fix this are: 
1) Make gtest_progress_reporter output to exception to log instead of outputstream in gtest_progress_reporter.DidFail (https://cs.chromium.org/chromium/src/third_party/catapult/telemetry/telemetry/internal/results/gtest_progress_reporter.py?rcl=40e4ebef555172691468e7670c8c3870bebf7051&l=41)

2) Make gtest_progress_outputter no longer handles print out exception, add code in story_runner to do logging.exception(exc) to print the exception string to the log.

I prefer (2) to (1) because (1) creates a hidden dependency between how gtest_progress_reporter handle exception strings and story_runner module

Project Member

Comment 2 by bugdroid1@chromium.org, May 24 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/catapult/+/7dc0e251e9a996fe9007c23022623f466637d238

commit 7dc0e251e9a996fe9007c23022623f466637d238
Author: Nghia Nguyen <nednguyen@google.com>
Date: Thu May 24 12:06:50 2018

Make sure Telemetry output all exception string related to single story to per story log

This also add test coverage to ensure the artifact logs capture both logs & exception stack
(see extra tests in telemetry/telemetry/internal/story_runner_unittest.py)

Bug:  chromium:845878 
Change-Id: Ia81597f4fe9e06afb1a17b7be0b1d955a7ff91c2
Reviewed-on: https://chromium-review.googlesource.com/1069484
Commit-Queue: Ned Nguyen <nednguyen@google.com>
Reviewed-by: Juan Antonio Navarro Pérez <perezju@chromium.org>

[modify] https://crrev.com/7dc0e251e9a996fe9007c23022623f466637d238/telemetry/telemetry/internal/results/page_test_results.py
[modify] https://crrev.com/7dc0e251e9a996fe9007c23022623f466637d238/telemetry/telemetry/internal/results/progress_reporter.py
[modify] https://crrev.com/7dc0e251e9a996fe9007c23022623f466637d238/telemetry/telemetry/internal/story_runner.py
[modify] https://crrev.com/7dc0e251e9a996fe9007c23022623f466637d238/telemetry/telemetry/internal/story_runner_unittest.py
[modify] https://crrev.com/7dc0e251e9a996fe9007c23022623f466637d238/telemetry/telemetry/internal/results/gtest_progress_reporter_unittest.py
[modify] https://crrev.com/7dc0e251e9a996fe9007c23022623f466637d238/telemetry/telemetry/internal/results/gtest_progress_reporter.py
[modify] https://crrev.com/7dc0e251e9a996fe9007c23022623f466637d238/telemetry/telemetry/testing/system_stub.py

Project Member

Comment 3 by bugdroid1@chromium.org, May 24 2018

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

commit 09c6d27e5dbba14dc9a05ae872bfe8e2010a5193
Author: catapult-chromium-autoroll <catapult-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Date: Thu May 24 13:32:19 2018

Roll src/third_party/catapult/ 1986f5a95..7dc0e251e (1 commit)

https://chromium.googlesource.com/catapult.git/+log/1986f5a957da..7dc0e251e9a9

$ git log 1986f5a95..7dc0e251e --date=short --no-merges --format='%ad %ae %s'
2018-05-24 nednguyen Make sure Telemetry output all exception string related to single story to per story log

Created with:
  roll-dep src/third_party/catapult
BUG= chromium:845878 


The AutoRoll server is located here: https://catapult-roll.skia.org

Documentation for the AutoRoller is here:
https://skia.googlesource.com/buildbot/+/master/autoroll/README.md

If the roll is causing failures, please contact the current sheriff, who should
be CC'd on the roll, and stop the roller if necessary.


CQ_INCLUDE_TRYBOTS=luci.chromium.try:android_optional_gpu_tests_rel;luci.chromium.try:linux_optional_gpu_tests_rel;luci.chromium.try:mac_optional_gpu_tests_rel;luci.chromium.try:win_optional_gpu_tests_rel
TBR=sullivan@chromium.org

Change-Id: I9a48b1ae79353beed5b63193fdc85d50f4ab8911
Reviewed-on: https://chromium-review.googlesource.com/1070783
Reviewed-by: catapult-chromium-autoroll <catapult-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Commit-Queue: catapult-chromium-autoroll <catapult-chromium-autoroll@skia-buildbots.google.com.iam.gserviceaccount.com>
Cr-Commit-Position: refs/heads/master@{#561485}
[modify] https://crrev.com/09c6d27e5dbba14dc9a05ae872bfe8e2010a5193/DEPS

Status: Fixed (was: Assigned)

Comment 5 by benhenry@google.com, Jan 16 (6 days ago)

Components: Test>Telemetry

Comment 6 by benhenry@google.com, Jan 16 (6 days ago)

Components: -Speed>Telemetry

Sign in to add a comment