WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQuality* is failing on Mac |
|||||||
Issue descriptionhttps://build.chromium.org/p/chromium.webrtc/builders/Mac%20Tester: It has been failing starting build #66925 6 tests produced excessive output: WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityH264/0 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343) WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityH264/1 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343) WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityVp8/0 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343) WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityVp8/1 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343) WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityVp9/0 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343) WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityVp9/1 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343)
,
Apr 13 2017
It looks restart won't help, see issue 711408. Here is a disable CL that would skip the tests until the issue is addressed: https://codereview.chromium.org/2821533002/
,
Apr 13 2017
Looks like the limit is somewhat new, https://codereview.chromium.org/2406243004 Is there some way to make these tests produce less output? What do they print when you run them locally?
,
Apr 13 2017
The output normally is not that much. See the below log for the section "RESULT Unique_frames_count". However, there is a lot of WARNING and INFO lines printed during the test. https://build.chromium.org/p/chromium.webrtc/builders/Mac%20Tester/builds/66924/steps/browser_tests/logs/stdio Here is the output from the failed ones. It seems to point at a different audio_sync_reader,\.cc error. Can this be related to an actual audio capture problem on the bots? kjellander@ and ehmaldonado@ can you PTAL? https://build.chromium.org/p/chromium.webrtc/builders/Mac%20Tester/builds/66925/steps/browser_tests/logs/stdio <truncated (2334432 bytes)> ARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:167947:0413/053436.627464:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:167947:0413/053436.627630:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:167947:0413/053436.637435:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:167947:0413/053436.637616:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:167947:0413/053436.647387:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:779:0413/053436.647450:WARNING:audio_auhal_mac.cc(464)] AU out: Total glitches=1. Total frames lost=480 (10 ms). [13902:167947:0413/053436.647564:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:167947:0413/053436.657360:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:167947:0413/053436.657473:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:167947:0413/053436.667373:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:167947:0413/053436.677453:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:167947:0413/053436.687459:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [13902:779:0413/053436.719637:WARNING:audio_auhal_mac.cc(464)] AU out: Total glitches=1. Total frames lost=480 (10 ms).
,
Apr 14 2017
Friendly ping. Can somebody from infra take a look into the possible audio issue here? I am still waiting for a stamp on the CL that disables the test for now.
,
Apr 17 2017
corrected bot name
,
Apr 18 2017
The bot is now also stuck offline, for which I reported bug 712522. Maybe these errors were related to those issues? Re #6: You don't need to wait for approval disabling a test - just TBR the CL.
,
Apr 18 2017
,
Apr 18 2017
I see the same today:
[ OK ] WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityVp9/1 (64874 ms)
[92/92] WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityVp9/1 (65162 ms)
6 tests produced excessive output:
WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityH264/0 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343)
WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityH264/1 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343)
WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityVp8/0 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343)
WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityVp8/1 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343)
WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityVp9/0 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343)
WebRtcVideoQualityBrowserTests/WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityVp9/1 (../../chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc:343)
<Thread(Thread-1, started 4392476672)> ProcessRead: proc.stdout finished.
<Thread(Thread-1, started 4392476672)> ProcessRead: cleaning up.
<Thread(Thread-2, started daemon 4396683264)> TimedFlush: Finished
<Thread(Thread-1, started 4392476672)> ProcessRead: finished.
,
Apr 18 2017
This also hit the chromium.webrtc.fyi bot, which went went red at the same time and then also got stuck offline (bug 687467). Good news is that I think I've found the culprit for this: it was tricky to find because we hit an edge case that Buildbot doesn't handle properly, which I filed bug 712543 for. In short, the builder hit compile failures in two builds, causing the tester blame list to be shorter than what it should have been: https://chromium.googlesource.com/chromium/src.git/+log/d3916f29a4b748b20d9de39d8655dc2c8c29e190..e87bbc88306d3bbac6249887d846077c8d0f923b That blame list makes me highly suspect https://codereview.chromium.org/2809673002 since there are many errors about audio_sync_reader.cc in the logs starting with the red build: [12777:157959:0413/053156.346395:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. Before, there were errors like these instead: [8716:158995:0413/022013.450529:WARNING:audio_sync_reader.cc(188)] AudioSyncReader::Read timed out, audio glitch count=2 [8716:158995:0413/022013.455776:WARNING:audio_sync_reader.cc(188)] AudioSyncReader::Read timed out, audio glitch count=1 I assume the change made the log spammier so we hit the log size limit for test output.
,
Apr 18 2017
Right. There is a cap on how many glitch messages are printed, but no corresponding cap for socket errors. Guess I could add one, but I'm curious about how the test is treating its audio stream to cause this log spam :).
,
Apr 18 2017
The buffer is pretty large, iirc a second, and this likely happens during close/shutdown/etc. It would be good to know why.
,
Apr 18 2017
Re #12-13: Please add log spam capping for all potential log-spamming code. The test is setting up a 1-1 call between two Chrome tabs and then captures video for post-test analysis. It's pretty straight forward and you can see the code here: https://cs.chromium.org/chromium/src/chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc
,
Apr 18 2017
It may be that the test somehow blocks a thread needed to send the "stream close" IPC message, but still destructs the AudioDeviceThread, closing the sync socket. I wrote https://codereview.chromium.org/2822123002/ to stop the log spam. That the ASR keeps trying after the remote end is gone is quite silly, I feel like the error should propagate somehow.
,
Apr 18 2017
Considering the "truncated (2334432 bytes)", it looks like about (2334432 bytes/101 bytes per line/100 lines per second)=220 seconds of broken audio, so I don't think it's just shutdown noise.
,
Apr 18 2017
Hmm, looking at the logs the OS stream (I suppose it is) sometimes calls OnMoreData several times per millisecond (timestamps are e.g. 054357.466845, 054357.466982). Curious.
,
Apr 18 2017
Oops, I misread the error message. The 1 second or so buffer I mentioned is not the socket buffer. So ignore that comment.
,
Apr 18 2017
Re #17: this may be due to rebuffering. Could you point to a log you refer to or add a larger piece here?
,
Apr 18 2017
The logs are from comment 5: https://build.chromium.org/p/chromium.webrtc/builders/Mac%20Tester/builds/66925/steps/browser_tests/logs/stdio and the relevant part of the log is: <truncated (2278453 bytes)> o room in socket buffer. [19193:158215:0413/054357.456888:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.457067:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.457178:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.466845:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.466982:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.476900:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.477061:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.486851:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.496885:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:779:0413/054357.496939:WARNING:audio_auhal_mac.cc(464)] AU out: Total glitches=1. Total frames lost=480 (10 ms). [19193:158215:0413/054357.497137:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.506815:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.516859:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:158215:0413/054357.526889:WARNING:audio_sync_reader.cc(180)] ASR: No room in socket buffer. [19193:779:0413/054357.562245:WARNING:audio_auhal_mac.cc(464)] AU out: Total glitches=1. Total frames lost=480 (10 ms). I don't think it's using rebuffering since audio_auhal_mac.cc reports that one glitch is 480 frames, which is 10 ms. I should however mention that I don't know the low-level mac code very well. The 054357.45**** frame get three calls. I don't see why we should sometimes need three calls and sometimes one, if it was rebuffering. Maybe it's resampling, but I don't think we ever use that for webrtc?
,
Apr 18 2017
Callback size may decrease on Mac if a (input or output) stream with a smaller buffer size joins. In such a case the FIFO is injected here: https://cs.chromium.org/chromium/src/media/audio/mac/audio_auhal_mac.cc?q=audio_auhal_mac.cc&dr&l=300 It can restore back if a stream with a smaller buffer size goes away. However, the FIFO will remain. The FIFO will be calling the render callback in a cycle until it has enough data: https://cs.chromium.org/chromium/src/media/base/audio_pull_fifo.cc?type=cs&l=37 In our case it's forever until it's deleted, because the socket is not functioning properly (shutting down?)(https://cs.chromium.org/chromium/src/content/browser/renderer_host/media/audio_sync_reader.cc?l=177)
,
Apr 18 2017
Re #8, thanks for the pointer, will TBR next time. Since there is an effort now about fixing the actual problem, I will not continue with the CL trying to disable it.
,
Apr 19 2017
Re #21, the sync reader doesn't actually handle the error, it just logs it. Later, in Read, it will fail to wait for data. However, there is no way for it to return less data than what is asked for, so it will zero the AudioBus instead (at https://cs.chromium.org/chromium/src/content/browser/renderer_host/media/audio_sync_reader.cc?l=200). Thus, the fifo shouldn't have problems getting data (except that it's all zero).
,
Apr 19 2017
The log in comment #20 does look surprising to me. I would expect two consecutive calls from time to time if rebuffering, but not three. I'm taking a deeper look into Mac audio in general and will look at this while doing so.
,
Apr 19 2017
I went ahead and clicked the box on the CL to disable the test (from #2) as my fix is still in review.
,
Apr 19 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/896daeca6982c6250e36660df8f957fbb01437b0 commit 896daeca6982c6250e36660df8f957fbb01437b0 Author: emircan <emircan@chromium.org> Date: Wed Apr 19 08:14:34 2017 Disable WebRtcVideoQualityBrowserTest on Mac BUG= 711400 Review-Url: https://codereview.chromium.org/2821533002 Cr-Commit-Position: refs/heads/master@{#465528} [modify] https://crrev.com/896daeca6982c6250e36660df8f957fbb01437b0/chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc
,
Apr 19 2017
OK, I figured out the timestamping, it's because they're from different streams. It's a p2p call between two tabs. Data is pulled on the same OS thread on Mac for all streams, hence the same thread id for all calls. So we can expect two calls every 10 ms (and an occasional extra due to rebuffering) and we also see when one stream is closed ("Total glitches" log) that only one call is made per 10 ms.
,
Apr 19 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/f38129c81c161fdd52874bf178b9110427a8c2ed commit f38129c81c161fdd52874bf178b9110427a8c2ed Author: maxmorin <maxmorin@chromium.org> Date: Wed Apr 19 13:32:55 2017 Avoid log spam in AudioSyncReader. When the remote socket has been closed, Send will always fail, leading to frequent logging. This change limits the logging to a maximum of one log call for the lifetime of the AudioSyncReader. One log should be enough, since the likely cause of the failure is that the remote socket is closed (and this condition cannot be fixed). The log call is also updated to display OS error information. Also includes corresponding changes in AudioInputSyncWriter. BUG= 711400 Review-Url: https://codereview.chromium.org/2822123002 Cr-Commit-Position: refs/heads/master@{#465578} [modify] https://crrev.com/f38129c81c161fdd52874bf178b9110427a8c2ed/content/browser/renderer_host/media/audio_input_sync_writer.cc [modify] https://crrev.com/f38129c81c161fdd52874bf178b9110427a8c2ed/content/browser/renderer_host/media/audio_input_sync_writer.h [modify] https://crrev.com/f38129c81c161fdd52874bf178b9110427a8c2ed/content/browser/renderer_host/media/audio_sync_reader.cc [modify] https://crrev.com/f38129c81c161fdd52874bf178b9110427a8c2ed/content/browser/renderer_host/media/audio_sync_reader.h
,
Apr 19 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/256eeddadb58f87e4be50dff04f81e3adf451a77 commit 256eeddadb58f87e4be50dff04f81e3adf451a77 Author: maxmorin <maxmorin@chromium.org> Date: Wed Apr 19 14:26:18 2017 Revert of Disable WebRtcVideoQualityBrowserTest on Mac (patchset #2 id:20001 of https://codereview.chromium.org/2821533002/ ) Reason for revert: Reenabling the test since the log spam is fixed. Original issue's description: > Disable WebRtcVideoQualityBrowserTest on Mac > > BUG= 711400 > > Review-Url: https://codereview.chromium.org/2821533002 > Cr-Commit-Position: refs/heads/master@{#465528} > Committed: https://chromium.googlesource.com/chromium/src/+/896daeca6982c6250e36660df8f957fbb01437b0 TBR=thakis@chromium.org,hbos@chromium.org,emircan@chromium.org BUG= 711400 Review-Url: https://codereview.chromium.org/2833453002 Cr-Commit-Position: refs/heads/master@{#465595} [modify] https://crrev.com/256eeddadb58f87e4be50dff04f81e3adf451a77/chrome/browser/media/webrtc/webrtc_video_quality_browsertest.cc
,
Apr 20 2017
Bot is green now. In the logs for this test (e.g. WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQualityH264/0 in https://build.chromium.org/p/chromium.webrtc/builders/Mac%20Tester/builds/67042/steps/browser_tests/logs/stdio) there are now four "ASR: No room in socket buffer.: Broken pipe" errors. Looks like the AudioDeviceThread is somehow destructed without the "stream closed" IPC message being sent. Might be an issue of the AudioOutputDevice being destructed without being Stop()ed first? Would be nice with a DCHECK for this.
,
Apr 20 2017
Wrote https://codereview.chromium.org/2828233002/ for the DCHECKs. Would be nice to run it on the previously failing bot before landing though. Anyone know if it's possible?
,
Apr 20 2017
I could repro this on my Macbook, so testing locally should be an option too.
,
Apr 20 2017
Re #31: No there are no trybots that runs these tests, so you have to test locally.
,
Apr 25 2017
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/63575c0e1d7b89a2658f34a07a6bb7ba3a3d1e97 commit 63575c0e1d7b89a2658f34a07a6bb7ba3a3d1e97 Author: maxmorin <maxmorin@chromium.org> Date: Tue Apr 25 06:24:26 2017 DCHECK that audio devices are stopped prior to destruction. This is required (and documented by a comment in the header file), so the DCHECKs are motivated. BUG= 711400 CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.android:android_optional_gpu_tests_rel;master.tryserver.chromium.linux:linux_optional_gpu_tests_rel;master.tryserver.chromium.mac:mac_optional_gpu_tests_rel;master.tryserver.chromium.win:win_optional_gpu_tests_rel Review-Url: https://codereview.chromium.org/2828233002 Cr-Commit-Position: refs/heads/master@{#466898} [modify] https://crrev.com/63575c0e1d7b89a2658f34a07a6bb7ba3a3d1e97/media/audio/audio_input_device.cc [modify] https://crrev.com/63575c0e1d7b89a2658f34a07a6bb7ba3a3d1e97/media/audio/audio_input_device_unittest.cc [modify] https://crrev.com/63575c0e1d7b89a2658f34a07a6bb7ba3a3d1e97/media/audio/audio_output_device.cc [modify] https://crrev.com/63575c0e1d7b89a2658f34a07a6bb7ba3a3d1e97/media/audio/audio_output_device_unittest.cc
,
Apr 25 2017
https://build.chromium.org/p/chromium.webrtc.fyi/builders/Mac%20Tester/builds/39137 checks doesn't seem to fire, so I'm out of ideas for what would cause this. I'll just go ahead and close this bug since the original issue is fixed. |
|||||||
►
Sign in to add a comment |
|||||||
Comment 1 by emir...@chromium.org
, Apr 13 2017