asterisk users - Jun 2005 - Zap Clocking - Frame Slips - tdm400p wcfxo zttest cpu spikes spandsp

I've made some modifications to zttest in order to use
it as a frame clock accuracy tester / slip detector.
I'm not certain if that was it's original purpose, but it
seems that a lot of folks try to use it that way.
The result is something that I'm calling ztclock for now
to help avoid confusion.

I'm including the source at the end of this post.  You
can compile it by placing the source in your zaptel
source directory as ztclock.c and building with:
cc -I. -O3 -g -Wall ztclock.c -o ztclock

Here is a sample run of the test:

-- snip --
./ztclock


ztclock - clock source accuracy test (3 passes)

Flushing input buffer...
Flush Complete.

Test is approximately 3 minutes.  Please wait...

483328 samples in 60.410900 sec. (483288 sample intervals) 99.991722%
483328 samples in 60.410901 sec. (483288 sample intervals) 99.991722%
483328 samples in 60.410899 sec. (483288 sample intervals) 99.991722%

Estimate 8 frame slips every 12.083200 seconds.
-- snip --

Background:
During routine codec/dimensioning testing, I observed a strange,
recurring cpu spike occuring appoximately every 12 seconds on a
completely idle system with only the zaptel drivers loaded. I used
'vmstat 1' to monitor this. I was using the wcfxo driver (wildcard
fxo) as a timing source.  After switching to the ztdummy driver and
using the usb controller as a clock source, I observed that the frequency
of the CPU spikes changed to approximately every 5.5 seconds.  Hmm...
Also, as additional channels were added to the system, the CPU spikes
increased in intensity (ie: from 15% utilization to 50% each spike).

Further research indicated that many folks using various flavors of
FXO cards were experiencing similar observations as well as problems
with data applications such as spandsp.  Some of them are observing
similar CPU spikes using the TDM400P hardware. I tried to use zttest
to put a finger on the problem, but could not seem to get the resulting
math to work out.  I believe that ztclock may provide some insight into
what is happening with those spikes.  The test attempts to first determine
the accuracy of your clock source compared to the results that could be
expected from a true 8khz clock source.  Once this is accomplished, it
uses the results of the third pass in an attempt to calculate the time
frequency that you should expect to see 8 frame slips.  I selected 8
frame slips for the calculation instead of 1 because it appears that the
zaptel driver moves 8 samples / interrupt / channel.  It also appears
that the data is clocked across the PCI bus in a similar manner.
My calculated frame slip result seems to correspond directly with the
frequency of the CPU spikes that I observed, suggesting a possible
relationship.

I'd like to hear from anyone who may be tracking this or similar issues.
I'd also like to hear some feedback on the ztclock program itself in terms
of how it seems to work against various clock sources that you may have
available.

Thank you.  Source Follows...

--snip--
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <errno.h>
#include <string.h>
#include <fcntl.h>
#include <sys/time.h>
#include <sys/signal.h>
#include <math.h>

int main(int argc, char *argv[])
{
        int fd;
        int res;
        int count=0;
        int pass=1;
        int lastcount;
        char buf[1024];
        float score;
        float t_usec;
        float t_sec;
        float t_intervals;
        float sf;
        struct timeval start, now;
        fd = open("/dev/zap/pseudo", O_RDWR);
        if (fd < 0) {
                fprintf(stderr, "Unable to open zap interface: %s\n",
strerror(errno));
                exit(1);
        }
        printf("\n\nztclock - clock source accuracy test (3
passes)\n");
        /* Flush input buffer */
        printf("\nFlushing input buffer...\n");
        gettimeofday(&start, NULL);
        for (count = 0;count < 64; count++)
                res = read(fd, buf, 1024);
        gettimeofday(&now, NULL);
        count = 0;
        start = now;
        printf("Flush Complete.\n\nTest is approximately 3 minutes. 
Please wait...\n");
        for(;;) {
                res = read(fd, buf, 1024);
                if (res < 0) {
                        fprintf(stderr, "Failed to read from pseudo
interface: %s\n", strerror(errno));
                        exit(1);
                }
                count += res;
                if (count >= 483328) {
                        gettimeofday(&now, NULL);
                        t_usec = ((float)now.tv_sec - (float)start.tv_sec)
* 1000000;
                        t_usec += ((float)now.tv_usec -
(float)start.tv_usec);
                        t_sec = t_usec / 1000000;
                        t_intervals = ceil(t_usec / 125);
                        start = now;
                        printf("\n%d samples in %f sec. (%d sample
intervals) ", count, t_sec, (int)t_intervals);
                        score = 100.0 - 100.0 * fabs((float)count -
t_intervals) / (float)count;
                        printf("%f%%  ", score);
                        fflush(stdout);
                        pass++;
                        lastcount = count;
                        count = 0;
                        if (pass > 3) {
                                if (lastcount == (int)t_intervals)
                                exit(0);
                                sf = 483.328 / (fabs((float)lastcount -
t_intervals));
                                printf("\n\nEstimate 8 frame slips every
%f seconds.\n\n", sf);
                                exit(0);
                        }
                }
        }
}
---snip---

> I've made some modifications to zttest in order to use
> it as a frame clock accuracy tester / slip detector.
> I'm not certain if that was it's original purpose, but it
> seems that a lot of folks try to use it that way.
> The result is something that I'm calling ztclock for now
> to help avoid confusion.
> <snip>
> Background:
> During routine codec/dimensioning testing, I observed a strange,
> recurring cpu spike occuring appoximately every 12 seconds on a
> completely idle system with only the zaptel drivers loaded. I used
> 'vmstat 1' to monitor this. I was using the wcfxo driver (wildcard
> fxo) as a timing source. 
So, chicken & egg: which comes first... the cpu spiking causing
missed data, or, missed data causing cpu spiking, or, none of the
above?

Compiled and ran on a cvs-head box with a TDM04b (4 fxo's) Rev H card,
fedora 3, 3ghz celery:

[root@phoenix zaptel]# ./ztclock
ztclock - clock source accuracy test (3 passes)
Flushing input buffer...
Flush Complete.
Test is approximately 3 minutes. Please wait...
483328 samples in 60.413670 sec. (483310 sample intervals) 99.996277%  
483328 samples in 60.413665 sec. (483310 sample intervals) 99.996277%  
483328 samples in 60.413670 sec. (483310 sample intervals) 99.996277%  
Estimate 8 frame slips every 26.851555 seconds.

I see the above appears to be slightly better then the numbers posted
in your example. Running spandsp fails on the above system with
nothing else running on this system (no calls, no nothing).

Can we draw any conclusions or limit assumptions given the output?

Rich