Bug 496281
| Summary: | PA backend of XINE has issues | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | David Woodhouse <dwmw2> | ||||||
| Component: | xine-lib | Assignee: | Lennart Poettering <lpoetter> | ||||||
| Status: | CLOSED WONTFIX | QA Contact: | Fedora Extras Quality Assurance <extras-qa> | ||||||
| Severity: | medium | Docs Contact: | |||||||
| Priority: | low | ||||||||
| Version: | 11 | CC: | ajschult784, beland, gauret, kevin, lkundrak, lpoetter, rdieter, wtogami | ||||||
| Target Milestone: | --- | ||||||||
| Target Release: | --- | ||||||||
| Hardware: | All | ||||||||
| OS: | Linux | ||||||||
| URL: | http://bugs.xine-project.org/show_bug.cgi?id=301 | ||||||||
| Whiteboard: | |||||||||
| Fixed In Version: | Doc Type: | Bug Fix | |||||||
| Doc Text: | Story Points: | --- | |||||||
| Clone Of: | Environment: | ||||||||
| Last Closed: | 2010-06-28 11:52:53 UTC | Type: | --- | ||||||
| Regression: | --- | Mount Type: | --- | ||||||
| Documentation: | --- | CRM: | |||||||
| Verified Versions: | Category: | --- | |||||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||||
| Embargoed: | |||||||||
| Attachments: |
|
||||||||
|
Description
David Woodhouse
2009-04-17 15:58:35 UTC
Run pulseaudio -vvvv in a terminal (kill it first with pulseaudio -k). That will spit out a lot of debug output and should give you a hint of what's going on. If you cannot make sense of it paste it here. When I kill pulseaudio and restart it, the panel applet and volume/mute hotkeys stop working in my gnome session. I've just had this happen again with the flash player. First it just wasn't appearing in the list of applications in the new lobotomised gnome-volume-control. I tried closing the tab in firefox, and firefox locked up without redrawing itself for a minute or so. Opening the same page in a new tab, it _did_ manage to connect to PA but started up muted. I'll attach pulseaudio -vvvvv output from that run. Created attachment 341361 [details]
pulseaudio output
This shows the flash player starting up muted.
There's no interesting output from pulseaudio -vvvvv when it just fails to connect. Perhaps unsurprisingly. How do we go about debugging that? I can reproduce the silent failure mode by killing pulseaudio and restarting it, while the flash player is on the screen. So maybe the first time it happened it was because pulseaudio had crashed? After that, I don't get sound again until I close the tab -- and that long wait on exit seems to be because it's waiting for a futex. I'd suggest it could be a bug with failing to try to reconnect to pulse after pulse goes away.... but when this was happening to xine, it was at xine startup. Debugging closed source software is always pain. What I saw from the sources of Flash 9 showed me their audio backend was incredibly racey. I doubt that changed with Flash 10. So I am not surprised if it locks up, even though it might be PA that plays a role here. Which version of Flash are you using btw? PA saves and restores the volume settings for each client. If you mute Flash in pavucontrol and then restart Flash it will be muted again. Or are you saying you closed an unmuted Flash and when it came back it was muted? Is it possible to enable a more verbose debug mode in xine some way? Can you reproduce this with mplayer? It is much more verbose by default. It's flash 10. I don't think I've seen the long delay on exit with other software, so perhaps we can ignore that -- although it definitely only happens when it's failed to connect to pulseaudio. I've certainly never muted flash in pavucontrol, or muted any of the other software that comes up muted. Yes, I closed an unmuted flash (and xine) and they came back muted. Or didn't come back at all, at various times. I'll try to get more verbose debugging output from xine for each case. The one where it fails to connect is hard, since every time I'm paying attention, it works. This is the output from pulseaudio when I start xine and the audio is garbled and skipping... I: client.c: Created 76 "Native client (UNIX socket client)" D: protocol-native.c: Protocol version: remote 15, local 15 I: protocol-native.c: Got credentials: uid=500 gid=500 success=1 D: protocol-native.c: SHM possible: yes D: protocol-native.c: Negotiated SHM: yes D: module-augment-properties.c: Looking for .desktop file for xine I: client.c: Freed 76 "ALSA plug-in [xine]" I: protocol-native.c: Connection died. I: client.c: Created 77 "Native client (UNIX socket client)" D: protocol-native.c: Protocol version: remote 15, local 15 I: protocol-native.c: Got credentials: uid=500 gid=500 success=1 D: protocol-native.c: SHM possible: yes D: protocol-native.c: Negotiated SHM: yes D: module-augment-properties.c: Looking for .desktop file for xine I: client.c: Freed 77 "ALSA plug-in [xine]" I: protocol-native.c: Connection died. I: client.c: Created 78 "Native client (UNIX socket client)" D: protocol-native.c: Protocol version: remote 15, local 15 I: protocol-native.c: Got credentials: uid=500 gid=500 success=1 D: protocol-native.c: SHM possible: yes D: protocol-native.c: Negotiated SHM: yes D: module-augment-properties.c: Looking for .desktop file for xine I: client.c: Freed 78 "ALSA plug-in [xine]" I: protocol-native.c: Connection died. I: client.c: Created 79 "Native client (UNIX socket client)" D: protocol-native.c: Protocol version: remote 15, local 15 I: protocol-native.c: Got credentials: uid=500 gid=500 success=1 D: protocol-native.c: SHM possible: yes D: protocol-native.c: Negotiated SHM: yes D: module-augment-properties.c: Looking for .desktop file for xine I: client.c: Created 80 "Native client (UNIX socket client)" D: protocol-native.c: Protocol version: remote 15, local 15 I: protocol-native.c: Got credentials: uid=500 gid=500 success=1 D: protocol-native.c: SHM possible: yes D: protocol-native.c: Negotiated SHM: yes D: module-augment-properties.c: Looking for .desktop file for xine I: alsa-sink.c: Trying resume... D: alsa-util.c: Maximum hw buffer size is 23777 ms D: alsa-sink.c: hwbuf_unused=0 D: alsa-sink.c: setting avail_min=84400 I: alsa-sink.c: Resumed successfully... I: alsa-sink.c: Starting playback. D: alsa-sink.c: Cutting sleep time for the initial iterations by half. D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes idle. D: alsa-sink.c: Cutting sleep time for the initial iterations by half. D: alsa-sink.c: Cutting sleep time for the initial iterations by half. D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes busy. D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0 D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0 I: sink-input.c: Created input 201 "ALSA Playback" on alsa_output.pci_8086_284b_sound_card_0 with sample spec s16le 2ch 44100Hz and channel map front-left,front-right I: protocol-native.c: Requested tlength=999.91 ms, minreq=124.99 ms D: protocol-native.c: Early requests mode enabled, configuring sink latency to minreq. D: alsa-sink.c: Cutting sleep time for the initial iterations by half. D: alsa-sink.c: Cutting sleep time for the initial iterations by half. D: memblockq.c: memblockq requested: maxlength=4194304, tlength=176384, base=4, prebuf=154336, minreq=22048 maxrewind=0 D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=176384, base=4, prebuf=154336, minreq=22048 maxrewind=0 I: protocol-native.c: Final latency 1124.90 ms = 749.93 ms + 2*124.99 ms + 124.99 ms D: alsa-sink.c: Requested volume: 0: 100% 1: 100% D: alsa-sink.c: Got hardware volume: 0: 100% 1: 100% D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% D: alsa-sink.c: Cutting sleep time for the initial iterations by half. D: alsa-sink.c: Latency set to 124.99ms D: alsa-sink.c: hwbuf_unused=330724 D: alsa-sink.c: setting avail_min=84401 D: alsa-sink.c: Requesting rewind due to latency change. D: alsa-sink.c: Requested to rewind 352768 bytes. D: alsa-sink.c: Limited to 337344 bytes. D: alsa-sink.c: before: 84336 D: alsa-sink.c: after: 84336 D: alsa-sink.c: Rewound 337344 bytes. D: sink.c: Processing rewind... D: sink-input.c: Have to rewind 337344 bytes on render memblockq. D: source.c: Processing rewind... D: core-subscribe.c: Dropped redundant event due to change event. D: protocol-native.c: Requesting rewind due to end of underrun. D: alsa-sink.c: Requested to rewind 352768 bytes. D: alsa-sink.c: Limited to 3580 bytes. D: alsa-sink.c: before: 895 D: alsa-sink.c: after: 895 D: alsa-sink.c: Rewound 3580 bytes. D: sink.c: Processing rewind... D: sink-input.c: Have to rewind 3580 bytes on render memblockq. D: source.c: Processing rewind... D: sink-input.c: Requesting rewind due to corking D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes idle. D: alsa-sink.c: Requested volume: 0: 100% 1: 100% D: alsa-sink.c: Got hardware volume: 0: 100% 1: 100% D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% D: alsa-sink.c: hwbuf_unused=0 D: alsa-sink.c: setting avail_min=84400 D: alsa-sink.c: Requested to rewind 352768 bytes. D: alsa-sink.c: Limited to 4028 bytes. D: alsa-sink.c: before: 1007 D: alsa-sink.c: after: 1007 D: alsa-sink.c: Rewound 4028 bytes. D: sink.c: Processing rewind... D: source.c: Processing rewind... D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes idle. I: sink-input.c: Freeing input 201 "ALSA Playback" D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes busy. D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0 D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0 I: sink-input.c: Created input 202 "ALSA Playback" on alsa_output.pci_8086_284b_sound_card_0 with sample spec s16le 2ch 44100Hz and channel map front-left,front-right I: protocol-native.c: Requested tlength=999.91 ms, minreq=124.99 ms D: protocol-native.c: Early requests mode enabled, configuring sink latency to minreq. D: memblockq.c: memblockq requested: maxlength=4194304, tlength=176384, base=4, prebuf=154336, minreq=22048 maxrewind=0 D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=176384, base=4, prebuf=154336, minreq=22048 maxrewind=0 I: protocol-native.c: Final latency 1124.90 ms = 749.93 ms + 2*124.99 ms + 124.99 ms D: alsa-sink.c: Requested volume: 0: 100% 1: 100% D: alsa-sink.c: Got hardware volume: 0: 100% 1: 100% D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% D: alsa-sink.c: Latency set to 124.99ms D: alsa-sink.c: hwbuf_unused=330724 D: alsa-sink.c: setting avail_min=84401 D: alsa-sink.c: Requesting rewind due to latency change. D: alsa-sink.c: Requested to rewind 352768 bytes. D: alsa-sink.c: Limited to 335232 bytes. D: alsa-sink.c: before: 83808 D: alsa-sink.c: after: 83808 D: alsa-sink.c: Rewound 335232 bytes. D: sink.c: Processing rewind... D: sink-input.c: Have to rewind 335232 bytes on render memblockq. D: source.c: Processing rewind... D: sink-input.c: Requesting rewind due to corking D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes idle. D: alsa-sink.c: Requested volume: 0: 100% 1: 100% D: alsa-sink.c: Got hardware volume: 0: 100% 1: 100% D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% D: alsa-sink.c: hwbuf_unused=0 D: alsa-sink.c: setting avail_min=84400 D: alsa-sink.c: Requested to rewind 352768 bytes. D: alsa-sink.c: Limited to 6460 bytes. D: alsa-sink.c: before: 1615 D: alsa-sink.c: after: 1615 D: alsa-sink.c: Rewound 6460 bytes. D: sink.c: Processing rewind... D: source.c: Processing rewind... D: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 becomes idle. I: sink-input.c: Freeing input 202 "ALSA Playback" I: client.c: Freed 80 "ALSA plug-in [xine]" I: protocol-native.c: Connection died. I: client.c: Freed 79 "ALSA plug-in [xine]" I: protocol-native.c: Connection died. I: module-suspend-on-idle.c: Sink alsa_output.pci_8086_284b_sound_card_0 idle for too long, suspending ... I: alsa-sink.c: Device suspended... xine says... video_out_xshm: tried to set unsupported property 0 load_plugins: plugin theora will be used for video streamtype 3e. load_plugins: plugin vorbis will be used for audio streamtype 09. audio_alsa_out:open pause_resume=0 output sample rate 44100 av_offset=0 pts spu_offset=0 pts xine_play libtheora:Received an bad packet diff=1 (pts=1, last_pts=0) video discontinuity #2, type is 2, disc_off 1 waiting for audio discontinuity #2 audio discontinuity #2, type is 2, disc_off 1 waiting for in_discontinuity update #2 libtheora:Received an bad packet audio jump, diff=0 video jump play_internal ...done fixing sound card drift by 3361 pts fixing sound card drift by 3448 pts audio_out: inserting 15243 0-frames to fill a gap of 31157 pts audio_out: inserting 20326 0-frames to fill a gap of 41545 pts fixing sound card drift by 1936 pts audio_out: inserting 11773 0-frames to fill a gap of 24064 pts audio_out: inserting 19813 0-frames to fill a gap of 40498 pts audio_out: inserting 9655 0-frames to fill a gap of 19735 pts fixing sound card drift by 1755 pts audio_out: inserting 8185 0-frames to fill a gap of 16731 pts audio_out: inserting 13416 0-frames to fill a gap of 27423 pts fixing sound card drift by -3523 pts audio_out: inserting 7751 0-frames to fill a gap of 15844 pts fixing sound card drift by -1687 pts audio_out: inserting 8270 0-frames to fill a gap of 16905 pts fixing sound card drift by 2079 pts fixing sound card drift by 1741 pts fixing sound card drift by 2824 pts fixing sound card drift by 3462 pts ao_flush (loop running: 1) input_cache: read calls: 626, main input read calls: 606 input_cache: seek_calls: 38, main input seek calls: 5 xine_dispose shutdown audio ao_close Now the panel applet isn't working, and neither are the volume up/down and mute hotkeys. Created attachment 341405 [details]
pulseaudio output with xine native PA driver
This is the output when I switch xine to the native PA audio driver instead of ALSA. The audio is _still_ garbled this way too, and I get messages like this from xine:
audio_out: inserting 8231 0-frames to fill a gap of 16824 pts
audio_out: inserting 23959 0-frames to fill a gap of 48971 pts
audio_out: inserting 18310 0-frames to fill a gap of 37425 pts
audio_out: inserting 12765 0-frames to fill a gap of 26091 pts
audio_out: inserting 12401 0-frames to fill a gap of 25348 pts
audio_out: inserting 8284 0-frames to fill a gap of 16932 pts
audio_out: inserting 8601 0-frames to fill a gap of 17581 pts
audio_out: inserting 8084 0-frames to fill a gap of 16525 pts
audio_out: inserting 7341 0-frames to fill a gap of 15005 pts
This time it didn't come up muted; it's just that the volume was set to zero.
I increased the volume with the gnome-volume-control, but although it worked xine didn't notice and change its own volume slider. So I turned it up in xine's volume control too. I'm not sure how the two are related.
On quitting xine and restarting it again, it was silent again.
*** Bug 497698 has been marked as a duplicate of this bug. *** *** Bug 501154 has been marked as a duplicate of this bug. *** All three of David's bugs seem to expose issues of the PA backend of Xine. I wrote that backend years ago, so I'll reassign this to xine but keep me as assignee. Even if the three issues David points out might be unrelated I'd rather keep track of this in a single bug. Er, don't most of these bugs use the ALSA back end? I only tried switching to the PA back end to see if that made the skipping, and the complete failures to play audio, go away. It didn't. And I just chose xine as an example -- this kind of thing is happening with all applications. Do you have an application with which you'd _prefer_ me to reproduce such bugs? This bug appears to have been reported against 'rawhide' during the Fedora 11 development cycle. Changing version to '11'. More information and reason for this action is here: http://fedoraproject.org/wiki/BugZappers/HouseKeeping With Fedora 12, I haven't seen garbled audio from xine, but I have seen the problem with volume coming up at zero. I didn't find this bug report with I reported that as Bug 555912, but I did manage to find a way to reproduce it reliably. It's also been sent upstream at: http://bugs.xine-project.org/show_bug.cgi?id=301 *** Bug 555912 has been marked as a duplicate of this bug. *** This message is a reminder that Fedora 11 is nearing its end of life. Approximately 30 (thirty) days from now Fedora will stop maintaining and issuing updates for Fedora 11. It is Fedora's policy to close all bug reports from releases that are no longer maintained. At that time this bug will be closed as WONTFIX if it remains open with a Fedora 'version' of '11'. Package Maintainer: If you wish for this bug to remain open because you plan to fix it in a currently maintained version, simply change the 'version' to a later Fedora version prior to Fedora 11's end of life. Bug Reporter: Thank you for reporting this issue and we are sorry that we may not be able to fix it before Fedora 11 is end of life. If you would still like to see this bug fixed and are able to reproduce it against a later version of Fedora please change the 'version' of this bug to the applicable version. If you are unable to change the version, please add a comment here and someone will do it for you. Although we aim to fix as many bugs as possible during every release's lifetime, sometimes those efforts are overtaken by events. Often a more recent Fedora release includes newer upstream software that fixes bugs or makes them obsolete. The process we are following is described here: http://fedoraproject.org/wiki/BugZappers/HouseKeeping Fedora 11 changed to end-of-life (EOL) status on 2010-06-25. Fedora 11 is no longer maintained, which means that it will not receive any further security or bug fix updates. As a result we are closing this bug. If you can reproduce this bug against a currently maintained version of Fedora please feel free to reopen this bug against that version. Thank you for reporting this bug and we are sorry it could not be fixed. |