Erratic performance of IO operations in Qt4 program

[jcox23]

Hi,

Somewhere in a qt4 program, I launch a thread, that will do some IO operations in a file...
I'm trying to time this operation...

QTime t;
t.start();
 
 SegDIO_getRMS(mFilename.data(), mSegdAttributes->averaged, mSegdAttributes);
 
 qDebug("Time to extract datasquare: %d ms", t.elapsed());

QTime t;
t.start();

 SegDIO_getRMS(mFilename.data(), mSegdAttributes->averaged, mSegdAttributes);

 qDebug("Time to extract datasquare: %d ms", t.elapsed());

To copy to clipboard, switch view to plain text mode 

all three parameters of the function SegDIO_getRMS are pointers... (to char*, float* and pointer to a custom struct....)

Now there is a timer also in the called function, wrapping all operations...

At the beginning, the 2 timers are in agreement... everything's as fast as it should...but after some time,
the outside time is reporting times that are 5 times bigger than the inside timer...

Unless I'n not understanding something properly , the only operations made between these 2 timers are
locating the position in memory of the function and copy 3 pointers to it... that is reported during almost a full second...
which makes no sense...

I'm out of ideas of how to diagnostic the problem...

Does somebody has an idea of what's going on?

EDIT: additional info:
monitoring the I/O with iostat confirms that something goes to hell when timing become inconsistent :

Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
sda              26.50       232.00        16.00        464         32
sr0               0.00         0.00         0.00          0          0
 
Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
sda              14.50       120.00        16.00        240         32
sr0               0.00         0.00         0.00          0          0
 
Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
sda            1578.50     30748.00         0.00      61496          0
sr0               0.00         0.00         0.00          0          0
 
Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
sda            3230.50     63684.00        28.00     127368         56
sr0               0.00         0.00         0.00          0          0

Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
sda              26.50       232.00        16.00        464         32
sr0               0.00         0.00         0.00          0          0

Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
sda              14.50       120.00        16.00        240         32
sr0               0.00         0.00         0.00          0          0

Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
sda            1578.50     30748.00         0.00      61496          0
sr0               0.00         0.00         0.00          0          0

Device:            tps   Blk_read/s   Blk_wrtn/s   Blk_read   Blk_wrtn
sda            3230.50     63684.00        28.00     127368         56
sr0               0.00         0.00         0.00          0          0

To copy to clipboard, switch view to plain text mode 

[wysota]

The process is probably preemptied by the kernel somewhere inbetween reading the two timers so the second timer is delayed by the amount of time your process was sleeping. I wouldn't worry about it, especially that using QTime for benchmarking is unreliable anyway. Use QBENCHMARK instead and see if you get consistant results (note though that you can't nest calls to QBENCHMARK).

[jcox23]

The process is probably preemptied by the kernel somewhere inbetween reading the two timers so the second timer is delayed by the amount of time your process was sleeping. I wouldn't worry about it, especially that using QTime for benchmarking is unreliable anyway. Use QBENCHMARK instead and see if you get consistant results (note though that you can't nest calls to QBENCHMARK).

Thanks for pointing out QBENCHMARK...I didn't know QTime was not appropriate....

Also, I discovered that I may have benefited from a generous OS caching policy ... testing on the same series of files all the time and having 12Gb of RAM, I would assume the OS (ubuntu 8.04 64 bits here) would cache those files in memory...

After a computer restart, the timings I get are systematically the ones I thought were slow...