Re: need help with AUHAL audio glitching at high cpu utilisation
Re: need help with AUHAL audio glitching at high cpu utilisation
- Subject: Re: need help with AUHAL audio glitching at high cpu utilisation
- From: Jeff Moore <email@hidden>
- Date: Mon, 6 Jul 2009 15:54:40 -0700
Sorry this took so long. I've been out on leave for the past week or so.
At any rate, yes it certainly looks like the audio driver in question
is returning the error from the kernel trap at a time when I wouldn't
expect an error. There have been several similar reports in the past
(including a few filed by myself). It can't hurt to file a bug report
about your particular case though.
On Jul 2, 2009, at 6:55 PM, Ross Bencina wrote:
Hi Jeff
Are you able to offer any further insight into the issue below?
Stephane Letz reproduced similar behavior on another machine
(kAudioDeviceProcessorOverload being set) with 70-80% CPU. Should
we file a bug report?
Thanks
Ross.
===================================
AudioMulch 2.0 is here!
http://www.audiomulch.com
----- Original Message ----- From: "Ross Bencina" <email@hidden
>
To: "CoreAudio API" <email@hidden>
Sent: Thursday, June 25, 2009 8:43 PM
Subject: Re: need help with AUHAL audio glitching at high cpu
utilisation
Hi again Jeff
(sorry about the dup, didn't reply to list the first time)
I've generated some telemetry from HALLab now, and the results
confuse me
and imply that neither variance in CPU clock speed, execution time
of my
code, nor CA doing extra work, nor scheduling jitter is the cause
of the
glitching I'm observing:
http://www.audiomulch.com/~rossb/junk/patest_telemetry.png
This dump is from running a simple application that mixes 175 sine
waves
generated with the sin() function. It consumes about 85% CPU on my
first gen
MacBook (according to my gettimeofday measurements). The nominal
sample rate
was 44100Hz with 256 frame i/o buffers. I was using built in audio
with
external speakers.
btw. I tried to save the dump out as text but the text file
contained data
in a different format and didn't include the event names. Is there
a way to
get the data in a more analyzable form without writing my own
telemetry
client? Its a shame i can't cut and paste the contents of the
telemetry
window into a text file.
I think I understand the data (but see below for some questions)
and I'm
still not sure why the writes are returning the late error (I found
somewhere where you noted that 0x2EE is a missed deadline).
Here's my analysis, please let me know what you think:
I'm outputing 256 sample blocks at nominal SR of 44100Hz. The
indicated rate
is 1.000002, so the actual sample rate is 44100.088, giving a block
period
of 5.805ms.
Now, if we consider the overrun with timestamp 299.841:
229.81 (+5.876, +0.103)
->cycle 229.842 ( 0.000)
->calls 229.844 (0.002)
->ioproc 229.845 (0.002)
<-ioproc 234.895 (5.049)
sig out: 234.896 (0.001)
<-calls 234.896 (0.001)
->write 234.897 (0.001)
<-write 234.912 (0.015)
<-cycle 234.939
The processing cycle starts 0.103ms late (presumably due to
scheduling
jitter). The total duration of the processing cycle (including any
write
overhead) is 5.071ms (234.912 - 229.841), if we include the
scheduling
jitter, the time from the ideal cycle start time to "<-
write" (presumably
write completion) is 5.174ms. Given that the block period is
5.805ms it is
unclear to me why write() is marking this as an underrun. What
actually is
it that CA is writing to that's indicated by <-write/->write? And
why would
it return that the data is late when according to my analysis above
it is
being delivered within bounds? I could guess that the driver
actually needs
the data earlier than it has requested it, or that the phase of the
CA
cycles is lagging what is necessary but I don't really know.
A separate observation is that the entire cycle takes 5.098ms
(234.939-229.841) yet the following cycle is scheduled at +10.977
which
suggests that CA has dropped a cycle even though the entire cycle
at 229.841
executed within 5.805ms of the schedule cycle start time.
5.098 is about 87% of 5.805 which suggests that CA is throttling at
less
that 100% utilisation.
Can you explain this behavior please?
Now for some questions about the AUHAL telemetry events. I found some
documentation about the CA telemetry events in a header file but it
didn't
really enlighten me. Could you please correct, fill in the gaps and
answer
the questions below?
->cycle = start of io cycle. the thread has just woken up
( what happens here? )
-> calls = what does this indicate?
(what happens here?)
-> ioproc = call to user io processing routine?
(user performs processing)
<- ioproc = user io processing routine returns?
(what happens here?)
<- calls = what does this indicate
(what happens here?)
-> write = CoreAudio writes buffers to the driver (does it invoke
the driver
synchronously here or is there some async handshake?)
<- write = Driver has completed writing samples to the device (by
this time
audio data is definitely queued with the driver)
(what happens here?)
<-cycle = end of io cycle, the thread is about to go to sleep
until the
next deadline
--
You mentioned that CA does extra processing to handle speaker
protection,
does this happen in the IO thread? if so where in the telemetry
sequence
does this occurr?
Thanks!
Ross.
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Coreaudio-api mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Coreaudio-api mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden
--
Jeff Moore
Core Audio
Apple
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Coreaudio-api mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden