intermittant and out of order audio

[rudolfc]

On my Asus P5E3 mainboard audio plays back distorted. It sounds like some buffers are played correctly, then a brief silence is heard, and a few buffers are played out of order or in incorrect speed (metallic sound like effect). This sequence is repeated for ever.

I tested with MediaPlayer, vlc and CLamp. CLamp on lower or higher speeds gives the same effect (no influence). This behaviour exists on my system ever since I first installed Haiku, some 6 months ago or so..

The mainboard has a HDA chipset, so I tested with this one with the driver that currently gets updated from time to time (no effect), and I compiled ES1370 in the haiku source tree and tested with a SB64 soundcard: same symptoms.

I recompiled MediaEventLooper.cpp, and enabled debugprinting (three lines in function BMediaEventLooper::ControlLoop().

From the looks of it the Timestamps on the buffers are OK but Getting realtime for performance time messes up. I'll attach a small file with the shell debug output from MediaPlayer.

I am using a Core2Duo E8200 CPU @ 2.66Ghz, which is a 45nm Intel CPU. It's recognized as a Pentium4 Extreme edition BTW. Memory is DDR3 running at 1066Mhz.

[rudolfc]

The attached file first has output coming from running vlc, after that I run MediaPlayer. If different Mediacontent (video for example) is played, the error is still there.

Bye!

Rudolf.

[scottmc]

I get the same effect here. But it's less noticeable if I am playing a "wav" file copied from a cd, vs. playing an mp3 file. Also when running sdl (or allegro) games from a terminal you'll usually see lots of error messages about the sound lagging or something like that. Not sure if that is related or not. Note that I am also using the HDA driver.

[rudolfc]

Something is indeed going wrong with TimeSource()->RealTimeFor(fEventQueue.FirstEventTime()... in MediaEventLooper.cpp, ControlLoop() AFAICT.

I enabled variable dumping in TimeSource.cpp, function GetTime() which is ultimately called from the controlloop it seems.

I attached the resulting grabbed Terminal output above. It's clear that this routine reports enourmous drifts (in time that is?). This variable varies from 0.4 to 2 or so while it should be around 1.0 I take it...

Bye!

Rudolf.

[stippi]

Yes, that is an interesting subject. In the OSS Media Node, which was based on the regular MultiAudio Media Node that is used with this HDA driver, I had a lot of fun with computing the drift. I believe the computation in the MultiAudio Node may be much too simple, since it has way too drastic discontinuities. In the OSS Node, I keep a rotating buffer of the recent drift values and the resulting drift value is the average of all those, so it changes more smoothly.

[korli]

Interesting in fact, though my understanding is it wouldn't help anyway if the audio interrupt is lagging. The drift shouldn't go far from 1.0, except in case of problem.

[stippi]

That's true. But I did have to come up with this solution while testing the OSS Node on ZETA 1.2. So while Haiku certainly still has problems (scheduling high priority threads?), it was nevertheless necessary on ZETA, too. On Haiku, audio skipping is still pretty likely, while on ZETA, there wouldn't be any with the OSS node. But without the drift smoothing, it would always playback with frequent cracks in ZETA.

[rudolfc]

Hi Guys,

I copied over drift averaging (locally here) from the oss multimedia-addon to the default multimedia-addon and retested on my system. Drift is nolonger jumping, looks a lot better. However, the sound still skips in more or less the same way. I added two new files:

BTimeSource-avg-drift-oss-1 shows only the control-loop 'debug' messages: nolonger late messages it seems, though there are still skips in realtime moments for the buffers.

In BTimeSource-avg-drift-oss-2 the gettime function dumps stuff as well, here you can see the drift nolonger jumping as before.

Anyhow, this by itself is no solution apparantly.

I've got a few questions:

In the OSS node I saw a lock being held during updating the timesource: fDevice->Locker()->Lock()

This is not done in the default hmulti_audio_addon. (?) Could that be a problem?

And another question: I stated I tested with HDA hardware but also with SB64 (ES1370) hardware, resulting in the same distorted output. Does this rule out your hardware interrupt time-lagging?

(I could retest to see if different lines are used?)

Thanks and Bye!

Rudolf.

[rudolfc]

Hi again.

I have to add a comment: I just let my girlfriend listen to the audio (she's been hearing a lot lately ;-) and she reports audio is now playing with a lot less interruptions and if they come, they are shorter in timespan. I played a few more files and I have to conclude she's right. Some files are even bearable now :-)

So although the error still persists, the distortions resulting from it are minimized more. Come to think of it, it's actually what you can already see in the files I attached, no buffers are skipped now while before one buffer was delayed soo much in time the following 4 or so buffers were dumped as well before continuing playback.

This is nolonger the case.

If I think about what Stephan said I'd say this drift-averaging makes audio more robust indeed. Don't know what effect it has if you use a mediaplayer with variable playback speed though: will it respond less promptly on settings changes for instance? I'd say some sort of optimum/compromise would have to be found, but improvement over the current default multi-media-addon is certainly possible.

I'll leave that upto others though ;-)

Bye!

Rudolf.

[korli]

Rudolf,

could you add timestamp logging in your hda (or es1370) driver, and also display the difference with the last timestamp ? This way you can eventually check what happens in your interrupt handler.

I agree the drift-averaging is useful in your case, but it hides the cause.

[korli]

Forgot, could you post a patch for multiaudio? Thanks

[stippi]

Replying to rudolfc:

If I think about what Stephan said I'd say this drift-averaging makes audio more robust indeed. Don't know what effect it has if you use a mediaplayer with variable playback speed though: will it respond less promptly on settings changes for instance? I'd say some sort of optimum/compromise would have to be found, but improvement over the current default multi-media-addon is certainly possible.

No, the drift averaging will have no effect whatsoever on the latency. It's really just a way to get a smoother change in drift. Drift in audio happens when the true clock frequency of the audio hardware is slightly different from what it's supposed to be. Like 48005 Hz instead of 48000 Hz. It is not uncommon. The Media Kit can compensate this by sending buffers at a slightly faster or slower rate, it could even to have audio playback at the correct speed anyways, but I am not a fan of that, since it degrades quality, no matter how good the resampler. I'd rather have a song be 0.5 seconds shorter or faster. You calculate the drift in the Media Kit node by comparing the expected buffer duration (performance time) with the measured buffer duration (OS real time clock). Usually, the node will wait on an interrupt of the hardware (ie a semaphore released by the driver), and since it runs at realtime priority, it should wake up as soon as possible when the driver releases the semaphore. This *seems* to be where Haiku currently still has some problems. But obviously one effect of that is less accurate drift calculation, since the measurement of the realtime between two buffers, respectively two semaphore wake ups, is less accurate. The averaging should be useful even if the wakeup latency would be much better on Haiku, since it will never be perfect. And as I already explained, it was necessary on ZETA as well (tested with C-Media hardware). In any case, the latency for userland applications is totally uneffected by all this.

[rudolfc]

Hi Korli,

I don't think drift averaging hides the problem: seriously, you can't miss it. BTW I tested haiku on more systems (over at my work) on which audio does work OK. But if you start firefox for instance, audio will stutter anyway. I think that if averaging would prevent that on these systems, that it's good to have.

Maybe starting firefox is not a good example, but I guess variable latency is bound to happen to some extent on any system outthere: that should not be a problem for audido playback.

I'll test dumping time as you suggested if I can get it done (it's all new os parts for me you know). Also, I don't know how to make a diff file. I take it that can be created automatically somehow?

Bye!

Rudolf.

[rudolfc]

Hi,

I've got an important update. I found out what was troubling me!! It turns out that there are actually two faults haunting me:

one: the audio files were corrupted by Haiku. I copied over the files once again from the original source (exact same creation time and date and size) and half the distortions went away!! Unfortunately I don't know when this happened, probably half a year ago already. Since then some updates to bfs were made if I remember correctly, so I'm hoping I won't encounter this again!

(though on system crashes I see the last few lines of sourcefiles dissappear regurarly, which I discover because builds later-on fail).

second, and _very_ interesting: the function dprintf() messes up audio INT timing! So probably all INT timing is messed up by this function.

Here's what I found: It turns out the SCSI AHCI driver caused the audio intermitting. This only happens if I have no CD in the SATA DVD burner. If I have no disc in, you see port4 errors (that's my HD), and port5 errors (which is the DVD burner). As soon as I put in a data CD: all AHCI error messages are gone. You can simply check the (first) syslog already attached to this bugreport, you'll find the errors in there.

If I remove all TRACE and dprintf() calls in the AHCI driver: audio is perfectly OK. So, the actual behaviour of the ACHI driver isn't changed, though audio is now OK!

OK, I was interested in short interruptions in audio as well because of having the Media prefs app running: if you select the HDA driver tab for all slider settings then audio skips as well. It turns out this driver does some dprintf() calls (directly or via TRACE). Simply disabling these calls solve the intermittant audio while playing around with the Media prefs app.

-->>> dprintf() seems to be the problem, and I expect for many users!!!

What are we going to do? Close this burreport and create a new one for dprintf()???

Bye!

Rudolf.

[stippi]

Interesting. In your settings/drivers/kernel file, you can disabled syslog debug output and/or serial debug output. For which combinations of disabled syslog and/or serial debug output do you still get skippy audio when you re-enable the dprintf() calls? My personal bet would be that serial debugging is causing it, but I may be wrong.

[rudolfc]

Yep!

Stephan, you're totally right. Disabling serial debug output (as the one and only change to the kernel settings file) fixes the problem of intermitting audio!!

And quess what: this system does NOT HAVE a serial port!!

Could it be that not having this port is the real problem??

Rudolf.

[rudolfc]

And correction: I do have one com port.

Anyhow: it should not block/influence INTs this much causing the audio problem???

[rudolfc]

The com port seems to be COM1 (3F8/IRQ4). listdev doesn't list it though.

I'll test the com port to see if actual debug output comes out tommorrow or so and let you know.

I hope this can be solved: otherwise this source of audio (and probably other) trouble should be made known with the 'fix' of disabling serial debug output? Or maybe disable it by default instead of keeping it enabled by default?

Bye!

Rudolf.

PS: Thanks for the pointers everyone: it's what I needed to get this far :-)

[stippi]

Glad we could find the culprit. I believe this lagging issue when writing to the serial port (even if there is no real outlet), is actually normal behavior, though I could be wrong of course. The serial port debugging is actually quite useful for a lot of situations, even if your hardware doesn't have a port (like getting output in the Terminal from where you run Haiku within QEMU and such stuff).

But anyhow, if you have no use for serial debug output, please feel free to disable it. It will not stay on by default for the real release I would guess.

[axeld]

Serial debug output is for debugging purposes only. It's not interrupt driven, and the interface is *pretty* slow for today's standards. Release builds won't have this enabled by default.

So that audio may stutter during debug output is to be expected (not that I have thought of this earlier when looking at Haiku's audio problems...).

Should we keep this open for the multi-audio drift problems?

[stippi]

Rudolf, could you please attach your changes to the Multiaudio node here? That will save some work for me or Jerome. Thanks!

[rudolfc]

Hi:

Axel,

So, if the serial debug output is NOT interrupt driven, why does it (seem to) block/delay ints for other devices? Please have a look at file dump_int_time_div_ser_debug_off to see the debug output in the syslog when serial debug is turned off, and compare it to dump_int_time_div_ser_debug_on: the lines starting with KERN: H5: are printed from within the HDA driver's interrupt service routine processing audio buffers (2 streams). The time_div between each INT entry should be around 42667 uS. (can be calc'd as well)

When serial debug is enabled the INT routine behaves erratical: there are entrys with big faulty time-divs around the dprintf() messages from the sata driver.

Are you sure that's normal? In my opinion, if some routine is dumping messages to a serial port, without using ints, and without disabling ints, this cannot happen.

In the HDA driver, in file hda_controller.cpp, in routine hda_interrupt_handler(), I added the time-div dprintf stuff, see attached file: hda_snippet.

Thanks in advance for looking. If you still say it's normal behaviour after looking at the HDA driver stuff I just mentioned, I'll nolonger trouble you guys further and just disable serial debugging.

BTW: I just checked if serial debugging actually works on my system: it does. At 115k2, and I get no <truncated> messages across it. Still, syslog and listdev do not mention the existance of the serial port.

Stephan,

I'll look once again at the Timesource stuff and post something here. I want to see if I can write it somewhat less messy... :)

Bye!

Rudolf.

[anevilyak]

Replying to rudolfc:

Still, syslog and listdev do not mention the existance of the serial port.

That's actually normal: listdev currently lists nothing other than PCI devices, which the UART driving the serial port is not.

[axeld]

As it's not interrupt driven, it needs to manually write to the serial port, and, of course, it needs to protect this with a spinlock. So it blocks out interrupts during that time, messing up their timing.

When you turn on serial output under BeOS R5, the system becomes pretty much unusable with lots of output, as the serial line speed defaults to 19200 baud there.

[rudolfc]

Ah, OK.

This means that intermittant audio on a system is a (reasonable strong) pointer to some driver or program having difficulty and thus dumping stuff in the syslog in practice I take it. My laptop and a system at my work have OK audio so the syslog should be reasonable quiet there. I still have two more questions though: would using an int for the serial port fix this? And: why isn't an int used?

Thanks for the explanations (beforehand)!

Bye,

Rudolf.

[tqh]

I also experience stutters which may or may not be related to drifts. Disabling Serial debug don't help, but disabling one (of two) processors does solve the problem for me. I'm curious if the drift handling might help this. See #1072 for more hda related info.

[tqh]

Rudolf, could you share the patch that improves multi_audio from opensound?

[ithamar]

Rudolf, in case you still want an answer about why the serial output is so blocking:

It is made so blocking as to make sure that by time dprintf() returns the string specified has actually gone over the port. This is essential for debugging e.g. crashes in drivers, so you know for sure you're looking at the last dprintf() output before the crash.

It is really only intended for kernel debugging purposes, or at least extreme debugging for most of us devs, and therefore it was off by default in BeOS, and, when we know all kernel-space code is perfect (:P) it'll be default off for Haiku !

Axel is absolutely right in saying that performance suffered even more under BeOS, you _really_ only wanted to enable that if you had a _good_ reason....

Hope this helps....

[rudolfc]

Hi,

Thanks Ithamar, this is the missing piece of info I was searching for. I take it this explains the 'of course' part of axel's last message here..

As far as I'm concerned my problem is no problem anymore. I only hope others encountering timing trouble involving ints are instructed to disable serial debugging so they don't have to live with this problem and possibly post tickets for them.

I know the value of the serial debugging feature indeed, since I used it a lot on R5 in the old days BTW :-)

About the mod I did on the multiaudio node: I still didn't find the time to look at it, clean it up a bit, and post it here. I'll do it as soon as I find some time..

Bye!

Rudolf.

[tqh]

Disabling serial doesn't change anything here. Rudolf, could you pleeease supply your drifting patch from oss so that we can try if this helps any.

[scottmc]

I have been looking through older tickets and found 7 other tickets that may or may not be related to this issue: #1279, #1425, #2402, #2512, #2787, #2871 and #3079.

[rudolfc]

Modified to behave like oss node for BTimeSource

[rudolfc]

Hi,

I've just added the file MultiAudioNode.cpp, the modified version I used to prevent sudden jumps for BTimeSource. Modification was taken from the oss media add-on.

I hope you can just drop this file in place of the original one to test with the modification.

I didn't cleanup (sorry). You can easily find my modifications though, just search for "rudolf" in the file.

Bye!

Rudolf.

[rudolfc]

Update: (oops)

please uncomment the drift averaging part before compiling: Line 1536 trough 1539.

(sorry..)

Bye!

Rudolf.

[tqh]

Rudolf's changes updated in patch form

[tqh]

I havn't noticed any improvement on my system, even with debugging and most drivers disabled. So while it might improve things, I have some other problem.

[korli]

Is this bug still valid ?

[rudolfc]

Hi there,

I guess not.

• the skipping audio can be prevented by disabling serial debugging. Since I do that it's OK on my computer. The sudden jumps/BtimeSource thing might still apply: don't know if someone looked that over.

Bye!

Rudolf.

[pulkomandy]

Well rudolf agreed 10 years ago that there was nothing to fix here. So let's close the ticket. tqh, if you still have problems 11 years later I think it's a good idea to open a separate ticket for it?