[MPlayer-dev-eng] [PATCH] Make volume restore with pulseaudio work

Marcus Blumhagen marcus.blumhagen at web.de
Mon Oct 19 14:02:26 CEST 2009


On Sun, Oct 18, 2009 at 09:38:27AM +0200, Reimar Döffinger wrote:
> On Sat, Oct 17, 2009 at 06:46:10PM +0200, Marcus Blumhagen wrote:
> > Volume control inside mplayer also works flawlessly. Also setting the
> > initial volume of mplayer using -volume works and results in the
> > specified value rather then the restored volume.
> 
> Maybe my mail didn't get through, but I asked why -volume stops working when
> pa_cvolume_reset is not called.
> Probably it would be more correct to call pa_cvolume_init, but the documentation
> says the volume is not set to valid, and I have not found any function to
> do that.

Disabling the call of pa_cvolume_reset results in the following error,
when -volume >-1 is specified:

  $ mplayer -v -noconfig all -volume 0 -ao pulse Elephants_Dream_HD.avi
  [...]
  Assertion 'channels > 0' failed at pulse/volume.c:76, function pa_cvolume_set(). Aborting.

  MPlayer interrupted by signal 6 in module: av_init
  [...]

For the full output have a look at the attachment.

I think this has to do with pa_cvolume_init being called in
pulsecore/protocol-native.c, which results in volume.channels being
set to 0. The definition of that function is this:

  pa_cvolume* pa_cvolume_init(pa_cvolume *a) {
      unsigned c;

      pa_assert(a);

      a->channels = 0;

      for (c = 0; c < PA_CHANNELS_MAX; c++)
	  a->values[c] = PA_VOLUME_INVALID;

      return a;
  }

In contrast to that pa_cvolume_reset will set volume.channels to the
actual requested number of channels and values[] to PA_VOLUME_NORM.

So I think pa_cvolume_reset is the correct way to initialize the pulse
audio stream of mplayer, because it doesn´t interfere with volume
restoration and sets the volume to PA_VOLUME_NORM if
module-stream-restore is not loaded. I had a closer look at the output
of pulseaudio -vvvvC and saw that no matter what -volume is set to
module-stream-restore restores the volume of the stream, but after the
stream is initialized the volume will be set to the requested value of
-volume. I think this is related to how -volume works in mplayer but
haven´t checked that. My guess would be that mplayer waits for the
audio output being ready and then applies -volume.

For reference I attached a rather long log of pulseaudio -vvvvC with
timestamps activated after it was started, so the interesting part is
timestamped. I ran mplayer -volume 0 and mplayer -volume 50, here is
an excerpt of the relevant output:

  pulseaudio log of mplayer -volume 50 ...:
  [...]
  (   0.004|   0.000) I: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:MPlayer.
  [...]
  (   0.037|   0.016) D: protocol-native.c: Client mplayer changes volume of sink input audio stream.
  (   0.038|   0.000) D: alsa-sink.c: Requested volume: 0:  50% 1: 50%
  [...]

  pulseaudio log of mplayer -volume 0 ...:
  [...]
  (  12.803|   0.000) I: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:MPlayer.
  [...]
  (  12.825|   0.006) D: protocol-native.c: Client mplayer changes volume of sink input audio stream.
  (  12.825|   0.000) D: alsa-sink.c: Requested volume: 0:   0% 1: 0%


I hope this clears up things a little bit and this patch can make its
way into svn. ;)


Marcus

-- 
Marcus Blumhagen

"Any intelligent fool can make things bigger, more complex, and more
violent. It takes a touch of genius -- and a lot of courage -- to move
in the opposite direction."
                                                      -- Albert Einstein
-------------- next part --------------
MPlayer SVN-r29779-4.3.4 (C) 2000-2009 MPlayer Team
CPU vendor name: AuthenticAMD  max cpuid level: 1
CPU: AMD Athlon(tm) 64 X2 Dual Core Processor 5000+ (Family: 15, Model: 107, Stepping: 1)
extended cpuid-level: 24
extended cache-info: 33587520
Detected cache-line size is 64 bytes
CPUflags:  MMX: 1 MMX2: 1 3DNow: 1 3DNowExt: 1 SSE: 1 SSE2: 1 SSSE3: 0
Compiled for x86 CPU with extensions: MMX MMX2 3DNow 3DNowExt SSE SSE2 CMOV
get_path('codecs.conf') -> '/home/natas/.mplayer/codecs.conf'
Reading /home/natas/.mplayer/codecs.conf: Can't open '/home/natas/.mplayer/codecs.conf': No such file or directory
Reading /etc/mplayer/codecs.conf: Can't open '/etc/mplayer/codecs.conf': No such file or directory
Using built-in default codecs.conf.
Configuration: --prefix=/usr --confdir=/etc/mplayer
CommandLine: '-v' '-noconfig' 'all' '-volume' '0' '-ao' 'pulse' 'Elephants_Dream_HD.avi'
init_freetype
Using MMX (with tiny bit MMX2) Optimized OnScreenDisplay
get_path('fonts') -> '/home/natas/.mplayer/fonts'
Using nanosleep() timing
get_path('input.conf') -> '/home/natas/.mplayer/input.conf'
Parsing input config file /home/natas/.mplayer/input.conf
Input config file /home/natas/.mplayer/input.conf parsed: 68 binds
get_path('Elephants_Dream_HD.avi.conf') -> '/home/natas/.mplayer/Elephants_Dream_HD.avi.conf'

Playing Elephants_Dream_HD.avi.
get_path('sub/') -> '/home/natas/.mplayer/sub/'
[file] File size is 854537054 bytes
STREAM: [file] Elephants_Dream_HD.avi
STREAM: Description: File
STREAM: Author: Albeu
STREAM: Comment: based on the code from ??? (probably Arpi)
LAVF_check: AVI format
AVI file format detected.
list_end=0xFFAE
======= AVI Header =======
us/frame: 41667  (fps=24.000)
max bytes/sec: 0
padding: 0
MainAVIHeader.dwFlags: (272) HAS_INDEX IS_INTERLEAVED
frames  total: 39   initial: 0
streams: 2
Suggested BufferSize: 0
Size:  1920 x 1080
==========================
list_end=0x12C
==> Found video stream: 0
[aviheader] Video stream found, -vid 0
====== STREAM Header =====
Type: vids   FCC: MP42 (3234504D)
Flags: 0
Priority: 0   Language: 0
InitialFrames: 0
Rate: 5000000/208333 = 24.000
Start: 0   Len: 15691
Suggested BufferSize: 1127016
Quality 0
Sample size: 0
==========================
Found 'bih', 40 bytes of 40
======= VIDEO Format ======
  biSize 40
  biWidth 1920
  biHeight 1080
  biPlanes 1
  biBitCount 24
  biCompression 842289229='MP42'
  biSizeImage 6220800
===========================
Regenerating keyframe table for DIVX3 video.
====== AVI Super Index Header ========
  FCC (indx) dwSize (72) wLongsPerEntry(4)
  bIndexSubType (0) bIndexType (0)
  nEntriesInUse (3) dwChunkId (00dc)
  dwReserved[0] (0) dwReserved[1] (0) dwReserved[2] (0)
===========================
ODML (00dc): [0] 0x000000000011fac6 0x0158 39
ODML (00dc): [1] 0x000000002fe0c646 0x1d3a8 14961
ODML (00dc): [2] 0x0000000032ef0f8e 0x15b8 691
list_end=0x200
==> Found audio stream: 1
[aviheader] Audio stream found, -aid 1
====== STREAM Header =====
Type: auds   FCC:  (0)
Flags: 1
Priority: 0   Language: 0
InitialFrames: 0
Rate: 56000/1 = 56000.000
Start: 0   Len: 36614144
Suggested BufferSize: 7168
Quality -1
Sample size: 1
==========================
Found 'wf', 18 bytes of 18
======= WAVE Format =======
Format Tag: 8192 (0x2000)
Channels: 5
Samplerate: 48000
avg byte/sec: 56000
Block align: 1
bits/sample: 0
cbSize: 0
==========================================================================
====== AVI Super Index Header ========
  FCC (indx) dwSize (72) wLongsPerEntry(4)
  bIndexSubType (0) bIndexType (0)
  nEntriesInUse (3) dwChunkId (01wb)
  dwReserved[0] (0) dwReserved[1] (0) dwReserved[2] (0)
===========================
ODML (01wb): [0] 0x000000000011fc1e 0x0108 103936
ODML (01wb): [1] 0x000000002fe299ee 0x13080 34908160
ODML (01wb): [2] 0x0000000032ef2546 0x0e18 1602048
list_end=0x30C
AVI: dmlh found (size=248) (total_frames=15691)
list_end=0xFFF4
hdr=Software  size=41
Software  : AVI-Mux GUI 1.17.5, Apr  5 2006  18:41:17
list_end=0x11FD26
Found movie at 0x10000 - 0x11FD26
Reading INDEX block, 68 chunks for 39 frames (fpos=1178926).
Additional RIFF header...
list_end=0x32EF335E
Found movie at 0x10000 - 0x32EF335E
AVI: ODML: Building ODML index (2 superindexchunks).
====== AVI Standard Index Header ========
  FCC (ix00) dwSize (336) wLongsPerEntry(2)
  bIndexSubType (0) bIndexType (1)
  nEntriesInUse (39) dwChunkId (00dc)
  qwBaseOffset (0x1000C) dwReserved3 (0)
===========================
====== AVI Standard Index Header ========
  FCC (ix00) dwSize (119712) wLongsPerEntry(2)
  bIndexSubType (0) bIndexType (1)
  nEntriesInUse (14961) dwChunkId (00dc)
  qwBaseOffset (0x120192) dwReserved3 (0)
===========================
====== AVI Standard Index Header ========
  FCC (ix00) dwSize (5552) wLongsPerEntry(2)
  bIndexSubType (0) bIndexType (1)
  nEntriesInUse (691) dwChunkId (00dc)
  qwBaseOffset (0x120192) dwReserved3 (0)
===========================
====== AVI Standard Index Header ========
  FCC (ix01) dwSize (256) wLongsPerEntry(2)
  bIndexSubType (0) bIndexType (1)
  nEntriesInUse (29) dwChunkId (01wb)
  qwBaseOffset (0x1000C) dwReserved3 (0)
===========================
====== AVI Standard Index Header ========
  FCC (ix01) dwSize (77944) wLongsPerEntry(2)
  bIndexSubType (0) bIndexType (1)
  nEntriesInUse (9740) dwChunkId (01wb)
  qwBaseOffset (0x120192) dwReserved3 (0)
===========================
====== AVI Standard Index Header ========
  FCC (ix01) dwSize (3600) wLongsPerEntry(2)
  bIndexSubType (0) bIndexType (1)
  nEntriesInUse (447) dwChunkId (01wb)
  qwBaseOffset (0x120192) dwReserved3 (0)
===========================
AVI index offset: 0x0 (movi=0x10000 idx0=0x1000C idx1=0x10E14)
Auto-selected AVI audio ID = 1
Auto-selected AVI video ID = 0
AVI: Searching for audio stream (id:1)
AVI video size=817358648 (15691) audio size=36614144 (36614144)
VIDEO:  [MP42]  1920x1080  24bpp  24.000 fps  10001.5 kbps (1220.9 kbyte/s)
Auto-selected AVI audio ID = 1
[V] filefmt:3  fourcc:0x3234504D  size:1920x1080  fps:24.000  ftime:=0.0417
Clip info:
 Software: AVI-Mux GUI 1.17.5, Apr  5 2006  18:41:17
get_path('sub/') -> '/home/natas/.mplayer/sub/'
X11 opening display: :0.0
vo: X11 color mask:  FFFFFF  (R:FF0000 G:FF00 B:FF)
vo: X11 running at 1280x1024 with depth 24 and 32 bpp (":0.0" => local display)
[x11] Detected wm supports NetWM.
[x11] Detected wm supports FULLSCREEN state.
[x11] Detected wm supports ABOVE state.
[x11] Detected wm supports BELOW state.
[x11] Current fstype setting honours FULLSCREEN ABOVE BELOW X atoms
[VO_XV] Using Xv Adapter #0 (NV17 Video Texture)
[xv common] Drawing no colorkey.
[xv common] Maximum source image dimensions: 2046x2046
==========================================================================
Opening video decoder: [ffmpeg] FFmpeg's libavcodec codec family
INFO: libavcodec init OK!
Selected video codec: [ffmp42] vfm: ffmpeg (FFmpeg MSMPEG-4 v2)
==========================================================================
==========================================================================
Opening audio decoder: [liba52] AC3 decoding with liba52
dec_audio: Allocating 3840 bytes for input buffer.
dec_audio: Allocating 6144 + 65536 = 71680 bytes for output buffer.
Using SSE optimized IMDCT transform
AC3: 5.1 (3f+2r+lfe)  48000 Hz  448.0 kbit/s
A52 flags before a52_frame: 0x2A
A52 flags after a52_frame: 0xA
Using MMX optimized resampler
AUDIO: 48000 Hz, 2 ch, s16le, 448.0 kbit/29.17% (ratio: 56000->192000)
Selected audio codec: [a52] afm: liba52 (AC3-liba52)
==========================================================================
Building audio filter chain for 48000Hz/2ch/s16le -> 0Hz/0ch/??...
[libaf] Adding filter dummy 
[dummy] Was reinitialized: 48000Hz/2ch/s16le
[dummy] Was reinitialized: 48000Hz/2ch/s16le
Trying preferred audio driver 'pulse', options '[none]'
AO: [pulse] 48000Hz 2ch s16le (2 bytes per sample)
AO: Description: PulseAudio audio output
AO: Author: Lennart Poettering
Building audio filter chain for 48000Hz/2ch/s16le -> 48000Hz/2ch/s16le...
[dummy] Was reinitialized: 48000Hz/2ch/s16le
[dummy] Was reinitialized: 48000Hz/2ch/s16le
Assertion 'channels > 0' failed at pulse/volume.c:76, function pa_cvolume_set(). Aborting.


MPlayer interrupted by signal 6 in module: av_init
- MPlayer crashed. This shouldn't happen.
  It can be a bug in the MPlayer code _or_ in your drivers _or_ in your
  gcc version. If you think it's MPlayer's fault, please read
  DOCS/HTML/en/bugreports.html and follow the instructions there. We can't and
  won't help unless you provide this information when reporting a possible bug.
-------------- next part --------------
I: main.c: setrlimit(RLIMIT_NICE, (31, 31)) fehlgeschlagen: Die Operation ist nicht erlaubt
D: core-rtclock.c: Timer slack is set to 50 us.
I: core-util.c: Failed to acquire high-priority scheduling: Datei oder Verzeichnis nicht gefunden
I: main.c: Dies ist PulseAudio 0.9.19
D: main.c: Kompilier-Host: x86_64-pc-linux-gnu
D: main.c: Kompilier-CFLAGS: -g -O2 -g -Wall -O2 -Wall -W -Wextra -pipe -Wno-long-long -Winline -Wvla -Wno-overlength-strings -Wunsafe-loop-optimizations -Wundef -Wformat=2 -Wlogical-op -Wsign-compare -Wformat-security -Wmissing-include-dirs -Wformat-nonliteral -Wold-style-definition -Wpointer-arith -Winit-self -Wdeclaration-after-statement -Wfloat-equal -Wmissing-prototypes -Wstrict-prototypes -Wredundant-decls -Wmissing-declarations -Wmissing-noreturn -Wshadow -Wendif-labels -Wcast-align -Wstrict-aliasing=2 -Wwrite-strings -Wno-unused-parameter -ffast-math -Wp,-D_FORTIFY_SOURCE=2 -fno-common -fdiagnostics-show-option
D: main.c: Laufe auf Host: Linux x86_64 2.6.30-amd64-custom #1 SMP PREEMPT Sun Oct 11 19:17:23 CEST 2009
D: main.c: 2 CPUs gefunden.
I: main.c: Seitengröße ist 4096 Bytes.
D: main.c: Kompiliere mit Valgrind-Unterstützung: nein
D: main.c: Läuft im Valgrind-Modus: no
D: main.c: Optimiertes Build: ja
D: main.c: Alle Ansprüche aktiviert.
I: main.c: System- ID ist db26de6e1db656e815073c29482401b4.
I: main.c: System- ID ist db26de6e1db656e815073c29482401b4-1255946427.480604-1277222009.
I: main.c: Nutze Laufzeit-Verzeichnis /home/natas/.pulse/db26de6e1db656e815073c29482401b4-runtime.
I: main.c: Nutze Zustands-Verzeichnis /home/natas/.pulse.
I: main.c: Modul-Verzeichnis /usr/lib/pulse-0.9.19/modules benutzen.
I: main.c: Laufe im System-Modus: no
I: main.c: Neue hochauslösende Timer verfügbar! Guten Appetit!
I: cpu-x86.c: CPU flags: MMX SSE SSE2 SSE3 MMXEXT 3DNOW 3DNOWEXT 
I: svolume_mmx.c: Initialising MMX optimized functions.
I: remap_mmx.c: Initialising MMX optimized remappers.
I: svolume_sse.c: Initialising SSE2 optimized functions.
I: remap_sse.c: Initialising SSE2 optimized remappers.
I: sconv_sse.c: Initialising SSE2 optimized conversions.
D: memblock.c: Using shared memory pool with 1024 slots of size 64,0 KB each, total size is 64,0 MB, maximum usable slot size is 65472
D: database-gdbm.c: Opened GDBM database '/home/natas/.pulse/db26de6e1db656e815073c29482401b4-device-volumes.x86_64-pc-linux-gnu.gdbm'
I: module-device-restore.c: Sucessfully opened database file '/home/natas/.pulse/db26de6e1db656e815073c29482401b4-device-volumes'.
I: module.c: Loaded "module-device-restore" (index: #0; argument: "").
D: database-gdbm.c: Opened GDBM database '/home/natas/.pulse/db26de6e1db656e815073c29482401b4-stream-volumes.x86_64-pc-linux-gnu.gdbm'
I: module-stream-restore.c: Sucessfully opened database file '/home/natas/.pulse/db26de6e1db656e815073c29482401b4-stream-volumes'.
I: module.c: Loaded "module-stream-restore" (index: #1; argument: "").
D: database-gdbm.c: Opened GDBM database '/home/natas/.pulse/db26de6e1db656e815073c29482401b4-card-database.x86_64-pc-linux-gnu.gdbm'
I: module-card-restore.c: Sucessfully opened database file '/home/natas/.pulse/db26de6e1db656e815073c29482401b4-card-database'.
I: module.c: Loaded "module-card-restore" (index: #2; argument: "").
I: module.c: Loaded "module-augment-properties" (index: #3; argument: "").
D: dbus-util.c: Successfully connected to D-Bus session bus 63caddefe43dff2615df47d34adc38be as :1.54
D: reserve-wrap.c: Successfully acquired reservation lock on device 'Audio0'
D: reserve-wrap.c: Successfully create reservation lock monitor for device 'Audio0'
D: alsa-util.c: Trying front:Live with SND_PCM_NO_AUTO_FORMAT ...
D: alsa-util.c: Managed to open front:Live
D: alsa-util.c: Maximum hw buffer size is 371 ms
D: alsa-util.c: Set buffer size first, period size second.
I: alsa-sink.c: Successfully opened device front:Live.
I: alsa-sink.c: Successfully enabled mmap() mode.
I: alsa-sink.c: Successfully enabled timer-based scheduling mode.
I: (alsa-lib)control.c: Invalid CTL front:Live
I: alsa-mixer.c: Unable to attach to mixer front:Live: Datei oder Verzeichnis nicht gefunden
I: alsa-mixer.c: Successfully attached to mixer 'hw:0'
D: alsa-mixer.c: Probing path 'Master'
D: alsa-sink.c: Probed mixer path Master:
D: alsa-mixer.c: Path Master ((null)), direction=1, priority=0, probed=yes, supported=yes, has_mute=yes, has_volume=yes, has_dB=yes, min_volume=0, max_volume=31, min_dB=-46,5, max_dB=0
D: alsa-mixer.c: Element Master, direction=1, switch=1, volume=1, enumeration=0, required=0, required_absent=0, mask=0x6, n_channels=2, override_map=no
I: module-device-restore.c: Restoring volume for sink headphones.
I: module-device-restore.c: Restoring mute state for sink headphones.
I: sink.c: Created sink 0 "headphones" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: sink.c:     alsa.resolution_bits = "16"
I: sink.c:     device.api = "alsa"
I: sink.c:     device.class = "sound"
I: sink.c:     alsa.class = "generic"
I: sink.c:     alsa.subclass = "generic-mix"
I: sink.c:     alsa.name = "ADC Capture/Standard PCM Playback"
I: sink.c:     alsa.id = "emu10k1"
I: sink.c:     alsa.subdevice = "2"
I: sink.c:     alsa.subdevice_name = "subdevice #2"
I: sink.c:     alsa.device = "0"
I: sink.c:     alsa.card = "0"
I: sink.c:     alsa.card_name = "SB Live! Value [CT4670]"
I: sink.c:     alsa.long_card_name = "SB Live! Value [CT4670] (rev.5, serial:0x201102) at 0xdc00, irq 19"
I: sink.c:     alsa.driver_name = "snd_emu10k1"
I: sink.c:     device.bus_path = "pci-0000:01:07.0"
I: sink.c:     sysfs.path = "/devices/pci0000:00/0000:00:09.0/0000:01:07.0/sound/card0"
I: sink.c:     device.bus = "pci"
I: sink.c:     device.vendor.id = "1102"
I: sink.c:     device.vendor.name = "Creative Labs"
I: sink.c:     device.product.id = "0002"
I: sink.c:     device.product.name = "SB Live! EMU10k1"
I: sink.c:     device.string = "front:Live"
I: sink.c:     device.buffering.buffer_size = "65536"
I: sink.c:     device.buffering.fragment_size = "65536"
I: sink.c:     device.access_mode = "mmap+timer"
I: sink.c:     device.description = "Kopfhörer"
I: sink.c:     alsa.mixer_name = "TriTech TR28602"
I: sink.c:     alsa.components = "AC97a:54524123"
I: sink.c:     device.icon_name = "audio-card-pci"
D: core-subscribe.c: Dropped redundant event due to change event.
I: source.c: Created source 0 "headphones.monitor" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: source.c:     device.description = "Monitor of Kopfhörer"
I: source.c:     device.class = "monitor"
I: source.c:     device.icon_name = "audio-input-microphone"
I: alsa-sink.c: Using 1,0 fragments of size 65536 bytes (371,52ms), buffer size is 65536 bytes (371,52ms)
I: alsa-sink.c: Time scheduling watermark is 20,00ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=15502
D: alsa-mixer.c: Activating path Master
D: alsa-mixer.c: Path Master ((null)), direction=1, priority=0, probed=yes, supported=yes, has_mute=yes, has_volume=yes, has_dB=yes, min_volume=0, max_volume=31, min_dB=-46,5, max_dB=0
D: alsa-mixer.c: Element Master, direction=1, switch=1, volume=1, enumeration=0, required=0, required_absent=0, mask=0x6, n_channels=2, override_map=no
I: alsa-sink.c: Hardware volume ranges from -46,50 dB to 0,00 dB.
I: alsa-sink.c: No particular base volume set, fixing to 0 dB
I: alsa-sink.c: Using hardware volume control. Hardware dB scale supported.
I: alsa-sink.c: Using hardware mute control.
D: alsa-util.c: snd_pcm_dump():
D: alsa-util.c: Hooks PCM
D: alsa-util.c: Its setup is:
D: alsa-util.c:   stream       : PLAYBACK
D: alsa-util.c:   access       : MMAP_INTERLEAVED
D: alsa-util.c:   format       : S16_LE
D: alsa-util.c:   subformat    : STD
D: alsa-util.c:   channels     : 2
D: alsa-util.c:   rate         : 44100
D: alsa-util.c:   exact rate   : 44100 (44100/1)
D: alsa-util.c:   msbits       : 16
D: alsa-util.c:   buffer_size  : 16384
D: alsa-util.c:   period_size  : 16384
D: alsa-util.c:   period_time  : 371519
D: alsa-util.c:   tstamp_mode  : ENABLE
D: alsa-util.c:   period_step  : 1
D: alsa-util.c:   avail_min    : 16384
D: alsa-util.c:   period_event : 0
D: alsa-util.c:   start_threshold  : -1
D: alsa-util.c:   stop_threshold   : 4611686018427387904
D: alsa-util.c:   silence_threshold: 0
D: alsa-util.c:   silence_size : 0
D: alsa-util.c:   boundary     : 4611686018427387904
D: alsa-util.c: Slave: Hardware PCM card 0 'SB Live! Value [CT4670]' device 0 subdevice 2
D: alsa-util.c: Its setup is:
D: alsa-util.c:   stream       : PLAYBACK
D: alsa-util.c:   access       : MMAP_INTERLEAVED
D: alsa-util.c:   format       : S16_LE
D: alsa-util.c:   subformat    : STD
D: alsa-util.c:   channels     : 2
D: alsa-util.c:   rate         : 44100
D: alsa-util.c:   exact rate   : 44100 (44100/1)
D: alsa-util.c:   msbits       : 16
D: alsa-util.c:   buffer_size  : 16384
D: alsa-util.c:   period_size  : 16384
D: alsa-util.c:   period_time  : 371519
D: alsa-util.c:   tstamp_mode  : ENABLE
D: alsa-util.c:   period_step  : 1
D: alsa-util.c:   avail_min    : 16384
D: alsa-util.c:   period_event : 0
D: alsa-util.c:   start_threshold  : -1
D: alsa-util.c:   stop_threshold   : 4611686018427387904
D: alsa-util.c:   silence_threshold: 0
D: alsa-util.c:   silence_size : 0
D: alsa-util.c:   boundary     : 4611686018427387904
D: alsa-util.c:   appl_ptr     : 0
D: alsa-util.c:   hw_ptr       : 0
D: alsa-sink.c: Thread starting up
D: core-util.c: SCHED_RR worked.
I: core-util.c: Successfully enabled SCHED_RR scheduling for thread, with priority 5.
D: alsa-sink.c: Requested volume: 0:  17% 1:  17%
D: alsa-sink.c: Got hardware volume: 0:  17% 1:  17%
D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
I: alsa-sink.c: Starting playback.
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.
I: module.c: Loaded "module-alsa-sink" (index: #4; argument: "device=front:Live sink_name=headphones sink_properties=device.description=Kopfhörer control=Master").
D: alsa-util.c: Trying rear:Live with SND_PCM_NO_AUTO_FORMAT ...
D: alsa-util.c: Managed to open rear:Live
D: alsa-util.c: Maximum hw buffer size is 371 ms
D: alsa-util.c: Set buffer size first, period size second.
I: alsa-sink.c: Successfully opened device rear:Live.
I: alsa-sink.c: Successfully enabled mmap() mode.
I: alsa-sink.c: Successfully enabled timer-based scheduling mode.
I: (alsa-lib)control.c: Invalid CTL rear:Live
I: alsa-mixer.c: Unable to attach to mixer rear:Live: Datei oder Verzeichnis nicht gefunden
I: alsa-mixer.c: Successfully attached to mixer 'hw:0'
D: alsa-mixer.c: Probing path 'Surround'
D: alsa-sink.c: Probed mixer path Surround:
D: alsa-mixer.c: Path Surround ((null)), direction=1, priority=0, probed=yes, supported=yes, has_mute=no, has_volume=yes, has_dB=yes, min_volume=0, max_volume=100, min_dB=-40, max_dB=0
D: alsa-mixer.c: Element Surround, direction=1, switch=0, volume=1, enumeration=0, required=0, required_absent=0, mask=0x6, n_channels=2, override_map=no
D: core-subscribe.c: Dropped redundant event due to change event.
I: module-device-restore.c: Restoring volume for sink hifi.
I: sink.c: Created sink 1 "hifi" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: sink.c:     alsa.resolution_bits = "16"
I: sink.c:     device.api = "alsa"
I: sink.c:     device.class = "sound"
I: sink.c:     alsa.class = "generic"
I: sink.c:     alsa.subclass = "generic-mix"
I: sink.c:     alsa.name = "ADC Capture/Standard PCM Playback"
I: sink.c:     alsa.id = "emu10k1"
I: sink.c:     alsa.subdevice = "3"
I: sink.c:     alsa.subdevice_name = "subdevice #3"
I: sink.c:     alsa.device = "0"
I: sink.c:     alsa.card = "0"
I: sink.c:     alsa.card_name = "SB Live! Value [CT4670]"
I: sink.c:     alsa.long_card_name = "SB Live! Value [CT4670] (rev.5, serial:0x201102) at 0xdc00, irq 19"
I: sink.c:     alsa.driver_name = "snd_emu10k1"
I: sink.c:     device.bus_path = "pci-0000:01:07.0"
I: sink.c:     sysfs.path = "/devices/pci0000:00/0000:00:09.0/0000:01:07.0/sound/card0"
I: sink.c:     device.bus = "pci"
I: sink.c:     device.vendor.id = "1102"
I: sink.c:     device.vendor.name = "Creative Labs"
I: sink.c:     device.product.id = "0002"
I: sink.c:     device.product.name = "SB Live! EMU10k1"
I: sink.c:     device.string = "rear:Live"
I: sink.c:     device.buffering.buffer_size = "65536"
I: sink.c:     device.buffering.fragment_size = "65536"
I: sink.c:     device.access_mode = "mmap+timer"
I: sink.c:     device.description = "Hifi-Anlage"
I: sink.c:     alsa.mixer_name = "TriTech TR28602"
I: sink.c:     alsa.components = "AC97a:54524123"
I: sink.c:     device.icon_name = "audio-card-pci"
D: core-subscribe.c: Dropped redundant event due to change event.
I: source.c: Created source 1 "hifi.monitor" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: source.c:     device.description = "Monitor of Hifi-Anlage"
I: source.c:     device.class = "monitor"
I: source.c:     device.icon_name = "audio-input-microphone"
I: alsa-sink.c: Using 1,0 fragments of size 65536 bytes (371,52ms), buffer size is 65536 bytes (371,52ms)
I: alsa-sink.c: Time scheduling watermark is 20,00ms
D: alsa-sink.c: hwbuf_unused=0
D: alsa-sink.c: setting avail_min=15502
D: alsa-mixer.c: Activating path Surround
D: alsa-mixer.c: Path Surround ((null)), direction=1, priority=0, probed=yes, supported=yes, has_mute=no, has_volume=yes, has_dB=yes, min_volume=0, max_volume=100, min_dB=-40, max_dB=0
D: alsa-mixer.c: Element Surround, direction=1, switch=0, volume=1, enumeration=0, required=0, required_absent=0, mask=0x6, n_channels=2, override_map=no
I: alsa-sink.c: Hardware volume ranges from -40,00 dB to 0,00 dB.
I: alsa-sink.c: No particular base volume set, fixing to 0 dB
I: alsa-sink.c: Using hardware volume control. Hardware dB scale supported.
I: alsa-sink.c: Driver does not support hardware mute control, falling back to software mute control.
D: alsa-util.c: snd_pcm_dump():
D: alsa-util.c: Hooks PCM
D: alsa-util.c: Its setup is:
D: alsa-util.c:   stream       : PLAYBACK
D: alsa-util.c:   access       : MMAP_INTERLEAVED
D: alsa-util.c:   format       : S16_LE
D: alsa-util.c:   subformat    : STD
D: alsa-util.c:   channels     : 2
D: alsa-util.c:   rate         : 44100
D: alsa-util.c:   exact rate   : 44100 (44100/1)
D: alsa-util.c:   msbits       : 16
D: alsa-util.c:   buffer_size  : 16384
D: alsa-util.c:   period_size  : 16384
D: alsa-util.c:   period_time  : 371519
D: alsa-util.c:   tstamp_mode  : ENABLE
D: alsa-util.c:   period_step  : 1
D: alsa-util.c:   avail_min    : 16384
D: alsa-util.c:   period_event : 0
D: alsa-util.c:   start_threshold  : -1
D: alsa-util.c:   stop_threshold   : 4611686018427387904
D: alsa-util.c:   silence_threshold: 0
D: alsa-util.c:   silence_size : 0
D: alsa-util.c:   boundary     : 4611686018427387904
D: alsa-util.c: Slave: Hardware PCM card 0 'SB Live! Value [CT4670]' device 0 subdevice 3
D: alsa-util.c: Its setup is:
D: alsa-util.c:   stream       : PLAYBACK
D: alsa-util.c:   access       : MMAP_INTERLEAVED
D: alsa-util.c:   format       : S16_LE
D: alsa-util.c:   subformat    : STD
D: alsa-util.c:   channels     : 2
D: alsa-util.c:   rate         : 44100
D: alsa-util.c:   exact rate   : 44100 (44100/1)
D: alsa-util.c:   msbits       : 16
D: alsa-util.c:   buffer_size  : 16384
D: alsa-util.c:   period_size  : 16384
D: alsa-util.c:   period_time  : 371519
D: alsa-util.c:   tstamp_mode  : ENABLE
D: alsa-util.c:   period_step  : 1
D: alsa-util.c:   avail_min    : 16384
D: alsa-util.c:   period_event : 0
D: alsa-util.c:   start_threshold  : -1
D: alsa-util.c:   stop_threshold   : 4611686018427387904
D: alsa-util.c:   silence_threshold: 0
D: alsa-util.c:   silence_size : 0
D: alsa-util.c:   boundary     : 4611686018427387904
D: alsa-util.c:   appl_ptr     : 0
D: alsa-util.c:   hw_ptr       : 0
D: alsa-sink.c: Thread starting up
D: alsa-sink.c: Requested volume: 0:  27% 1:  27%
D: core-util.c: SCHED_RR worked.
I: core-util.c: Successfully enabled SCHED_RR scheduling for thread, with priority 5.
D: alsa-sink.c: Got hardware volume: 0:  27% 1:  27%
D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
I: alsa-sink.c: Starting playback.
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.
I: module.c: Loaded "module-alsa-sink" (index: #5; argument: "device=rear:Live sink_name=hifi sink_properties=device.description=Hifi-Anlage control=Surround").
D: cli-command.c: Checking for existance of '/usr/lib/pulse-0.9.19/modules/module-udev-detect.so': success
D: module-udev-detect.c: /dev/snd/controlC0 is accessible: yes
D: module-udev-detect.c: /devices/pci0000:00/0000:00:09.0/0000:01:07.0/sound/card0 is busy: yes
I: module-udev-detect.c: Found 1 cards.
I: module.c: Loaded "module-udev-detect" (index: #6; argument: "").
D: cli-command.c: Checking for existance of '/usr/lib/pulse-0.9.19/modules/module-esound-protocol-unix.so': success
I: module.c: Loaded "module-esound-protocol-unix" (index: #7; argument: "").
I: module.c: Loaded "module-native-protocol-unix" (index: #8; argument: "").
D: cli-command.c: Checking for existance of '/usr/lib/pulse-0.9.19/modules/module-gconf.so': success
I: module.c: Loaded "module-gconf" (index: #9; argument: "").
D: core-subscribe.c: Dropped redundant event due to change event.
I: module-default-device-restore.c: Restored default sink 'headphones'.
D: core-subscribe.c: Dropped redundant event due to change event.
I: module-default-device-restore.c: Restored default source 'headphones.monitor'.
I: module.c: Loaded "module-default-device-restore" (index: #10; argument: "").
I: module.c: Loaded "module-rescue-streams" (index: #11; argument: "").
I: module.c: Loaded "module-always-sink" (index: #12; argument: "").
I: module.c: Loaded "module-intended-roles" (index: #13; argument: "").
D: module-suspend-on-idle.c: Sink headphones becomes idle, timeout in 5 seconds.
D: module-suspend-on-idle.c: Sink hifi becomes idle, timeout in 5 seconds.
I: module.c: Loaded "module-suspend-on-idle" (index: #14; argument: "").
D: dbus-util.c: Successfully connected to D-Bus system bus 6af983f8abe983d911ba0be34adc383d as :1.57
I: client.c: Created 0 "ConsoleKit Session /org/freedesktop/ConsoleKit/Session1"
D: module-console-kit.c: Added new session /org/freedesktop/ConsoleKit/Session1
I: client.c: Created 1 "ConsoleKit Session /org/freedesktop/ConsoleKit/Session3"
D: module-console-kit.c: Added new session /org/freedesktop/ConsoleKit/Session3
I: module.c: Loaded "module-console-kit" (index: #15; argument: "").
I: module.c: Loaded "module-position-event-sounds" (index: #16; argument: "").
I: module.c: Loaded "module-cork-music-on-phone" (index: #17; argument: "").
D: module-cli.c: Managed to open /dev/tty.
I: client.c: Created 2 "Unknown client"
I: module.c: Loaded "module-cli" (index: #18; argument: "exit_on_eof=1").
D: main.c: Got org.pulseaudio.Server!
I: main.c: Start des Daemons abgeschlossen.
D: module-console-kit.c: dbus: interface=org.freedesktop.DBus, path=/org/freedesktop/DBus, member=NameAcquired
I: module-suspend-on-idle.c: Sink hifi idle for too long, suspending ...
D: sink.c: Suspend cause of sink hifi is 0x0004, suspending
I: alsa-sink.c: Device suspended...
I: module-suspend-on-idle.c: Sink headphones idle for too long, suspending ...
D: sink.c: Suspend cause of sink headphones is 0x0004, suspending
I: alsa-sink.c: Device suspended...
D: reserve-wrap.c: Device lock status of reserve-monitor-wrapper at Audio0 changed: not busy
D: module-udev-detect.c: /dev/snd/controlC0 is accessible: yes
D: module-udev-detect.c: /devices/pci0000:00/0000:00:09.0/0000:01:07.0/sound/card0 is busy: yes
(   0.000|   0.000) I: client.c: Created 3 "Native client (UNIX socket client)"
(   0.001|   0.001) D: protocol-native.c: Protocol version: remote 16, local 16
(   0.001|   0.000) I: protocol-native.c: Got credentials: uid=1000 gid=1000 success=1
(   0.001|   0.000) D: protocol-native.c: SHM possible: yes
(   0.001|   0.000) D: protocol-native.c: Negotiated SHM: yes
(   0.002|   0.000) D: module-augment-properties.c: Looking for .desktop file for mplayer
(   0.004|   0.001) D: module-intended-roles.c: Not setting device for stream audio stream, because it lacks role.
(   0.004|   0.000) I: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:MPlayer.
(   0.004|   0.000) D: sink.c: Suspend cause of sink headphones is 0x0000, resuming
(   0.005|   0.001) D: reserve-wrap.c: Successfully acquired reservation lock on device 'Audio0'
(   0.005|   0.000) I: alsa-sink.c: Trying resume...
(   0.007|   0.001) D: alsa-util.c: Maximum hw buffer size is 371 ms
(   0.007|   0.000) D: alsa-util.c: Set buffer size first, period size second.
(   0.007|   0.000) D: alsa-sink.c: hwbuf_unused=0
(   0.007|   0.000) D: alsa-sink.c: setting avail_min=15502
(   0.007|   0.000) I: alsa-sink.c: Resumed successfully...
(   0.007|   0.000) I: alsa-sink.c: Starting playback.
(   0.007|   0.000) D: module-suspend-on-idle.c: Sink headphones becomes idle, timeout in 5 seconds.
(   0.007|   0.000) D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
(   0.007|   0.000) D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
(   0.007|   0.000) D: module-suspend-on-idle.c: Sink headphones becomes busy.
(   0.007|   0.000) I: resampler.c: Using resampler 'ffmpeg'
(   0.007|   0.000) I: resampler.c: Using s16le as working format.
(   0.018|   0.010) D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
(   0.018|   0.000) D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
(   0.018|   0.000) I: sink-input.c: Created input 0 "audio stream" on headphones with sample spec s16le 2ch 48000Hz and channel map front-left,front-right
(   0.018|   0.000) I: sink-input.c:     media.name = "audio stream"
(   0.018|   0.000) I: sink-input.c:     application.name = "MPlayer"
(   0.018|   0.000) I: sink-input.c:     native-protocol.peer = "UNIX socket client"
(   0.018|   0.000) I: sink-input.c:     native-protocol.version = "16"
(   0.018|   0.000) I: sink-input.c:     application.process.id = "8347"
(   0.018|   0.000) I: sink-input.c:     application.process.user = "natas"
(   0.018|   0.000) I: sink-input.c:     application.process.host = "Hellraiser"
(   0.018|   0.000) I: sink-input.c:     application.process.binary = "mplayer"
(   0.018|   0.000) I: sink-input.c:     application.language = "C"
(   0.018|   0.000) I: sink-input.c:     window.x11.display = ":0.0"
(   0.018|   0.000) I: sink-input.c:     application.process.machine_id = "db26de6e1db656e815073c29482401b4"
(   0.018|   0.000) I: sink-input.c:     application.process.session_id = "db26de6e1db656e815073c29482401b4-1255946427.480604-1277222009"
(   0.018|   0.000) I: sink-input.c:     module-stream-restore.id = "sink-input-by-application-name:MPlayer"
(   0.019|   0.000) I: protocol-native.c: Requested tlength=250,00 ms, minreq=20,00 ms
(   0.019|   0.000) D: protocol-native.c: Traditional mode enabled, modifying sink usec only for compat with minreq.
(   0.019|   0.000) D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
(   0.019|   0.000) D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
(   0.020|   0.000) D: memblockq.c: memblockq requested: maxlength=4194304, tlength=48000, base=4, prebuf=44164, minreq=3840 maxrewind=0
(   0.020|   0.000) D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=48000, base=4, prebuf=44164, minreq=3840 maxrewind=0
(   0.020|   0.000) I: protocol-native.c: Final latency 460,00 ms = 210,00 ms + 2*20,00 ms + 210,00 ms
(   0.020|   0.000) D: alsa-sink.c: Requested volume: 0:  17% 1:  17%
(   0.020|   0.000) D: alsa-sink.c: Got hardware volume: 0:  17% 1:  17%
(   0.020|   0.000) D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
(   0.020|   0.000) D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
(   0.020|   0.000) D: alsa-sink.c: Latency set to 210,00ms
(   0.020|   0.000) D: alsa-sink.c: hwbuf_unused=28492
(   0.020|   0.000) D: alsa-sink.c: setting avail_min=15503
(   0.020|   0.000) D: alsa-sink.c: Requesting rewind due to latency change.
(   0.021|   0.000) D: alsa-sink.c: Requested to rewind 65536 bytes.
(   0.021|   0.000) D: alsa-sink.c: Limited to 59648 bytes.
(   0.021|   0.000) D: alsa-sink.c: before: 14912
(   0.021|   0.000) D: alsa-sink.c: after: 14912
(   0.021|   0.000) D: alsa-sink.c: Rewound 59648 bytes.
(   0.021|   0.000) D: sink.c: Processing rewind...
(   0.021|   0.000) D: sink-input.c: Have to rewind 59648 bytes on render memblockq.
(   0.021|   0.000) D: source.c: Processing rewind...
(   0.021|   0.000) D: core-subscribe.c: Dropped redundant event due to change event.
(   0.021|   0.000) D: reserve-wrap.c: Device lock status of reserve-monitor-wrapper at Audio0 changed: not busy
(   0.037|   0.016) D: protocol-native.c: Client mplayer changes volume of sink input audio stream.
(   0.038|   0.000) D: alsa-sink.c: Requested volume: 0:  50% 1:  50%
(   0.038|   0.000) D: alsa-sink.c: Got hardware volume: 0:  50% 1:  50%
(   0.038|   0.000) D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
(   0.038|   0.000) I: module-device-restore.c: Storing volume/mute/port for device sink:headphones.
(   0.101|   0.063) D: protocol-native.c: Requesting rewind due to end of underrun.
(   0.102|   0.000) D: alsa-sink.c: Requested to rewind 65536 bytes.
(   0.102|   0.000) D: alsa-sink.c: Limited to 19256 bytes.
(   0.102|   0.000) D: alsa-sink.c: before: 4814
(   0.102|   0.000) D: alsa-sink.c: after: 4814
(   0.102|   0.000) D: alsa-sink.c: Rewound 19256 bytes.
(   0.102|   0.000) D: sink.c: Processing rewind...
(   0.102|   0.000) D: sink-input.c: Have to rewind 19256 bytes on render memblockq.
(   0.102|   0.000) D: source.c: Processing rewind...
(   0.257|   0.155) D: protocol-native.c: Underrun on 'audio stream', 0 bytes in queue.
(   0.549|   0.291) D: protocol-native.c: Requesting rewind due to end of underrun.
(   0.549|   0.000) D: alsa-sink.c: Requested to rewind 65536 bytes.
(   0.549|   0.000) D: alsa-sink.c: Limited to 33484 bytes.
(   0.549|   0.000) D: alsa-sink.c: before: 8371
(   0.549|   0.000) D: alsa-sink.c: after: 8371
(   0.549|   0.000) D: alsa-sink.c: Rewound 33484 bytes.
(   0.549|   0.000) D: sink.c: Processing rewind...
(   0.549|   0.000) D: sink-input.c: Have to rewind 33484 bytes on render memblockq.
(   0.549|   0.000) D: source.c: Processing rewind...
(   1.683|   1.133) D: protocol-native.c: Underrun on 'audio stream', 0 bytes in queue.
(   2.196|   0.513) D: alsa-sink.c: Requested volume: 0:  50% 1:  50%
(   2.197|   0.000) D: alsa-sink.c: Got hardware volume: 0:  50% 1:  50%
(   2.197|   0.000) D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
(   2.197|   0.000) D: alsa-sink.c: hwbuf_unused=0
(   2.197|   0.000) D: alsa-sink.c: setting avail_min=15502
(   2.197|   0.000) D: alsa-sink.c: Requested to rewind 65536 bytes.
(   2.197|   0.000) D: alsa-sink.c: Limited to 32212 bytes.
(   2.197|   0.000) D: alsa-sink.c: before: 8053
(   2.197|   0.000) D: alsa-sink.c: after: 8053
(   2.197|   0.000) D: alsa-sink.c: Rewound 32212 bytes.
(   2.198|   0.000) D: sink.c: Processing rewind...
(   2.198|   0.000) D: source.c: Processing rewind...
(   2.198|   0.000) D: module-suspend-on-idle.c: Sink headphones becomes idle, timeout in 5 seconds.
(   2.198|   0.000) D: module-suspend-on-idle.c: Sink headphones becomes idle, timeout in 5 seconds.
(   2.198|   0.000) D: core.c: Hmm, no streams around, trying to vacuum.
(   2.200|   0.001) I: sink-input.c: Freeing input 0 "audio stream"
(   2.201|   0.001) I: client.c: Freed 3 "MPlayer"
(   2.202|   0.000) I: protocol-native.c: Connection died.
(   7.203|   5.001) I: module-suspend-on-idle.c: Sink headphones idle for too long, suspending ...
(   7.204|   0.000) D: sink.c: Suspend cause of sink headphones is 0x0004, suspending
(   7.207|   0.002) I: alsa-sink.c: Device suspended...
(   7.207|   0.000) D: reserve-wrap.c: Device lock status of reserve-monitor-wrapper at Audio0 changed: not busy
(   7.208|   0.000) D: module-udev-detect.c: /dev/snd/controlC0 is accessible: yes
(   7.224|   0.015) D: module-udev-detect.c: /devices/pci0000:00/0000:00:09.0/0000:01:07.0/sound/card0 is busy: yes
(  10.042|   2.818) I: module-device-restore.c: Synced.
(  12.799|   2.756) I: client.c: Created 4 "Native client (UNIX socket client)"
(  12.800|   0.001) D: protocol-native.c: Protocol version: remote 16, local 16
(  12.800|   0.000) I: protocol-native.c: Got credentials: uid=1000 gid=1000 success=1
(  12.800|   0.000) D: protocol-native.c: SHM possible: yes
(  12.800|   0.000) D: protocol-native.c: Negotiated SHM: yes
(  12.801|   0.000) D: module-augment-properties.c: Looking for .desktop file for mplayer
(  12.803|   0.001) D: module-intended-roles.c: Not setting device for stream audio stream, because it lacks role.
(  12.803|   0.000) I: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:MPlayer.
(  12.803|   0.000) D: sink.c: Suspend cause of sink headphones is 0x0000, resuming
(  12.804|   0.001) D: reserve-wrap.c: Successfully acquired reservation lock on device 'Audio0'
(  12.804|   0.000) I: alsa-sink.c: Trying resume...
(  12.805|   0.001) D: alsa-util.c: Maximum hw buffer size is 371 ms
(  12.805|   0.000) D: alsa-util.c: Set buffer size first, period size second.
(  12.805|   0.000) D: alsa-sink.c: hwbuf_unused=0
(  12.805|   0.000) D: alsa-sink.c: setting avail_min=15502
(  12.805|   0.000) I: alsa-sink.c: Resumed successfully...
(  12.805|   0.000) D: module-suspend-on-idle.c: Sink headphones becomes idle, timeout in 5 seconds.
(  12.805|   0.000) I: alsa-sink.c: Starting playback.
(  12.806|   0.000) D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  12.806|   0.000) D: module-suspend-on-idle.c: Sink headphones becomes busy.
(  12.806|   0.000) D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  12.806|   0.000) I: resampler.c: Using resampler 'ffmpeg'
(  12.806|   0.000) I: resampler.c: Using s16le as working format.
(  12.816|   0.010) D: memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
(  12.816|   0.000) D: memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
(  12.816|   0.000) I: sink-input.c: Created input 1 "audio stream" on headphones with sample spec s16le 2ch 48000Hz and channel map front-left,front-right
(  12.816|   0.000) I: sink-input.c:     media.name = "audio stream"
(  12.816|   0.000) I: sink-input.c:     application.name = "MPlayer"
(  12.816|   0.000) I: sink-input.c:     native-protocol.peer = "UNIX socket client"
(  12.816|   0.000) I: sink-input.c:     native-protocol.version = "16"
(  12.816|   0.000) I: sink-input.c:     application.process.id = "8350"
(  12.816|   0.000) I: sink-input.c:     application.process.user = "natas"
(  12.816|   0.000) I: sink-input.c:     application.process.host = "Hellraiser"
(  12.816|   0.000) I: sink-input.c:     application.process.binary = "mplayer"
(  12.816|   0.000) I: sink-input.c:     application.language = "C"
(  12.816|   0.000) I: sink-input.c:     window.x11.display = ":0.0"
(  12.816|   0.000) I: sink-input.c:     application.process.machine_id = "db26de6e1db656e815073c29482401b4"
(  12.816|   0.000) I: sink-input.c:     application.process.session_id = "db26de6e1db656e815073c29482401b4-1255946427.480604-1277222009"
(  12.816|   0.000) I: sink-input.c:     module-stream-restore.id = "sink-input-by-application-name:MPlayer"
(  12.817|   0.000) I: protocol-native.c: Requested tlength=250,00 ms, minreq=20,00 ms
(  12.817|   0.000) D: protocol-native.c: Traditional mode enabled, modifying sink usec only for compat with minreq.
(  12.817|   0.000) D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  12.817|   0.000) D: memblockq.c: memblockq requested: maxlength=4194304, tlength=48000, base=4, prebuf=44164, minreq=3840 maxrewind=0
(  12.817|   0.000) D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  12.817|   0.000) D: memblockq.c: memblockq sanitized: maxlength=4194304, tlength=48000, base=4, prebuf=44164, minreq=3840 maxrewind=0
(  12.817|   0.000) I: protocol-native.c: Final latency 460,00 ms = 210,00 ms + 2*20,00 ms + 210,00 ms
(  12.817|   0.000) D: alsa-sink.c: Requested volume: 0:  50% 1:  50%
(  12.818|   0.000) D: alsa-sink.c: Got hardware volume: 0:  50% 1:  50%
(  12.818|   0.000) D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
(  12.818|   0.000) D: alsa-sink.c: Cutting sleep time for the initial iterations by half.
(  12.818|   0.000) D: alsa-sink.c: Latency set to 210,00ms
(  12.818|   0.000) D: alsa-sink.c: hwbuf_unused=28492
(  12.818|   0.000) D: alsa-sink.c: setting avail_min=15503
(  12.818|   0.000) D: alsa-sink.c: Requesting rewind due to latency change.
(  12.818|   0.000) D: alsa-sink.c: Requested to rewind 65536 bytes.
(  12.818|   0.000) D: alsa-sink.c: Limited to 59816 bytes.
(  12.818|   0.000) D: alsa-sink.c: before: 14954
(  12.818|   0.000) D: alsa-sink.c: after: 14954
(  12.818|   0.000) D: alsa-sink.c: Rewound 59816 bytes.
(  12.818|   0.000) D: sink.c: Processing rewind...
(  12.818|   0.000) D: sink-input.c: Have to rewind 59816 bytes on render memblockq.
(  12.818|   0.000) D: source.c: Processing rewind...
(  12.818|   0.000) D: core-subscribe.c: Dropped redundant event due to change event.
(  12.818|   0.000) D: reserve-wrap.c: Device lock status of reserve-monitor-wrapper at Audio0 changed: not busy
(  12.825|   0.006) D: protocol-native.c: Client mplayer changes volume of sink input audio stream.
(  12.825|   0.000) D: alsa-sink.c: Requested volume: 0:   0% 1:   0%
(  12.825|   0.000) D: alsa-sink.c: Got hardware volume: 0:  17% 1:  17%
(  12.825|   0.000) D: alsa-sink.c: Calculated software volume: 0:   0% 1:   0% (accurate-enough=no)
(  12.825|   0.000) D: alsa-sink.c: Requested to rewind 65536 bytes.
(  12.825|   0.000) D: alsa-sink.c: Limited to 32212 bytes.
(  12.825|   0.000) D: alsa-sink.c: before: 8053
(  12.825|   0.000) D: alsa-sink.c: after: 8053
(  12.825|   0.000) D: alsa-sink.c: Rewound 32212 bytes.
(  12.825|   0.000) D: sink.c: Processing rewind...
(  12.826|   0.000) D: sink-input.c: Have to rewind 32212 bytes on render memblockq.
(  12.826|   0.000) D: source.c: Processing rewind...
(  12.826|   0.000) I: module-stream-restore.c: Storing volume/mute/device for stream sink-input-by-application-name:MPlayer.
(  12.834|   0.007) D: protocol-native.c: Requesting rewind due to end of underrun.
(  12.834|   0.000) D: alsa-sink.c: Requested to rewind 65536 bytes.
(  12.834|   0.000) D: alsa-sink.c: Limited to 32052 bytes.
(  12.834|   0.000) D: alsa-sink.c: before: 8013
(  12.834|   0.000) D: alsa-sink.c: after: 8013
(  12.834|   0.000) D: alsa-sink.c: Rewound 32052 bytes.
(  12.834|   0.000) D: sink.c: Processing rewind...
(  12.834|   0.000) D: sink-input.c: Have to rewind 32052 bytes on render memblockq.
(  12.834|   0.000) D: source.c: Processing rewind...
(  12.988|   0.154) D: protocol-native.c: Underrun on 'audio stream', 0 bytes in queue.
(  13.063|   0.074) D: protocol-native.c: Requesting rewind due to end of underrun.
(  13.063|   0.000) D: alsa-sink.c: Requested to rewind 16644 bytes.
(  13.063|   0.000) D: alsa-sink.c: Limited to 16644 bytes.
(  13.063|   0.000) D: alsa-sink.c: before: 4161
(  13.063|   0.000) D: alsa-sink.c: after: 4161
(  13.063|   0.000) D: alsa-sink.c: Rewound 16644 bytes.
(  13.063|   0.000) D: sink.c: Processing rewind...
(  13.063|   0.000) D: sink-input.c: Have to rewind 16644 bytes on render memblockq.
(  13.063|   0.000) D: source.c: Processing rewind...
(  14.092|   1.029) D: protocol-native.c: Underrun on 'audio stream', 0 bytes in queue.
(  14.615|   0.522) D: alsa-sink.c: Requested volume: 0:  50% 1:  50%
(  14.615|   0.000) D: alsa-sink.c: Got hardware volume: 0:  50% 1:  50%
(  14.615|   0.000) D: alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
(  14.615|   0.000) D: alsa-sink.c: hwbuf_unused=0
(  14.616|   0.000) D: alsa-sink.c: setting avail_min=15502
(  14.616|   0.000) D: alsa-sink.c: Requested to rewind 65536 bytes.
(  14.616|   0.000) D: alsa-sink.c: Limited to 30388 bytes.
(  14.616|   0.000) D: alsa-sink.c: before: 7597
(  14.616|   0.000) D: alsa-sink.c: after: 7597
(  14.616|   0.000) D: alsa-sink.c: Rewound 30388 bytes.
(  14.616|   0.000) D: sink.c: Processing rewind...
(  14.616|   0.000) D: module-suspend-on-idle.c: Sink headphones becomes idle, timeout in 5 seconds.
(  14.616|   0.000) D: source.c: Processing rewind...
(  14.616|   0.000) D: module-suspend-on-idle.c: Sink headphones becomes idle, timeout in 5 seconds.
(  14.616|   0.000) D: core.c: Hmm, no streams around, trying to vacuum.
(  14.618|   0.001) I: sink-input.c: Freeing input 1 "audio stream"
(  14.619|   0.000) I: client.c: Freed 4 "MPlayer"
(  14.619|   0.000) I: protocol-native.c: Connection died.
(  18.390|   3.771) D: cli.c: CLI got EOF from user.
(  18.391|   0.000) I: main.c: Herunterfahren des Daemon gestartet.
(  18.391|   0.000) I: module.c: Unloading "module-device-restore" (index: #0).
(  18.392|   0.000) I: module.c: Unloaded "module-device-restore" (index: #0).
(  18.392|   0.000) I: module.c: Unloading "module-stream-restore" (index: #1).
(  18.393|   0.001) I: module.c: Unloaded "module-stream-restore" (index: #1).
(  18.393|   0.000) I: module.c: Unloading "module-card-restore" (index: #2).
(  18.394|   0.000) I: module.c: Unloaded "module-card-restore" (index: #2).
(  18.394|   0.000) I: module.c: Unloading "module-augment-properties" (index: #3).
(  18.394|   0.000) I: module.c: Unloaded "module-augment-properties" (index: #3).
(  18.394|   0.000) I: module.c: Unloading "module-alsa-sink" (index: #4).
(  18.395|   0.000) D: core-subscribe.c: Dropped redundant event due to change event.
(  18.395|   0.000) D: alsa-sink.c: Thread shutting down
(  18.396|   0.000) I: sink.c: Freeing sink 0 "headphones"
(  18.396|   0.000) I: source.c: Freeing source 0 "headphones.monitor"
(  18.400|   0.004) I: module.c: Unloaded "module-alsa-sink" (index: #4).
(  18.401|   0.000) I: module.c: Unloading "module-alsa-sink" (index: #5).
(  18.401|   0.000) D: alsa-sink.c: Thread shutting down
(  18.402|   0.000) I: sink.c: Freeing sink 1 "hifi"
(  18.402|   0.000) I: source.c: Freeing source 1 "hifi.monitor"
(  18.405|   0.002) I: module.c: Unloaded "module-alsa-sink" (index: #5).
(  18.406|   0.000) I: module.c: Unloading "module-udev-detect" (index: #6).
(  18.406|   0.000) I: module.c: Unloaded "module-udev-detect" (index: #6).
(  18.407|   0.000) I: module.c: Unloading "module-esound-protocol-unix" (index: #7).
(  18.407|   0.000) I: module.c: Unloaded "module-esound-protocol-unix" (index: #7).
(  18.407|   0.000) I: module.c: Unloading "module-native-protocol-unix" (index: #8).
(  18.408|   0.000) I: module.c: Unloaded "module-native-protocol-unix" (index: #8).
(  18.408|   0.000) I: module.c: Unloading "module-gconf" (index: #9).
(  18.412|   0.003) I: module.c: Unloaded "module-gconf" (index: #9).
(  18.412|   0.000) I: module.c: Unloading "module-default-device-restore" (index: #10).
(  18.412|   0.000) I: module.c: Unloaded "module-default-device-restore" (index: #10).
(  18.413|   0.000) I: module.c: Unloading "module-rescue-streams" (index: #11).
(  18.413|   0.000) I: module.c: Unloaded "module-rescue-streams" (index: #11).
(  18.413|   0.000) I: module.c: Unloading "module-always-sink" (index: #12).
(  18.413|   0.000) I: module.c: Unloaded "module-always-sink" (index: #12).
(  18.414|   0.000) I: module.c: Unloading "module-intended-roles" (index: #13).
(  18.414|   0.000) I: module.c: Unloaded "module-intended-roles" (index: #13).
(  18.414|   0.000) I: module.c: Unloading "module-suspend-on-idle" (index: #14).
(  18.414|   0.000) I: module.c: Unloaded "module-suspend-on-idle" (index: #14).
(  18.415|   0.000) I: module.c: Unloading "module-console-kit" (index: #15).
(  18.415|   0.000) D: module-console-kit.c: Removing session /org/freedesktop/ConsoleKit/Session1
(  18.415|   0.000) I: client.c: Freed 0 "ConsoleKit Session /org/freedesktop/ConsoleKit/Session1"
(  18.415|   0.000) D: module-console-kit.c: Removing session /org/freedesktop/ConsoleKit/Session3
(  18.415|   0.000) I: client.c: Freed 1 "ConsoleKit Session /org/freedesktop/ConsoleKit/Session3"
(  18.426|   0.011) I: module.c: Unloaded "module-console-kit" (index: #15).
(  18.427|   0.000) I: module.c: Unloading "module-position-event-sounds" (index: #16).
(  18.427|   0.000) I: module.c: Unloaded "module-position-event-sounds" (index: #16).
(  18.427|   0.000) I: module.c: Unloading "module-cork-music-on-phone" (index: #17).
(  18.427|   0.000) I: module.c: Unloaded "module-cork-music-on-phone" (index: #17).
(  18.428|   0.000) I: module.c: Unloading "module-cli" (index: #18).
(  18.428|   0.000) I: client.c: Freed 2 "Unknown client"
(  18.428|   0.000) I: module.c: Unloaded "module-cli" (index: #18).
(  18.428|   0.000) I: main.c: Daemon beendet.


More information about the MPlayer-dev-eng mailing list