Issue 604570  has been merged into this issue.

Hi posciak, are you the correct owner for failures of this test? If not, do you know who else might be? Thanks!

Yes, I am the correct owner. Thanks.

Hi Pawel, I wanted to see if you had had a chance to look into this yet? Thanks!

Hi posciak, just checking in here. Thanks!

Hi Wu-cheng, have you had a chance to look at this? Best, Matt

Sorry. Not yet. I'll look at this on Monday.

The version in https://pantheon.corp.google.com/storage/browser/chromeos-autotest-results/59905136-haddowk is Zako R50-7978.55.0.

I ran test_that locally. I saw "Not enough googMaxDecodeMs" error. 

01:06:38 INFO | autoserv| Executing /usr/local/autotest/bin/autotest /usr/local/autotest/control phase 0
01:06:38 INFO | autoserv| Entered autotestd_monitor.
01:06:38 INFO | autoserv| Finished launching tail subprocesses.
01:06:38 INFO | autoserv| Finished waiting on autotestd to start.
01:06:40 INFO | autoserv| START	----	----	timestamp=1463378799	localtime=May 16 01:06:39
01:06:40 INFO | autoserv| START	video_WebRtcPerf	video_WebRtcPerf	timestamp=1463378799	localtime=May 16 01:06:39
01:06:40 INFO | autoserv| Bundling /build/daisy/usr/local/build/autotest/client/site_tests/video_WebRtcPerf into test-video_WebRtcPerf.tar.bz2
01:07:54 INFO | autoserv| ERROR	video_WebRtcPerf	video_WebRtcPerf	timestamp=1463378873	localtime=May 16 01:07:53	Not enough googMaxDecodeMs
01:07:54 INFO | autoserv| END ERROR	video_WebRtcPerf	video_WebRtcPerf	timestamp=1463378873	localtime=May 16 01:07:53
01:07:55 INFO | autoserv| END GOOD	----	----	timestamp=1463378874	localtime=May 16 01:07:54
01:07:56 INFO | autoserv| Got lock of exit_code_file.
01:07:56 INFO | autoserv| Released lock of exit_code_file and closed it.
01:07:58 INFO | autoserv| Client complete
01:07:58 INFO | autoserv| Finished processing control file
01:07:58 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_yRT_9kssh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/tmp/tmplbpIyV -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=300 -l root -p 22 100.102.7.190'
01:07:59 INFO | autoserv| Starting master ssh connection '/usr/bin/ssh -a -x   -N -o ControlMaster=yes -o ControlPath=/tmp/_autotmp_8n3vTussh-master/socket -o StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o BatchMode=yes -o ConnectTimeout=30 -o ServerAliveInterval=900 -o ServerAliveCountMax=3 -o ConnectionAttempts=4 -o Protocol=2 -l root -p 22 100.102.7.190'
01:08:00 INFO | autoserv| There are no orphaned crashes; deleting /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/crashinfo.100.102.7.190
01:08:00 INFO | autoserv| Trying to generate stack trace locally for /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/sysinfo/var/spool/crash/video_encode_accelerator_unittest.20150614.194037.10471.dmp
01:08:00 INFO | autoserv| symbol_dir: /build/daisy/usr/local/build/autotest/server/../../../lib/debug
01:08:00 INFO | autoserv| Generated stack trace for dump /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/sysinfo/var/spool/crash/video_encode_accelerator_unittest.20150614.194037.10471.dmp
01:08:00 INFO | autoserv| Trying to generate stack trace locally for /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/sysinfo/var/spool/crash/video_encode_accelerator_unittest.20150614.194030.10458.dmp
01:08:00 INFO | autoserv| symbol_dir: /build/daisy/usr/local/build/autotest/server/../../../lib/debug
01:08:00 INFO | autoserv| Generated stack trace for dump /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/sysinfo/var/spool/crash/video_encode_accelerator_unittest.20150614.194030.10458.dmp
01:08:00 INFO | autoserv| INFO	----	----	timestamp=1463378880	localtime=May 16 01:08:00	Start crashcollection record
01:08:00 INFO | autoserv| INFO	----	New Crash Dump	timestamp=1463378880	localtime=May 16 01:08:00	/tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/sysinfo/var/spool/crash/video_encode_accelerator_unittest.20150614.194037.10471.dmp
01:08:00 INFO | autoserv| INFO	----	New Crash Dump	timestamp=1463378880	localtime=May 16 01:08:00	/tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/sysinfo/var/spool/crash/video_encode_accelerator_unittest.20150614.194030.10458.dmp
01:08:00 INFO | autoserv| INFO	----	----	timestamp=1463378880	localtime=May 16 01:08:00	End crashcollection record
01:08:16 INFO | autoserv| find_package_of() found no packages for "video_encode_accelerator_unittest"
01:08:16 INFO | autoserv| Would report crash on <unknown package>.
01:08:25 INFO | autoserv| find_package_of() found no packages for "video_encode_accelerator_unittest"
01:08:25 INFO | autoserv| Would report crash on <unknown package>.
01:08:25 INFO | autoserv| Copied /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/sysinfo/var/spool/crash/video_encode_accelerator_unittest.20150614.194037.10471.dmp.txt to /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/debug/video_encode_accelerator_unittest.20150614.194037.10471.dmp.txt
01:08:25 INFO | autoserv| Failed to copy /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/sysinfo/var/spool/crash/video_encode_accelerator_unittest.20150614.194037.10471.log to /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/debug/video_encode_accelerator_unittest.20150614.194037.10471.log
01:08:25 INFO | autoserv| Copied /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/sysinfo/var/spool/crash/video_encode_accelerator_unittest.20150614.194030.10458.dmp.txt to /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/debug/video_encode_accelerator_unittest.20150614.194030.10458.dmp.txt
01:08:25 INFO | autoserv| Failed to copy /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/sysinfo/var/spool/crash/video_encode_accelerator_unittest.20150614.194030.10458.log to /tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/debug/video_encode_accelerator_unittest.20150614.194030.10458.log
01:08:27 INFO | autoserv| record_state_duration failed: job_or_task_id=None, hostname=100.102.7.190, status=Running
-------------------------------------------------------------------------------------
/tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf                  [  FAILED  ]
/tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf                    ERROR: Not enough googMaxDecodeMs
/tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/video_WebRtcPerf [  FAILED  ]
/tmp/test_that_results_aHxZyE/results-1-video_WebRtcPerf/video_WebRtcPerf   ERROR: Not enough googMaxDecodeMs

Sometimes I could repro. But the screen of my daisy is broken. According to Chromestop, Taipei office doesn't have any other daisy or zako. I'm trying to find a parrot.

I can't repro on Parrot. I'm trying connecting an external monitor to daisy.

Sometimes I could reproduce on daisy. Debugging.

In general, daisy is sluggish. I'm not sure if it's related to connecting to an external monitor. My daisy is old and the screen is broken. I need to request a new one.

Also the camera on my daisy is also broken. I connected an external webcam. There are many factors. I need to get a good daisy to reproduce. But it takes 2 weeks to arrive Taipei. I cannot reproduce on Parrot. There's no Zako here.

Chromestop didn't know Snow=Lucas=Daisy. He said there was no daisy. We found there were lots of lucas in Taipei. I'll find one tomorrow.

VDA test showed HW decode FPS was good.

localhost chrome # ./video_decode_accelerator_unittest --test_video_data='crowd720-41e9a3e6a6b1644ebdb3f5723fce96e5.vp8:1280:720:500:502:::11' --gtest_filter=DecodeVariations/VideoDecodeAcceleratorParamTest.TestSimpleDecode/0 --v=0 --rendering_fps=0

Decoder 0 fps: 213.168

It looked like software decode is now slower. So it did't generate enough frame samples in 15 seconds. Hardware decode passed.

17:00:23 ERROR| test hardware decode
17:00:44 ERROR| before evaluate
17:00:44 ERROR| len(decode_time_list)=1
17:00:45 ERROR| before evaluate
17:00:45 ERROR| len(decode_time_list)=2
17:00:46 ERROR| before evaluate
17:00:46 ERROR| len(decode_time_list)=4
17:00:47 ERROR| before evaluate
17:00:49 ERROR| len(decode_time_list)=5
17:00:50 ERROR| before evaluate
17:00:50 ERROR| len(decode_time_list)=8
17:00:51 ERROR| before evaluate
17:00:51 ERROR| len(decode_time_list)=9
17:00:52 ERROR| before evaluate
17:00:52 ERROR| len(decode_time_list)=10
17:00:52 INFO | Max decode time list=[0, 0, 6, 7, 7, 8, 8, 8, 8, 8]
17:00:52 INFO | Decode time list=[0, 0, 3, 3, 3, 3, 3, 3, 3, 4]
17:00:52 INFO | Maximum decode time=8, median=3
17:00:54 INFO | (Re)starting the ui (logs the user out)
17:00:55 ERROR| test software decode
17:00:55 INFO | Chose browser: PossibleCrOSBrowser(browser_type=system)
17:00:55 INFO | (Re)starting the ui (logs the user out)
17:00:58 INFO | Restarting Chrome with flags and login
02:01:02 INFO | Invoking Oobe.loginForTesting
02:01:09 INFO | Browser is up!
17:01:14 ERROR| before evaluate
17:01:14 ERROR| len(decode_time_list)=0
17:01:15 ERROR| before evaluate
17:01:15 ERROR| len(decode_time_list)=1
17:01:16 ERROR| before evaluate
17:01:30 ERROR| len(decode_time_list)=2
17:01:30 INFO | (Re)starting the ui (logs the user out)
17:01:32 WARNI| 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 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/video_WebRtcPerf/video_WebRtcPerf.py", line 141, in run_once
    keyvals = self.test_decode_time(local_path)
  File "/usr/local/autotest/tests/video_WebRtcPerf/video_WebRtcPerf.py", line 326, in test_decode_time
    return self.test_webrtc(local_path, get_decode_time)
  File "/usr/local/autotest/tests/video_WebRtcPerf/video_WebRtcPerf.py", line 200, in test_webrtc
    result = gather_result(cr)
  File "/usr/local/autotest/tests/video_WebRtcPerf/video_WebRtcPerf.py", line 315, in get_decode_time
    raise error.TestError('Not enough ' + GOOG_MAX_DECODE_MS)
TestError: Not enough googMaxDecodeMs

HW decode can failed as well. It looks like tab.EvaluateJavaScript was stuck.

16:17:28 INFO | Restarting Chrome with flags and login
01:17:33 INFO | Invoking Oobe.loginForTesting
01:17:40 INFO | Browser is up!
16:17:46 ERROR| before evaluate. elapsed time=1
16:17:47 ERROR| len(decode_time_list)=1
16:17:48 ERROR| before evaluate. elapsed time=2
16:18:05 ERROR| len(decode_time_list)=2
16:18:05 INFO | (Re)starting the ui (logs the user out)
16:18:07 WARNI| 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 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/video_WebRtcPerf/video_WebRtcPerf.py", line 142, in run_once
    keyvals = self.test_decode_time(local_path)
  File "/usr/local/autotest/tests/video_WebRtcPerf/video_WebRtcPerf.py", line 327, in test_decode_time
    return self.test_webrtc(local_path, get_decode_time)
  File "/usr/local/autotest/tests/video_WebRtcPerf/video_WebRtcPerf.py", line 181, in test_webrtc
    result = gather_result(cr)
  File "/usr/local/autotest/tests/video_WebRtcPerf/video_WebRtcPerf.py", line 315, in get_decode_time
    raise error.TestError('Not enough ' + GOOG_MAX_DECODE_MS)
TestError: Not enough googMaxDecodeMs

I found Chrome was not responsive when the test was stuck. I tried to switch the tab when running tests. I added some logs and they should've been printed every second. When the log stopped, Chrome was not responsive.

Maybe this is related to http://crbug.com/588579. Some tpm commands caused chrome to freeze.

2016-05-20T16:42:47.887434+08:00 INFO kernel: [ 1603.750884] tpm_i2c_infineon 3-0020: command 0x46 (size 14) returned code 0x0
2016-05-20T16:42:47.961437+08:00 INFO kernel: [ 1603.822891] tpm_i2c_infineon 3-0020: command 0xb (size 36) returned code 0x0
2016-05-20T16:42:48.073434+08:00 ERR shill[983]: [ERROR:crypto_des_cbc.cc(103)] Unable to load key matter from /var/lib/whitelist/owner.key
2016-05-20T16:42:48.102148+08:00 ERR shill[983]: [ERROR:crypto_des_cbc.cc(103)] Unable to load key matter from /var/lib/whitelist/owner.key
2016-05-20T16:42:48.124794+08:00 INFO session_manager[21291]: [INFO:session_manager_impl.cc(355)] Starting user session
2016-05-20T16:42:48.898506+08:00 WARNING cryptohomed[20732]: Could not load the device policy file.
2016-05-20T16:42:53.644366+08:00 INFO session_manager[21291]: [INFO:child_exit_handler.cc(77)] Handling 21504 exit.
2016-05-20T16:42:53.762363+08:00 INFO session_manager[21291]: [INFO:policy_service.cc(174)] Persisted policy key to disk.
2016-05-20T16:42:53.765689+08:00 INFO chapsd[20723]: Waiting for private objects to be loaded.
2016-05-20T16:42:53.782226+08:00 INFO session_manager[21291]: [INFO:policy_service.cc(197)] Persisted policy to disk.
2016-05-20T16:42:53.931298+08:00 INFO session_manager[21291]: [INFO:child_exit_handler.cc(77)] Handling 21595 exit.
2016-05-20T16:42:53.931341+08:00 ERR session_manager[21291]: [ERROR:vpd_process_impl.cc(65)] No completion provided.
2016-05-20T16:43:27.986569+08:00 INFO kernel: [ 1643.850308] tpm_i2c_infineon 3-0020: command 0x1f (size 146) returned code 0x0
2016-05-20T16:43:28.041498+08:00 INFO kernel: [ 1643.903328] tpm_i2c_infineon 3-0020: command 0xba (size 18) returned code 0x22
2016-05-20T16:43:28.091461+08:00 INFO kernel: [ 1643.953015] tpm_i2c_infineon 3-0020: command 0x65 (size 18) returned code 0x0
2016-05-20T16:43:28.186618+08:00 INFO kernel: [ 1644.047691] tpm_i2c_infineon 3-0020: command 0x21 (size 14) returned code 0x0
2016-05-20T16:43:28.246485+08:00 INFO kernel: [ 1644.109314] tpm_i2c_infineon 3-0020: command 0xa (size 10) returned code 0x0
2016-05-20T16:43:28.296444+08:00 INFO kernel: [ 1644.157883] tpm_i2c_infineon 3-0020: command 0x65 (size 18) returned code 0x0
2016-05-20T16:43:28.706495+08:00 INFO kernel: [ 1644.567593] tpm_i2c_infineon 3-0020: command 0x1e (size 274) returned code 0x0
2016-05-20T16:43:28.711753+08:00 WARNING cryptohomed[20732]: RemoveKeyset: key to remove not found
2016-05-20T16:43:28.766455+08:00 INFO kernel: [ 1644.631517] tpm_i2c_infineon 3-0020: command 0x65 (size 42) returned code 0x0
2016-05-20T16:43:29.801540+08:00 INFO kernel: [ 1645.663586] tpm_i2c_infineon 3-0020: command 0x41 (size 618) returned code 0x0
2016-05-20T16:43:29.861492+08:00 INFO kernel: [ 1645.723069] tpm_i2c_infineon 3-0020: command 0xba (size 18) returned code 0x22
2016-05-20T16:43:29.865522+08:00 INFO chapsd[20723]: Finished importing 0 pending objects.
2016-05-20T16:43:29.866842+08:00 INFO chapsd[20723]: Done waiting for private objects.
2016-05-20T16:43:29.872237+08:00 INFO chapsd[20723]: Master key is ready for token at /home/root/f605bc3f0f7b54fd20be328246ab525fe5da27b5/chaps
2016-05-20T16:43:30.539807+08:00 INFO session_manager[21291]: [INFO:policy_service.cc(197)] Persisted policy to disk.
2016-05-20T16:43:31.672713+08:00 INFO session_manager[21291]: [INFO:child_exit_handler.cc(77)] Handling 21741 exit.
2016-05-20T16:43:31.757685+08:00 INFO session_manager[21291]: [INFO:policy_service.cc(197)] Persisted policy to disk.
2016-05-20T16:43:32.393304+08:00 INFO session_manager[21291]: [INFO:child_exit_handler.cc(77)] Handling 21833 exit.
2016-05-20T16:43:32.455629+08:00 NOTICE autotest[21920]: 16:43:32.425 ERROR|  video_WebRtcPerf:0305| before evaluate. elapsed time=1
2016-05-20T16:43:32.561023+08:00 NOTICE autotest[21922]: 16:43:32.521 ERROR|  video_WebRtcPerf:0310| len(decode_time_list)=0

Deleted: messages 390 KB

messages 390 KB View Download

I confirmed this is 588579. The fix is up. https://chromium-review.googlesource.com/#/c/346381/1

But this only affects Snow. I don't know what happened on Parrot and Zako.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/5e8e8cb4ce50f402bb7d9abb649844ddfaf0eb5b

commit 5e8e8cb4ce50f402bb7d9abb649844ddfaf0eb5b
Author: Wu-Cheng Li <wuchengli@chromium.org>
Date: Fri May 20 09:07:16 2016

video_WebRtcPerf: sleep 30 seconds after login on daisy.

On daisy, there is a bug that TPM commands take a long time to
finish and cause Chrome to freeze for ~30 seconds after login
using telemetry. Before 588579 is fixed, add the same workaround
in audio tests -- sleep 30 second after login on daisy.

BUG= chromium:604580 
TEST=video_WebRtcPerf passes on daisy.

Change-Id: Iad16550d80a13aa14fab61d23ca6d05e2a2b287e
Reviewed-on: https://chromium-review.googlesource.com/346381
Commit-Ready: Wu-cheng Li <wuchengli@chromium.org>
Tested-by: Wu-cheng Li <wuchengli@chromium.org>
Reviewed-by: Kuang-che Wu <kcwu@chromium.org>

[modify] https://crrev.com/5e8e8cb4ce50f402bb7d9abb649844ddfaf0eb5b/client/site_tests/video_WebRtcPerf/video_WebRtcPerf.py

The test is not failing for us on Parrot and Zako. Can we mark this as fixed Wu-cheng, or is there more work? If we expect to revert this once 588579 lands, let's file a separate bug as blocked on that issue.

We cam mark this as fixed. Matt. How did you see the test didn't fail on Parrot and Zako? I don't see Parrot and Zako on wmatrix for video_WebRtcPerf. I don't see the information on Crosbolt, either.

Wu-Cheng, video_WebRtcPerf is being run by the performance scheduler instead of the standard lab scheduler hence you are not seeing video_WebRtcPerf test runs on wmatrix.

https://dashboards.corp.google.com/#/google::_24290669_64f2_42e0_879d_a8bad4e190e?f=milestone:in:52&f=board:in:parrot,zako,daisy&f=status:in:ABORT,ERROR,FAIL,WARN,NO_RESULTS,GOOD&f=test:in:video_WebRtcPerf

Data is now coming in. Marking as verified. Thank you!