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

Issue 711400 link

Starred by 4 users

Issue metadata

Status: Fixed
Owner:
Closed: Apr 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Mac
Pri: 1
Type: Bug

Blocked on:
issue 711408



Sign in to add a comment

WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQuality* is failing on Mac

Project Member Reported by emir...@chromium.org, Apr 13 2017

Issue description

https://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)
 
Blockedon: 711408
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/

Comment 3 by thakis@chromium.org, 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?

Comment 4 Deleted

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).
Cc: phoglund@chromium.org emir...@chromium.org
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.
Summary: WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQuality* is failing on Mac Tester (build107-b1) (was: WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQuality* is failing on Win 8 (build107-b1))
corrected bot name
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.
Cc: henrika@chromium.org
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.
Cc: -phoglund@chromium.org grunell@chromium.org
Components: -Infra>Client>WebRTC
Owner: maxmorin@chromium.org
Status: Assigned (was: Available)
Summary: WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQuality* is failing on Mac (was: WebRtcVideoQualityBrowserTest.MANUAL_TestVideoQuality* is failing on Mac Tester (build107-b1))
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.

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 :).
The buffer is pretty large, iirc a second, and this likely happens during close/shutdown/etc. It would be good to know why.
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

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.
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.
Labels: OS-Mac
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.
Oops, I misread the error message. The 1 second or so buffer I mentioned is not the socket buffer. So ignore that comment.

Comment 19 by olka@chromium.org, 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?
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?

Comment 21 by olka@chromium.org, 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)

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.
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).
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.
I went ahead and clicked the box on the CL to disable the test (from #2) as my fix is still in review.
Project Member

Comment 26 by bugdroid1@chromium.org, 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

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.
Project Member

Comment 28 by bugdroid1@chromium.org, 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

Project Member

Comment 29 by bugdroid1@chromium.org, 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

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.
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?
I could repro this on my Macbook, so testing locally should be an option too.
Re #31: No there are no trybots that runs these tests, so you have to test locally.
Project Member

Comment 34 by bugdroid1@chromium.org, 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

Status: Fixed (was: Assigned)
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