Bug 464998

Created attachment 264232 [details]
example y2log with debug enabled

here an example debug log when moving a slider from 78 to 93, it takes about 5 seconds : seems as if it's writing config for every single change in value

I have reproduced it - the problem is caused by the enabled debug mode. Every single volume change results in about 4kB text written to the yast log. If you move a slider very fast the result might be even about 1MB written to the log. And that's why it's so slow.

If you disable the debug mode then the sliders should move immediately.

Cannot confirm this, when I do not enable debug mode, it's also slow.

It depends on the pace with which you begin to drag.
If you drag the fastest you can from 0 to hundred, the counter moves in bigger steps -> 3 seconds
If you drag slowly in the beginning then faster it keeps the slow peace (one unit at a time) -> 30 seconds
IMHO, that's a rather dumb interface

other method:
If I keep pushing the up or down sign, it takes 15 seconds

This desktop Computer is unloaded ( at about 95% idle all the time )
AMD Athlon(tm) 64 X2 Dual Core Processor 4000+ with 2GB memory

Created attachment 264620 [details]
/var/log/boot.msg

wondering if this could be a kernel / timing issue
know any benchmark I could run to sort this out ?

That's strange, I cannot reproduce it, the sliders move fast here. The only case when it was slow was in the debug mode with watching the log in a terminal which is not very common situation.

Could you reproduce it in another mixer application (kmix or something similar)?

in kmix, response time is satisfactory because it adapts pace while moving. but when I drag slowly, I can see it hop about 3 times per second. If I drag fast, it will make bigger hops.
I rebooted also on my old installation on that machine (opensuse 10.2) : here 'yast2 sound' behaves even faster than kmix, the cursor is *very* responsive.
Installed latest bios (P1.90 -> P2.80)
Installed X driver from Nvidia repository, I'm impressed with the desktop effects :) but this didn't change anything for our problem.

I then tried an "strace -Tttv -s 128 -p 6213 -o sound.trace" command on the y2base process, this seems to be very informative :

One iteration takes about 350 ms, (81 syscalls) cumulated syscall time accounts for most of it.
Especially ioctl's on the /dev/snd/controlC0 account for about 320 ms

/dev/snd/controlC0 is opened RO / closed /opened RW /closed at each iteration, why not leave it open ?

are really that much ioctl (70) necessary to change the value of one control ?

so the added latency of the usb communication amplifies the effect on my system

Created attachment 264898 [details]
strace output for test "yast2/sound/volume"

Thank you for the details. The mixer part in yast2-sound has not been changed since 10.2, the problem is in kernel (USB) or ALSA (snd-usb-audio driver).

Likely a USB-stack problem.

Could you run strace on amixer and give a similar time measurement for syscalls?

Sorry, amixer and alsamixer insist on using pulseaudio, even if I tell yast not to enable it, it starts.
When I do not start kde, it doesn't work either.
Any hint or an alternative mixer to try?

Use -Dhw option.  If it's the secondary card, give "-Dhw:1".

Created attachment 265240 [details]
strace output for amixer -Dhw:0 --stdin

I pasted repetitively (40x) the command "set PCM 1%-" to amixer

there are 8 ioctl per iteration accounting for 52ms to 150ms, mean 66ms

so yast2: 70 ioctl -> 350 ms
  amixer: 8 ioctl -> 66 ms

I'd say same problem for amixer even if it uses ioctl's more effectively

Thanks, then it's apparently a driver / USB-bus issue.

I changed the usb-audio driver code to cache mixer values.  The patch was currently on sound-unstable tree, and alsa-driver-unstable-kmp package is available on OBS multimedia:audio:KMP repo for update:
    http://download.opensuse.org/repositories/multimedia:/audio:/KMP/

The package is being built and will be available in today, I guess.  You can install alsa-driver-unstable-kmp*.rpm corresponding to your kernel.

Give it a try later and let me know if it gives any improvement.

tried alsa-driver-unstable-kmp-default-1.0.18.20090116_2.6.27.7_9.1-2.1
with kernel-default-2.6.27.7-9.1

It does indeed improve, it shows normal behavior in "yast sound volume" module

I guess there are other changes also in these modules, because in playback I have these messages in /var/log/messages and playback is suspended after about 25 seconds:

Jan 16 18:47:25 linux-bcpx pulseaudio[4859]: cpulimit.c: Recevied request to terminate due to CPU overload.
Jan 16 18:48:37 linux-bcpx pulseaudio[5464]: main.c: High-priority scheduling enabled in configuration but not allowed by policy.
Jan 16 18:48:37 linux-bcpx pulseaudio[5464]: core-util.c: setpriority(): Permission denied
Jan 16 18:48:37 linux-bcpx pulseaudio[5464]: ltdl-bind-now.c: Failed to find original dlopen loader.
Jan 16 18:48:37 linux-bcpx pulseaudio[5466]: module-alsa-source.c: Your kernel driver is broken: it reports a volume range from -16.00 dB to -16.00 dB which makes no sense.
Jan 16 18:48:55 linux-bcpx pulseaudio[5466]: module-alsa-sink.c: Increasing wakeup watermark to 40.00 ms
Jan 16 18:49:21 linux-bcpx pulseaudio[5466]: cpulimit.c: Recevied request to terminate due to CPU overload.

to 2 "top" most processes
 5936 mm        20   0  321m 4992 3752 S   88  0.2   0:07.86 pulseaudio
    6 root      15  -5     0    0    0 S   12  0.0   0:17.40 ksoftirqd/1

Didn't want to alarm you, when I bypass pluseaudio with "aplay -Dhw:0" , everything is fine

Thanks, good to hear that something gets improved.

About the error messages -- the "-16.00 dB to -16.0dB..." should have appears in the original driver, too, as there is no change regarding this.
Basically it's no real driver bug.  It's a hardware that gives the broken information.

I'll back-merge the patch to the main tree so that you can try alsa-driver-kmp (no stable version) later.

The new driver with the fix is being built for alsa-driver-kmp package.
Please uninstall alsa-driver-unstable-kmp and install alsa-driver-kmp instead later (the build should be finished in today).

I tested with the new alsa-driver-kmp-default-1.0.18.20090117_2.6.27.7_9.1-2.1, this works also fine and no more problems with pulseaudio.
About the "-16.00 dB to -16.0dB..." error messages, they didn't appear with the original driver and do no longer appear now that I installed this driver.
I am happy with this fix, thanks a lot

Thanks for checking.  PA and the mixer-error issues may be then only by some patches in unstable tree.

Unfortunately, the cache feature is a bit too late to merge into 11.1 line since it's a non-security issue.  But you can use always alsa-driver-kmp as updates, so let's close this bug now.