[SOLVED] QAudioInput returns more data than expected

[maxsivkov]

Hello!

Having some problems with QAudioInput:
I'm trying to record sound using QAudioInput (settings are 8000 Hz/16bit/1channel
everything works fine except one thing: QAudiInput returns more bytes than expected:
by "expected" I mean that I should read about 16Kbytes/sec or 16 bytes in one millisecond interval.
Look at the following output (one line is generated each 10 seconds and shows how much bytes read from QAudioInput

        @<bytes received>     <time elapsed>
                  vvvvvv     vvvvvv

Total Received 166400 in 10141
Total Received 164480 in 10140
Total Received 163200 in 10142
Total Received 164480 in 10136
Total Received 163840 in 10151
Total Received 163200 in 10129
Total Received 163840 in 10143
Total Received 163840 in 10137
Total Received 163840 in 10152
Total Received 163840 in 10141
@
If we take in account timer inaccuracy (times between each line are measured with QTime::elapsed() call, running under Win7 X86 OS)
which is +-16mills, we got min and max value for elapsed column (min:10113 and max:10168) what gives us min and max values in bytes: (min:161808 max:162688).
so, if I am right, there shouldn't be any value in <bytes received> column that larger than 162688 bytes, but as you may see all of them are larger! 163840-162688=1152 bytes more than expected and gives about 72 mills more.
so in a minute it will give about 0.5 seconds more data than expected!
Am I missed something???

[JKSH]

Interesting! Could you share your code for measuring your bytes received and time elapsed?

I have a feeling that processing delay is affecting your measurements. After all, your results show a ~140ms delay in "time elapsed" (Ideally, they should all be 10000). Is your program (or OS) doing anything else during your measurements? What's the delay between emitting a signal and calling its slot? What's the delay between measuring "time elapsed" and measuring "bytes received"? What are your hardware specs?

Another experiment you could try is to pass 10000 into QAudioInput::setNotifyInterval(), and then connect QAudioInput::notify() to a slot that calls QTime::elapsed(), to see how much real time it takes for QAudioInput to produce 10s worth of data. If you're right, then "time elapsed" will be less than 10000 always.

[maxsivkov]

JKSH, thanks for reply!

[quote author="JKSH" date="1343403995"]Interesting! Could you share your code for measuring your bytes received and time elapsed?
[/quote]

I am using my own implementation of QIODevice, this class just implements circular buffer and could be used for both QAudioInput and QAudioOutput, so my QAudioInput works in "pull" mode.
As I mentioned, by OS is Windows7 x86, CPU Intel(R) Core(TM)2 Quad CPU Q6600 at 2.40GHz, 4Gb RAM
I understand that the system could do something in the middle but it shouldn't affect on a <bytes received> column grow for two subqequent lines.

Anyway, here is my code to measure time:

@qint64 MemoryDevice::writeData(const char *data, qint64 len)
{
QMutexLocker l(&lock);

static struct _time_t
{
    int total_received;
    QTime time;
    _time_t() : total_received(0) { time.start(); }
} timer;
timer.total_received+=len;
int elapsed = timer.time.elapsed();
if (elapsed > 10000)
{
    qDebug() << ">>>>> Total Received  " << timer.total_received << " in " << elapsed;
    timer.total_received = 0;
    timer.time.restart();
}

qint64 result = len;
while (len) { holder.append(*data++); len--;}
return result;

}@
the above is writeData() virtual function reimplemented in my own class.
"holder" implements circular buffer, but it doesn't matter in this case.

PS:
I'm facing this problem because my app should transfer audio data over network and remote side should be able to play this stream.
after getting all things done I put sender and receiver to work for about half an hour, and guess what, the delay between recorded sound on a sender and played on a receiver was about 10 seconds!

[maxsivkov]

I disabled all timers and threads in my application, and did another test with aggregation results.

Now the writeData function looks like:
@qint64 MemoryDevice::writeData(const char *data, qint64 len)
{
QMutexLocker l(&lock);

static struct _time_t
{
    int total_received_interval, total_received, time_passed;
    QTime time;
    _time_t() : total_received_interval(0), total_received(0), time_passed(0) { time.start(); }
} timer;

int elapsed = timer.time.elapsed();
timer.total_received_interval+=len;
if (elapsed > 10000)
{
    timer.total_received+=timer.total_received_interval;
    timer.time_passed+=elapsed;

    qDebug() << "!!!!! MemoryDevice::WriteStream Total Received/interval  " << timer.total_received_interval<< " in " << elapsed
                << "total bytes "<< timer.total_received << " in " << timer.time_passed
                   << "diff " << timer.total_received - (timer.time_passed*16);
    timer.total_received_interval = 0;
    timer.time.restart();
}

qint64 result = len;
return result;

}@

the output is the following:
@
Received/interval 160640 in 10001 total bytes 160640 in 10001 diff 624
Received/interval 161280 in 10005 total bytes 321920 in 20006 diff 1824
Received/interval 160640 in 10021 total bytes 482560 in 30027 diff 2128
Received/interval 160640 in 10036 total bytes 643200 in 40063 diff 2192
Received/interval 160640 in 10004 total bytes 803840 in 50067 diff 2768
Received/interval 160640 in 10029 total bytes 964480 in 60096 diff 2944
Received/interval 160000 in 10006 total bytes 1124480 in 70102 diff 2848
Received/interval 160640 in 10035 total bytes 1285120 in 80137 diff 2928
Received/interval 160640 in 10030 total bytes 1445760 in 90167 diff 3088
Received/interval 160640 in 10041 total bytes 1606400 in 100208 diff 3072
Received/interval 160640 in 10031 total bytes 1767040 in 110239 diff 3216
Received/interval 160640 in 10022 total bytes 1927680 in 120261 diff 3504
Received/interval 160640 in 10039 total bytes 2088320 in 130300 diff 3520
Received/interval 161280 in 10036 total bytes 2249600 in 140336 diff 4224
Received/interval 161280 in 10033 total bytes 2410880 in 150369 diff 4976
Received/interval 160640 in 10029 total bytes 2571520 in 160398 diff 5152
Received/interval 160000 in 10005 total bytes 2731520 in 170403 diff 5072
Received/interval 160640 in 10037 total bytes 2892160 in 180440 diff 5120
Received/interval 160640 in 10034 total bytes 3052800 in 190474 diff 5216
Received/interval 160640 in 10041 total bytes 3213440 in 200515 diff 5200
Received/interval 160640 in 10032 total bytes 3374080 in 210547 diff 5328
Received/interval 160640 in 10023 total bytes 3534720 in 220570 diff 5600
Received/interval 160000 in 10006 total bytes 3694720 in 230576 diff 5504
Received/interval 160640 in 10028 total bytes 3855360 in 240604 diff 5696
Received/interval 160640 in 10014 total bytes 4016000 in 250618 diff 6112
Received/interval 160640 in 10032 total bytes 4176640 in 260650 diff 6240
Received/interval 160640 in 10027 total bytes 4337280 in 270677 diff 6448
Received/interval 160640 in 10014 total bytes 4497920 in 280691 diff 6864
Received/interval 160640 in 10039 total bytes 4658560 in 290730 diff 6880
Received/interval 160640 in 10035 total bytes 4819200 in 300765 diff 6960
Received/interval 160640 in 10035 total bytes 4979840 in 310800 diff 7040
Received/interval 160000 in 10007 total bytes 5139840 in 320807 diff 6928
Received/interval 160640 in 10034 total bytes 5300480 in 330841 diff 7024
Received/interval 160640 in 10009 total bytes 5461120 in 340850 diff 7520
@

I removed "!!!!! MemoryDevice::WriteStream " from each line for better reading.
So, there are 34 lines, gives us 340 seconds = ~5,6 mins, and the difference is 7520/16=470 milliseconds!

[JKSH]

Mutex locking/unlocking is very slow... which could explain why your app lags over time, and could mean that your elapsed() measurements are out of sync with the data arrival times. Also, keep in mind that because QTime::elapsed() is inaccurate, the error in "timer.time_passed" grows every time you evaluate "timer.time_passed+=elapsed".

What happens if you get rid of the QMutexLock?

Anyway, here is my own bare-bones test device:

@class TimingDevice : public QIODevice
{
Q_OBJECT

qint64 total_received;
QElapsedTimer timer;

qint64 readData(char *data, qint64 maxlen) {return 0;}
qint64 writeData(const char *data, qint64 len)
{
    if (timer.isValid()) {

        qint64 elapsed = timer.elapsed();
        total_received += len;

        if (elapsed >= 10000) {
            qDebug() << total_received << "bytes in" << elapsed << "msecs";
            total_received = 0;
            timer.restart();
        }
    } else {
        timer.start();
    }
    return len;
}

public:
TimingDevice(QObject *parent = 0) : QIODevice(parent)
{
total_received = 0;
timer.invalidate();
}
};@

I'm running Windows7 ×86, CPU Intel® Core™2 Quad CPU Q6600 at 2.40GHz, 4Gb RAM and got:
@160000 bytes in 10000 msecs
160640 bytes in 10038 msecs
160640 bytes in 10039 msecs
160000 bytes in 10000 msecs
160640 bytes in 10039 msecs
160000 bytes in 10000 msecs
160640 bytes in 10039 msecs
160000 bytes in 10000 msecs
160640 bytes in 10039 msecs
160640 bytes in 10039 msecs
160000 bytes in 10000 msecs
160640 bytes in 10039 msecs
160000 bytes in 10000 msecs
160640 bytes in 10039 msecs
160000 bytes in 10000 msecs
@

So the device gets either 160640 bytes in 10040 msecs, or 160000 bytes in 10000 msecs, as expected.

[maxsivkov]

JKSH,

After disabling timers, threads, and using more accurate win32 "GetSystemTimeAsFileTime":http://msdn.microsoft.com/en-us/library/windows/desktop/ms724397(v=vs.85).aspx call that could return values up to 100 nanosec resolution (actually not less than 1 millisec) I got almost the same result as you did.

So the thread might be closed.
Thank you for your time and support!

[JKSH]

You're welcome, maxsivkov :) Good luck with your project!