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

Issue 610411 link

Starred by 3 users

Issue metadata

Status: Verified
Owner:
Closed: May 2016
Cc:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

Test graphics_WebGLAquarium/avg_fps_1000_fishes is not producing performance data on many devices

Project Member Reported by haddowk@chromium.org, May 9 2016

Issue description

The test graphics_WebGLAquarium/avg_fps_1000_fishes has not produced    data on several platforms for the last three runs of the test in the lab.

05/09 03:54:22.450 DEBUG|        base_utils:0176| Running 'rm -rf /var/spool/crash/*'
05/09 03:54:22.462 DEBUG|        base_utils:0176| Running 'logger "autotest finished iteration /usr/local/autotest/results/default/graphics_WebGLAquarium/sysinfo/iteration.1"'
05/09 03:54:22.485 WARNI|              test:0606| Autotest caught exception when running test:
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 600, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/common_lib/test.py", line 810, in _call_test_function
    raise error.UnhandledTestFail(e)
UnhandledTestFail: Unhandled TimeoutException: 
Exception thrown when trying to capture console output: TimeoutException('',)
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 804, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/common_lib/test.py", line 461, in execute
    dargs)
  File "/usr/local/autotest/common_lib/test.py", line 347, in _call_run_once_with_retry
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/common_lib/test.py", line 376, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/tests/graphics_WebGLAquarium/graphics_WebGLAquarium.py", line 298, in run_once
    self.run_fish_test(cr.browser, test_url, n)
  File "/usr/local/autotest/tests/graphics_WebGLAquarium/graphics_WebGLAquarium.py", line 109, in run_fish_test
    tab.WaitForDocumentReadyStateToBeComplete()
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 70, in WaitForDocumentReadyStateToBeComplete
    'document.readyState == "complete"', timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/web_contents.py", line 136, in WaitForJavaScriptExpression
    e.message + '\n' + debug_message)
TimeoutException: 
Exception thrown when trying to capture console output: TimeoutException('',)

Platforms currently affected:

orco
yuna
paine
sumo
cyan
lulu
ultima
guado
butterfly
chell
terra
big
celes
quawks
parrot
gnawty
expresso
gandof
setzer
rikku
panther
edgar
wizpig
tidus
sentry
lars
buddy
blaze
ninja
reks

Example logs

https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/62652349-haddowk

https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/62653455-haddowk

https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/62653855-haddowk




 

Comment 1 by ihf@chromium.org, May 9 2016

Cc: achuith@chromium.org steve...@chromium.org
Tried to repro/bisect using Linux binaries but no luck. The logs hint at problems with login or telemetry infra


2016-05-09T04:15:09.467989-07:00 INFO kernel: [  858.777478] [drm] Adding LVDS downclock mode
2016-05-09T04:15:09.607122-07:00 NOTICE root[17478]: autotest starting iteration /usr/local/autotest/results/default/graphics_WebGLAquarium/sysinfo/iteration.1 on parrot_1.1GHz_2GB
2016-05-09T04:15:09.846973-07:00 WARNING kernel: [  859.156521] init: debugd main process (16933) killed by TERM signal
2016-05-09T04:15:09.862319-07:00 INFO session_manager[16909]: [INFO:browser_job.cc(119)] Terminating process: 
2016-05-09T04:15:09.862354-07:00 INFO session_manager[16909]: [INFO:system_utils_impl.cc(49)] Sending 15 to 16927 as 1000
2016-05-09T04:15:10.425969-07:00 INFO session_manager[16909]: [INFO:session_manager_service.cc(572)] SessionManagerService quitting run loop
2016-05-09T04:15:10.426017-07:00 INFO session_manager[16909]: [INFO:session_manager_service.cc(224)] SessionManagerService exiting
2016-05-09T04:15:10.569402-07:00 INFO session_manager[16909]: [INFO:policy_service.cc(188)] Persisted policy to disk.
2016-05-09T04:15:10.868637-07:00 ERR lockbox-cache[17620]: Failed to read lockbox contents from /home/.shadow/install_attributes.pb
2016-05-09T04:15:10.869948-07:00 WARNING kernel: [  860.179216] init: lockbox-cache pre-start process (17613) terminated with status 1
2016-05-09T04:15:10.993013-07:00 INFO session_manager[17709]: [INFO:session_manager_main.cc(188)] Will wait 3s for graceful browser exit.
2016-05-09T04:15:10.995721-07:00 INFO session_manager[17709]: [INFO:session_manager_service.cc(156)] SessionManagerService starting
2016-05-09T04:15:10.997934-07:00 INFO session_manager[17709]: [INFO:policy_key.cc(54)] No policy key on disk at /var/lib/whitelist/owner.key
2016-05-09T04:15:10.997964-07:00 WARNING session_manager[17709]: [WARNING:device_policy_service.cc(427)] Policy file empty or missing.
2016-05-09T04:15:10.999645-07:00 INFO session_manager[17709]: [INFO:browser_job.cc(102)] Running child chrome...
2016-05-09T04:15:11.170946-07:00 INFO kernel: [  860.479915] [drm] Adding LVDS downclock mode
2016-05-09T04:15:11.198473-07:00 NOTICE autotest[17751]: 04:15:11.193 WARNI|        base_utils:0080| /usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser_credentials.py:28: UserWarning: Class FormBasedCredentialsBackend is deprecated. It will no longer be supported on May 05, 2017. Please remove it or switch to an alternative before that time. Use the login helper modules in https://code.google.com/p/chromium/codesearch#chromium/src/tools/perf/page_sets/login_helpers/ instead.#012#012  codepen_credentials_backend.CodePenCredentialsBackend(),
2016-05-09T04:15:11.205287-07:00 NOTICE autotest[17753]: 04:15:11.200 WARNI|        base_utils:0080| /usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser_credentials.py:29: UserWarning: Class FormBasedCredentialsBackend is deprecated. It will no longer be supported on May 05, 2017. Please remove it or switch to an alternative before that time. Use the login helper modules in https://code.google.com/p/chromium/codesearch#chromium/src/tools/perf/page_sets/login_helpers/ instead.#012#012  facebook_credentials_backend.FacebookCredentialsBackend(),
2016-05-09T04:15:11.212220-07:00 NOTICE autotest[17759]: 04:15:11.206 WARNI|        base_utils:0080| /usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser_credentials.py:30: UserWarning: Class FormBasedCredentialsBackend is deprecated. It will no longer be supported on May 05, 2017. Please remove it or switch to an alternative before that time. Use the login helper modules in https://code.google.com/p/chromium/codesearch#chromium/src/tools/perf/page_sets/login_helpers/ instead.#012#012  facebook_credentials_backend.FacebookCredentialsBackend2(),
2016-05-09T04:15:11.221281-07:00 NOTICE autotest[17762]: 04:15:11.213 WARNI|        base_utils:0080| /usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser_credentials.py:31: UserWarning: Class FormBasedCredentialsBackend is deprecated. It will no longer be supported on May 05, 2017. Please remove it or switch to an alternative before that time. Use the login helper modules in https://code.google.com/p/chromium/codesearch#chromium/src/tools/perf/page_sets/login_helpers/ instead.#012#012  google_credentials_backend.GoogleCredentialsBackend(),
2016-05-09T04:15:11.228422-07:00 NOTICE autotest[17764]: 04:15:11.222 WARNI|        base_utils:0080| /usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser_credentials.py:32: UserWarning: Class FormBasedCredentialsBackend is deprecated. It will no longer be supported on May 05, 2017. Please remove it or switch to an alternative before that time. Use the login helper modules in https://code.google.com/p/chromium/codesearch#chromium/src/tools/perf/page_sets/login_helpers/ instead.#012#012  google_credentials_backend.GoogleCredentialsBackend2()]
2016-05-09T04:15:11.244390-07:00 INFO session_manager[17709]: [INFO:browser_job.cc(111)] Terminating process group: Restarting browser on-demand.
2016-05-09T04:15:11.244428-07:00 INFO session_manager[17709]: [INFO:system_utils_impl.cc(49)] Sending 9 to -17724 as 1000
2016-05-09T04:15:11.248390-07:00 INFO session_manager[17709]: [INFO:child_exit_handler.cc(77)] Handling 17724 exit.
2016-05-09T04:15:11.248425-07:00 ERR session_manager[17709]: [ERROR:child_exit_handler.cc(85)]   Exited with signal 9
2016-05-09T04:15:11.248434-07:00 INFO session_manager[17709]: [INFO:session_manager_service.cc(284)] Exiting process is chrome.
2016-05-09T04:15:11.248442-07:00 INFO session_manager[17709]: [INFO:browser_job.cc(111)] Terminating process group: Ensuring browser processes are gone.
2016-05-09T04:15:11.248451-07:00 INFO session_manager[17709]: [INFO:system_utils_impl.cc(49)] Sending 9 to -17724 as 1000
2016-05-09T04:15:11.257983-07:00 INFO session_manager[17709]: [INFO:browser_job.cc(102)] Running child chrome...
2016-05-09T04:15:11.465956-07:00 INFO kernel: [  860.774784] [drm] Adding LVDS downclock mode
2016-05-09T04:15:12.110956-07:00 DEBUG kernel: [  861.419947] ehci-pci 0000:00:1a.0: setting latency timer to 64
2016-05-09T04:15:12.347157-07:00 INFO kernel: [  861.656454] [drm] Adding LVDS downclock mode
2016-05-09T04:15:14.437816-07:00 DEBUG kernel: [  863.744694] ieee80211 phy0: device no longer idle - scanning
2016-05-09T04:15:14.477415-07:00 INFO session_manager[17709]: [INFO:server_backed_state_key_generator.cc(132)] Stable device secret missing!
2016-05-09T04:15:14.680668-07:00 WARNING cryptohomed[16613]: Could not load the device policy file.
2016-05-09T04:15:14.721385-07:00 INFO kernel: [  864.029715] tpm_tis tpm_tis: command 0x15 (size 14) returned code 0x0
2016-05-09T04:15:14.721620-07:00 INFO cryptohomed[16613]: RecursiveCopy: /home/.shadow/skeleton/.ssh
2016-05-09T04:15:14.722017-07:00 INFO cryptohomed[16613]: RecursiveCopy: /home/.shadow/skeleton/.pki
2016-05-09T04:15:14.722045-07:00 INFO cryptohomed[16613]: RecursiveCopy: /home/.shadow/skeleton/.pki/nssdb
2016-05-09T04:15:14.722597-07:00 INFO cryptohomed[16613]: RecursiveCopy: /home/.shadow/skeleton/log
2016-05-09T04:15:15.397845-07:00 INFO session_manager[17709]: [INFO:session_manager_service.cc(337)] Received RestartJob from :1.88
2016-05-09T04:15:15.399982-07:00 INFO session_manager[17709]: [INFO:policy_key.cc(54)] No policy key on disk at /home/root/e259b5d9c30f44911e47e61378f7dd68528f127b/session_manager/policy/key
2016-05-09T04:15:15.407051-07:00 ERR session_manager[17709]: [ERROR:nss_util.cc(151)] Not checking key because size is 0
2016-05-09T04:15:15.407328-07:00 WARNING session_manager[17709]: [WARNING:device_policy_service.cc(402)] Could not verify that owner key belongs to this user.
2016-05-09T04:15:15.489251-07:00 ERR shill[991]: [ERROR:crypto_des_cbc.cc(103)] Unable to load key matter from /var/lib/whitelist/owner.key
2016-05-09T04:15:15.493413-07:00 ERR shill[991]: [ERROR:crypto_des_cbc.cc(103)] Unable to load key matter from /var/lib/whitelist/owner.key
2016-05-09T04:15:15.503470-07:00 INFO session_manager[17709]: [INFO:session_manager_impl.cc(348)] Starting user session
2016-05-09T04:15:15.503501-07:00 INFO session_manager[17709]: [INFO:browser_job.cc(111)] Terminating process group: Restarting browser on-demand.
2016-05-09T04:15:15.503512-07:00 INFO session_manager[17709]: [INFO:system_utils_impl.cc(49)] Sending 9 to -17767 as 1000
2016-05-09T04:15:15.579675-07:00 INFO session_manager[17709]: [INFO:child_exit_handler.cc(77)] Handling 17767 exit.
2016-05-09T04:15:15.579718-07:00 ERR session_manager[17709]: [ERROR:child_exit_handler.cc(85)]   Exited with signal 9
2016-05-09T04:15:15.579732-07:00 INFO session_manager[17709]: [INFO:session_manager_service.cc(284)] Exiting process is chrome.
2016-05-09T04:15:15.579744-07:00 INFO session_manager[17709]: [INFO:browser_job.cc(111)] Terminating process group: Ensuring browser processes are gone.
2016-05-09T04:15:15.579756-07:00 INFO session_manager[17709]: [INFO:system_utils_impl.cc(49)] Sending 9 to -17767 as 1000
2016-05-09T04:15:15.797239-07:00 INFO session_manager[17709]: [INFO:browser_job.cc(102)] Running child chrome...
2016-05-09T04:15:16.010943-07:00 INFO kernel: [  865.319798] [drm] Adding LVDS downclock mode
2016-05-09T04:15:17.081290-07:00 INFO kernel: [  866.389790] [drm] Adding LVDS downclock mode
2016-05-09T04:15:18.095131-07:00 DEBUG kernel: [  867.404148] ieee80211 phy0: device now idle
2016-05-09T04:15:20.128393-07:00 NOTICE autotest[18045]: 04:15:20.121 WARNI|        site_utils:0746| Unable to read temperature sensors using ectool.
2016-05-09T04:16:18.139486-07:00 DEBUG kernel: [  927.444684] ieee80211 phy0: device no longer idle - scanning
2016-05-09T04:16:21.789948-07:00 DEBUG kernel: [  931.097114] ieee80211 phy0: device now idle
2016-05-09T04:17:01.429956-07:00 WARNING kernel: [  970.736773] init: debugd main process (17731) killed by TERM signal
2016-05-09T04:17:01.462472-07:00 INFO session_manager[17709]: [INFO:browser_job.cc(119)] Terminating process: 
2016-05-09T04:17:01.462503-07:00 INFO session_manager[17709]: [INFO:system_utils_impl.cc(49)] Sending 15 to 17928 as 1000
2016-05-09T04:17:01.917647-07:00 INFO session_manager[17709]: [INFO:session_manager_service.cc(572)] SessionManagerService quitting run loop
2016-05-09T04:17:01.918621-07:00 INFO session_manager[17709]: [INFO:session_manager_service.cc(224)] SessionManagerService exiting
2016-05-09T04:17:02.048241-07:00 INFO session_manager[17709]: [INFO:policy_service.cc(188)] Persisted policy to disk.
2016-05-09T04:17:02.048647-07:00 INFO session_manager[17709]: [INFO:policy_service.cc(188)] Persisted policy to disk.
2016-05-09T04:17:02.091656-07:00 WARNING chapsd[16604]: Unload Token event received for unknown path: /home/root/b7a0e9c50bbca57c69551c4d0f2dae1b1febd296/chaps
2016-05-09T04:17:02.258988-07:00 WARNING cryptohomed[16613]: Could not load the device policy file.
2016-05-09T04:17:02.261200-07:00 WARNING chapsd[16604]: Unload Token event received for unknown path: /home/root/b7a0e9c50bbca57c69551c4d0f2dae1b1febd296/chaps
2016-05-09T04:17:02.300313-07:00 ERR lockbox-cache[18154]: Failed to read lockbox contents from /home/.shadow/install_attributes.pb
2016-05-09T04:17:02.301939-07:00 WARNING kernel: [  971.608004] init: lockbox-cache pre-start process (18146) terminated with status 1
2016-05-09T04:17:02.421613-07:00 INFO session_manager[18242]: [INFO:session_manager_main.cc(188)] Will wait 3s for graceful browser exit.
2016-05-09T04:17:02.425330-07:00 INFO session_manager[18242]: [INFO:session_manager_service.cc(156)] SessionManagerService starting
2016-05-09T04:17:02.427032-07:00 INFO session_manager[18242]: [INFO:policy_key.cc(54)] No policy key on disk at /var/lib/whitelist/owner.key
2016-05-09T04:17:02.427177-07:00 ERR session_manager[18242]: [ERROR:policy_store.cc(34)] Could not read policy off disk at /var/lib/whitelist/policy: No such file or directory
2016-05-09T04:17:02.427232-07:00 WARNING session_manager[18242]: [WARNING:device_policy_service.cc(181)] Failed to load device policy data, continuing anyway.
2016-05-09T04:17:02.427303-07:00 WARNING session_manager[18242]: [WARNING:device_policy_service.cc(427)] Policy file empty or missing.
2016-05-09T04:17:02.428971-07:00 INFO session_manager[18242]: [INFO:browser_job.cc(102)] Running child chrome...
2016-05-09T04:17:02.451087-07:00 NOTICE root[18263]: autotest finished iteration /usr/local/autotest/results/default/graphics_WebGLAquarium/sysinfo/iteration.1
2016-05-09T04:17:02.501260-07:00 NOTICE autotest[18276]: 04:17:02.495 WARNI|              test:0606| Autotest caught exception when running test:#012Traceback (most recent call last):#012  File "/usr/local/autotest/common_lib/test.py", line 600, in _exec#012    _call_test_function(self.execute, *p_args, **p_dargs)#012  File "/usr/local/autotest/common_lib/test.py", line 810, in _call_test_function#012    raise error.UnhandledTestFail(e)#012UnhandledTestFail: Unhandled TimeoutException: #012Exception thrown when trying to capture console output: TimeoutException('',)#012Traceback (most recent call last):#012  File "/usr/local/autotest/common_lib/test.py", line 804, in _call_test_function#012    return func(*args, **dargs)#012  File "/usr/local/autotest/common_lib/test.py", line 461, in execute#012    dargs)#012  File "/usr/local/autotest/common_lib/test.py", line 347, in _call_run_once_with_retry#012    postprocess_profiled_run, args, dargs)#012  File "/usr/local/autotest/common_lib/test.py", line 376, in _call_run_once#012    self.run_once(*args, **dargs)#012  File "/usr/local/autotest/tests/graphics_WebGLAquarium/

Comment 2 by ihf@chromium.org, May 9 2016

Just FYI, this regression should be in Chrome between
https://chromium.googlesource.com/chromium/src/+log/52.0.2724.0..52.0.2726.0?pretty=fuller&n=10000

Comment 3 by ihf@chromium.org, May 9 2016

So, it is not login. On the device pointing to the webglsamples.org site the aquarium hangs. Also autotest sees lots of crashes, which need to be symbolized.

Comment 4 by ihf@chromium.org, May 9 2016

Cc: ihf@chromium.org marc...@chromium.org avkodipelli@chromium.org
 Issue 610494  has been merged into this issue.
Ilja, what are implications of this issue? Is just the demo not working or this issue affects WebGL in general?

Comment 6 by ihf@chromium.org, May 9 2016

Looks like the crashes were unrelated.

Comment 7 by ihf@chromium.org, May 9 2016

Still happening on tot #392450.

Comment 8 by ihf@chromium.org, May 10 2016

Owner: erikc...@chromium.org
This is due to CL 391686:
https://codereview.chromium.org/1943513002
ihf: Could you provide some more information about how you determined this? Did you do a bisect? A local revert that fixed the problem?

The quoted CL ranged also has several WebGL changes by me, which I would expect to be more likely culprits.

Comment 10 by ihf@chromium.org, May 10 2016

#391685 doesn't show the hang, #391686 does show the hang.

Comment 11 by ihf@chromium.org, May 10 2016

Labels: -Restrict-View-Google M-52
I played with different command line flags on Linux to match about:gpu to the lars status. I did not get the hang on Linux. Looks like a Chromebook will be needed for repro.

Comment 12 by ihf@chromium.org, May 10 2016

I can help you tomorrow to set up a system.

Comment 13 by ihf@chromium.org, May 10 2016

((392450-391934)-391686) shows now hang.

Comment 14 by ihf@chromium.org, May 10 2016

now -> no.
Cc: pucchakayala@chromium.org
 Issue 610887  has been merged into this issue.
This is caused by the change in GpuChannel::HandleMessage from 

stub && stub->HasUnprocesedCommands() to !message_queue->IsScheduled().

There exist instances where "stub && stub->HasUnprocesedCommands()" returns true but "!message_queue->IsScheduled()" returns false.

Investigating further.
Cc: piman@chromium.org sunn...@chromium.org
The only place that the message_queue gets descheduled is in GpuCommandBufferStub::OnWaitFenceSync.

I think we could change the conditional to have use both clauses, as in:
if (stub && stub->HasUnprocesedCommands() || !message_queue->IsScheduled())

Alternatively, we could have GpuCommandBufferStub::OnAsyncFlush also deschedule the message_queue, and reschedule when the flush is finished. [CommandExecutor will be left scheduled.] This would require the type of |scheduled_| to become int, since the CommandExecutor may process OnWaitFencSync commands. 

The route we take mostly depends on the semantics we want to give GpuChannelMessageQueue::scheduled_. 

sunnyps, piman: thoughts?
Oh I see. The only way for there to be UnprocessedCommands in the stub is if it has a FenceSync it needed to wait on, or if it was pre-empted.

Comment 19 by piman@chromium.org, May 11 2016

Oh, preemption.
"if (stub && stub->HasUnprocesedCommands() || !message_queue->IsScheduled())" is probably the right thing in the short term.
Status: Fixed (was: Assigned)
https://codereview.chromium.org/1965253002/
(FYI: CL:1965253002 landed in 52.0.2733.0)
Status: Verified (was: Fixed)
Verified on 8337.0.0/52.0.2739.0
Cc: -mshe...@chromium.org

Sign in to add a comment