This is hung waiting for device information from the browser side. I thought we had a timeout cap on this now olka?

Not on Mac. Device authorization timeout is Windows-only at the moment.

I haven't found any crash reports for that - did I miss anything?
And are we sure there are only 2 threads participating?

This was on my machine. It got the "tab not responding" notification, but I told it to keep waiting so I could get a sample. I guess that prevents a crash reports from being emitted. 

Oops, though I had attached the full trace.

Deleted: gmail_renderer_deadlock.txt 80.0 KB

gmail_renderer_deadlock.txt 80.0 KB View Download

This happened to me again. This time, I hit the "kill" button, but to my surprise, no crash report was generated. mark@, shouldn't that generate a crash report accessible via either chrome://crashes or "~/Library/Application\ Support/Google/Chrome\ Canary/Crashpad/"?

No, that’s expected. Kills aren’t crashes.

erikchen@ - thank you.
I guess I'll enable authorization timeout on Linux.

dalecurtis@ - taking into account (a) the discussion in another thread about pipeline error growth due to authorization timing out and (b) the fact that this hang does not seem to be a common thing on Mac, I feel reluctant introducing authorization timeout on Mac for now. According to the stats we have 0.2% of authorizations taking longer than a second. I suspect we will cut off more healthy audio cases then we fix renderer hang cases by that timeout.
I would say that this hang "works as intended" for now. We should revisit it if we see more hangs like that. WDYT?

Why not just have the timeout set to lower than the normal-renderer-hang case? IIRC there's two time outs depending on the situation, one lower and one higher. We don't see many crashes on OSX, so using some value between (low, high) seems a happy middle ground.

Apologies if I'm misremembering something.

Please clarify: I ran across this issue twice, and no amount of waiting fixed the issue. That implies that there's something "wrong", right? Using a timeout is only a workaround. Who would be a good person to look into the underlying issue?

When you run into a renderer crash like this, force a browser crash and report the id along with the bug. This generally means the browser audio thread is hung waiting on some OS level operation.

In all recent cases such hangs have been due to some underlying driver or 3rd party software issue. Capturing the browser crash will help us narrow it down.

Issue 646914 has been merged into this issue.

I think it's correct to not report a crash report if the user does a process termination via task manager, but I think if the user gets a hung tab such as this, and pushes the kill button, that a crash report should be generated, given in this case it sounds like Chrome was legitimately hung doing some processing, and we are interested in this data, and it also appears in all our UMA stability data.

I can confirm that at least on Windows that clicking Kill in the unresponsive renderer dialog generates a crash. Here's chrome://hang -> Kill crash/d1bfa7fd00000000.

I don't recall off the top of my head if that might be Windows-only for some reason though?

hmm I was able to reproduce a hang on Windows from chrome://hang and click 'kill' and get a crash report so this might be another issue. Unduping to investigate further.

It took several minutes, but I was eventually able to get chrome://hang to register as a hang. I pressed the "kill" button but no crash was generated.

okay I've created a new bug to track this, since we should at least have parity across the platforms. I think we should get a report for a kill from that dialog. issue 649744.

Changed the bug name (no deadlock is observed on renderer side, it just waits forever for a message from the browser)

Do I get it correctly that we don't have any "render hang" crashes on Mac/Linux because of #19?

I.e. which statement is correct: (1) we don't have renderer hangs in GetOutputDeviceInfo() on Mac/Linux, or (2) we don't know if we have them?


Numbers re: #10 

I see these timeout values used:
kHungRendererDelayMs = 30000
(https://cs.chromium.org/chromium/src/content/common/content_constants_internal.cc?cl=GROK&rcl=1475220003&l=16)

kNewContentRenderingDelayMs = 4000
(https://cs.chromium.org/chromium/src/content/common/content_constants_internal.cc?cl=GROK&rcl=1475220003&l=19)

RenderViewHostImpl::kUnloadTimeoutMS = 1000
(https://cs.chromium.org/chromium/src/content/browser/renderer_host/render_view_host_impl.cc?cl=GROK&rcl=1475220003&l=204)

On Windows authorization timeout value is 1000; plus something adds up on the way (and it may be quite a lot for JavaScript). We still see render hangs on device authorization (but much less of those than before authorization timeout).

Friendly ping to get an update on this issue as per C#22.

Gentlt ping for an update.

wfh@ could you please answer #22?

Authorization timeout is a compromise between having a hang and having no audio in healthy cases. So, to go for it, I'd like to understand what is the current situation with hangs.

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

commit fa7d7d9413d0e3324e25cdb8d67ed87cf7f94acd
Author: olka <olka@chromium.org>
Date: Mon Oct 17 17:21:23 2016

Setting device authorization timeout to 2000 ms on MAC
Since we don't know the exact situation with renderer hangs due to device
authorization timeout (https://bugs.chromium.org/p/chromium/issues/detail?id=649744), setting the timeout to accomodate
99.9% of all the authorization times

BUG=647498

Review-Url: https://codereview.chromium.org/2429433002
Cr-Commit-Position: refs/heads/master@{#425709}

[modify] https://crrev.com/fa7d7d9413d0e3324e25cdb8d67ed87cf7f94acd/content/renderer/media/audio_device_factory.cc

I ran into this problem again. Got a sample of the renderer & browser, and also forced the browser to crash:

ID: crash/ff4ac52b00000000

Looked through the threads in the browser crash and didn't see a hung audio thread. 

Deleted: renderer_stack_trace.txt 82.1 KB

renderer_stack_trace.txt 82.1 KB View Download

Deleted: browser_sample.txt 272 KB

browser_sample.txt 272 KB View Download

In the renderer stack, it looks like the Media pipeline thread is waiting in media::AudioOutputDevice::GetOutputDeviceInfo(), and the main thread is blocked on the PipelineImpl lock.

Thank you erikchen@!

The situation looks the same as Issue 617615, which was know to be Windows-only (probably, becasue of Issue 649744).
My recent CL (#27) introduces device authorization timeout on Mac, which should unblock media::AudioOutputDevice::GetOutputDeviceInfo() (this is the same approach we take on Windows).

The fact that we are having the same problem on Mac makes me suspect that it may be caused by our browser side rather than a driver.
(Unfortunately, browser_sample does not tell me much).

Marking "blocked on" issue 649744, because we don't have a clear picture of render hangs on Mac/Linux for analysis.

See also Issue 645946 - might be related.

Stats show 0.15% of timeouts (999 out of 650,791 authorizations).
(https://uma.googleplex.com/p/chrome/histograms/?endDate=latest&dayCount=1&histograms=Media.Audio.OutputDeviceAuthorizationTime%2CMedia.Audio.Render.OutputDeviceAuthorizationTimedOut&fixupData=true&showMax=true&filters=platform%2Ceq%2CM%2Cchannel%2Ceq%2C1%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial)

dalecurtis@ WDYT? Do we want to merge this to M55, taking into account we don't have crash info?

I'd let this soak for a bit more. We are seeing YouTube/Netflix error rates increase due to these timeouts. Likely these are previously unseen hangs, but still worrying. 

Gentle Ping, Do we have any update on this issue. Please help us with steps , incase if this require any verification from TE team.

Thanks.!

The mitigating change landed October 17th (56.0.2895.0 Canary/56.0.2895.3 Dev). We'll wait a bit more to have at least a week of stats to look at. 

**** Bulk edit -  please ignore if not applicable ****

A friendly reminder that M55 Stable is launch is coming soon! Your bug is labelled as Stable ReleaseBlock, pls make sure to land the fix and get it merged into the release branch ASAP so it gets enough baking time in Beta (before Stable promotion). Thank you!

0.45% of authorizations hit time out, media pipeline error is at 0.05% (aggregated for all versions starting 56.0.2895.0 on Mac).

dalecurtis@ - does this level of pipeline errors look fine?

Hard to say, we need to know the rate of true hangs to make the determination of what an okay rate is. Is there a way we can log "never recovered vs was hung but eventually recovered" type UMA?

**** Bulk edit -  please ignore if not applicable ****

A friendly reminder that M55 Stable is launch is coming soon! Your bug is labelled as Stable ReleaseBlock, pls make sure to land the fix and get it merged into the release branch ASAP so it gets enough baking time in Beta (before Stable promotion). Thank you!

re:41 I'm not exactly sure what you mean?
I saw there is Media.AudioThreadStatus UMA recorded by hang monitor, but hand monitor is disabled on Mac for some reason
(https://cs.chromium.org/chromium/src/content/browser/renderer_host/render_process_host_impl.cc?sq=package:chromium&rcl=1477984636&l=832)
We can also see how may authorizations exceed the timeout threshold (2000ms) in Media.Audio.OutputDeviceAuthorizationTime.

(something like 0.4% of authorizations take longer than 2000ms)

That's because on OSX the audio thread is the UI thread. So the only time we should truly have an device authorization timeout is if the entire browser is hung. Given that, it's actually surprising that the original report here states that the everything else in the browser was working fine except for this tab. That would indicate that we have a bug in device authorization somewhere which is causing the authorization to be dropped somehow or to get into some other deadlock'd state.

Have you tried reproducing the issue around sleep/resume on a mac as was originally described?

I see, so Issue 645946 is an example of audio thread hang, and this one does look like authorization bug. This part has been recently (and is still being) refactored though. I'm looking into it now.

Oh I have not realized that I may try it! Working on that.

olka@, any update on this as we are getting closer to M55 stable launch.

Thank you.

**** Bulk edit -  please ignore if not applicable ****

A friendly reminder that M55 Stable is launch is coming soon! Your bug is labelled as Stable ReleaseBlock, pls make sure to land the fix and get it merged into the release branch ASAP so it gets enough baking time in Beta (before Stable promotion). Thank you!

Also due to Thanksgiving holidays in US, please make sure all fixes are ready and merged to M55 latest by 5:00 PM PT Friday, 11/18/16.

No news so far. I'm trying to track down if we have any authorization bag causing this.

+guidou@ for device authorization

It seems that there is not enough data to properly understand where the hang occurs.
If it happens with any significant frequency, then the problem is most likely caused with requests for the default device and the hang probably occurs when reading device parameters.

For nondefault devices there are two additional steps where a hang could occur: 1) a device enumeration performed in order to translate the hashed device ID sent by the renderer and 2) a check to verify if the requesting origin has permission to access the requested device. Hangs due to these should be a lot less frequent since few applications use nondefault devices.

If we are unable to reproduce this problem, I think we should not block the stable release due to this. Instead we should wait for more reports to see how frequent this problem is.

1) What can we do to provide more information when this problem occurs?

2) What can we do to get more information about the prevalence of this problem? e.g. Is there some UMA metric we can emit from the browser that would give us some insight?

At this point, it seems too late to merge a fix to M55, if we could even find the issue. Removing RB-S.

I've had this hang issue happening for months.  On application load then visiting gmail I get a beachball for 15-20 seconds.  The dtruss trace has this in a loop during the hang:

select(0xFD, 0x7000151DE370, 0x0, 0x0, 0x7000151DE3F0)		 = 1 0
ioctl(0xFC, 0x4004667F, 0x7000151DE354)		 = 0 0
read(0xFC, "M\002\0", 0x4)		 = 4 0
fcntl(0xFC, 0x3, 0x4)		 = 2 0
fcntl(0xFC, 0x4, 0x6)		 = 0 0
write(0xFC, "\307A\0", 0x4)		 = 4 0
fcntl(0xFC, 0x4, 0x2)		 = 0 0
select(0xFD, 0x7000151DE370, 0x0, 0x0, 0x7000151DE3F0)		 = 1 0
ioctl(0xFC, 0x4004667F, 0x7000151DE354)		 = 0 0
read(0xFC, "N\002\0", 0x4)		 = 4 0
fcntl(0xFC, 0x3, 0x4)		 = 2 0
fcntl(0xFC, 0x4, 0x6)		 = 0 0
write(0xFC, "\310A\0", 0x4)		 = 4 0
fcntl(0xFC, 0x4, 0x2)		 = 0 0
select(0xFD, 0x7000151DE370, 0x0, 0x0, 0x7000151DE3F0)		 = 1 0
ioctl(0xFC, 0x4004667F, 0x7000151DE354)		 = 0 0
read(0xFC, "O\002\0", 0x4)		 = 4 0
fcntl(0xFC, 0x3, 0x4)		 = 2 0
fcntl(0xFC, 0x4, 0x6)		 = 0 0
write(0xFC, "\326A\0", 0x4)		 = 4 0
fcntl(0xFC, 0x4, 0x2)		 = 0 0
select(0xFD, 0x7000151DE370, 0x0, 0x0, 0x7000151DE3F0)		 = 1 0
ioctl(0xFC, 0x4004667F, 0x7000151DE354)		 = 0 0
read(0xFC, "P\002\0", 0x4)		 = 4 0
fcntl(0xFC, 0x3, 0x4)		 = 2 0
fcntl(0xFC, 0x4, 0x6)		 = 0 0
write(0xFC, "\343A\0", 0x4)		 = 4 0
fcntl(0xFC, 0x4, 0x2)		 = 0 0
__semwait_signal(0x903, 0x0, 0x1)

+anthony.lauzon@gmail.com: which Chrome version are you at now? And are you on Mac? Thanks.

Re #52:

1) This might be helpful:
(a) run Chrome with
--enable-logging=stderr --vmodule=*audio*=1,*device*=1 > logging.txt 2>&1
(where "logging.txt" is your file of choice) and grab that log upon gmail tab hang occurs.
(b) (even if you do not do (a)): Grab content of "chrome://histograms/" tab.


2) We need Issue 649744 to be fixed to know how often it occurs. For now we are not getting any reports on it for Mac.

Sorry, correction to #55:

(a) run Chrome with
--enable-logging=stderr --v=1 > logging.txt 2>&1

Something confuses me in #28 traces.
Thread_336253, which seems to be main one, has this:

2566 content::ResourceDispatcher::OnMessageReceived(IPC::Message const&)  (in Google Chrome Framework)  load address 0x10fb76000 + 0x3decd10  [resource_dispatcher.cc:187]
    +                                                   2566 content::ResourceDispatcher::DispatchMessage(IPC::Message const&)  (in Google Chrome Framework)  load address 0x10fb76000 + 0x3ded444  [resource_dispatcher.cc:572]
    +                                                     2566 bool IPC::MessageT<ResourceMsg_DataReceived_Meta, std::__1::tuple<int, int, int, int, int>, void>::Dispatch...


-- Not sure if it's normal for the main thread to receive IPC messages? I thought it happens on IO thread only.
Or is (main thread == IO thread here)? (In this case we are having a deadlock, because this thread is waiting for a lock which should be released upon authorization is received on IO thread).

I got a bit lost in tracking that renderer threading.

+yhirano@ (who seems to have done a lot of work on ResourceDispatcher) could you comment on #57?

Re #55:

I'm using a mac, and here is the log when the beachball occurs:
1829:775:1109/114212:VERBOSE1:service_discovery_device_lister.cc(39)] DeviceListerStart: service_type: _privet._tcp.local
[1829:775:1109/114212:VERBOSE1:service_discovery_device_lister.cc(44)] DiscoverNewDevices: service_type: _privet._tcp.local
[1829:39171:1109/114216:ERROR:backend_impl.cc(1033)] Critical error found -8
[1829:39171:1109/114216:ERROR:entry_impl.cc(1039)] No file for c1030024
[1884:16931:1109/114223:WARNING:audio_output_device.cc(316)] Output device authorization timed out

Thank you. Could you upload the full log and chrome://histograms content? And which chrome version is that? (I'm guessing it's some dev or canary)

See https://bugs.chromium.org/p/chromium/issues/detail?id=359589

re #61: That's an old one. Device thread is UI thread on Mac now. If it deadlocks the whole browser stops working. See #45-46.

Could you provide the info per #60? Thank you!

re: #57

> Or is (main thread == IO thread here)?
No, they are different threads.

> Not sure if it's normal for the main thread to receive IPC messages? I thought it happens on IO thread only.

IPC messages are routed to the main thread from the IO thread. Resource messages are handled in a bit more complicated way than others due to ResourceSchedulingFilter, but I guess it's not related with this issue.

Thanks you anothony.lauzon@
Histograms show that there was a device authorization which took over 5 seconds:
Histogram: Media.Audio.OutputDeviceAuthorizationTime recorded 2 samples, mean = 4938.0 (flags = 0x1)
0     ...
34    ------------------------------------------------------------------------O (1 = 50.0%) {0.0%}
40    ...
5000  ------------------------------------------------------------------------O (1 = 50.0%) {50.0%}

yhirano@ thank you. So, do I get it correctly that resources messages never block IO thread?

> #66

I think so.

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

commit 8be2e3fd36fb909ba695c0bd84ef9f97d3855ac3
Author: dalecurtis <dalecurtis@chromium.org>
Date: Thu Nov 24 19:36:54 2016

Remove unnecessary lock on setClient().

The lock is unnecessary because the operation is a no-op
when client is unchanged (the vast majority of cases).

BUG=615589,647498
TEST=none

Review-Url: https://codereview.chromium.org/2527813002
Cr-Commit-Position: refs/heads/master@{#434380}

[modify] https://crrev.com/8be2e3fd36fb909ba695c0bd84ef9f97d3855ac3/media/blink/webaudiosourceprovider_impl.cc

See update https://bugs.chromium.org/p/chromium/issues/detail?id=615589#c97 - the same holds true here. olka@ are reports of this high enough that we need to merge this back to M55 prior to stable?

I'm not sure how to define what is high enough. It's 0.05-0.1% of the crashes on dev.
We have multiple bugs those look related, and the change is safe. So I think it worth merging.

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

commit b9b58bdcc7d2914fe016f839751b11149e9f500e
Author: Dale Curtis <dalecurtis@chromium.org>
Date: Tue Nov 29 20:56:20 2016

Merge M56: "Remove unnecessary lock on setClient()."

The lock is unnecessary because the operation is a no-op
when client is unchanged (the vast majority of cases).

BUG=615589,647498
TEST=none

Review-Url: https://codereview.chromium.org/2527813002
Cr-Commit-Position: refs/heads/master@{#434380}
(cherry picked from commit 8be2e3fd36fb909ba695c0bd84ef9f97d3855ac3)

Review URL: https://codereview.chromium.org/2539773003 .

Cr-Commit-Position: refs/branch-heads/2924@{#167}
Cr-Branched-From: 3a87aecc31cd1ffe751dd72c04e5a96a1fc8108a-refs/heads/master@{#433059}

[modify] https://crrev.com/b9b58bdcc7d2914fe016f839751b11149e9f500e/media/blink/webaudiosourceprovider_impl.cc

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

commit 1e29e41f663761f2447030dbdf7e45ea9179ed7a
Author: dalecurtis <dalecurtis@chromium.org>
Date: Tue Nov 29 22:14:51 2016

Clarify thread safety of WebAudioSourceProvider interface.

Update documentation to reflect current usage.

BUG=615589,647498
TEST=none

Review-Url: https://codereview.chromium.org/2536033003
Cr-Commit-Position: refs/heads/master@{#435090}

[modify] https://crrev.com/1e29e41f663761f2447030dbdf7e45ea9179ed7a/third_party/WebKit/public/platform/WebAudioSourceProvider.h

Output device info is requested on the main render thread for WebRTC playback, and it gets blocked until device authorization is received. On Mac it may take quite a long time, especially if it happens around system suspend/resume.
Render thread becomes unresponsive, browser notifications pile up, browser does not receive acknowledgments in time and considers the situation as a renderer hang.
Render thread should not be blocked waiting for device authorizations.

Reproduced with Chromium 58.0.3029.81 on Gentoo Linux - stack trace at https://pastebin.com/0kaW5JGg .
Cannot reproduce at will, but it's not super-rare here, and annoyed me enough to switched to Chromium from Chrome in order to have debug symbols and be able to have a stack trace for a meaningful report.

This specific bug is for Mac, and we have a similar problem for Win; but this is the first time we are getting a report on Linux.

Very useful, thanks maxximino@!

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

commit 7d472f296e715c26fa1dbe8295b607421319c53f
Author: olka <olka@chromium.org>
Date: Thu May 04 11:10:35 2017

Introducing audio output device authorization timeout for Linux.

The outcome is: if device authorization for a renderer is taking too long
it will be interupted. Page load will continue normally, some of the audio
playback on it may not work.

BUG=647498

Review-Url: https://codereview.chromium.org/2862823002
Cr-Commit-Position: refs/heads/master@{#469308}

[modify] https://crrev.com/7d472f296e715c26fa1dbe8295b607421319c53f/content/renderer/media/audio_device_factory.cc

Thanks olka! I've rebuilt Chromium 59.0.3071.29 with your patch and made sure that portage will apply it for future updates, if the problem shows up again I'll report in the bug.