Selective system profiling

Selective system profiling

[John Sigler]

Hello everyone,

Here's my situation:

I'm pushing data in chunks of 1316 bytes to a PCI device at 38 Mbit/s.
In other words, I write 1316 bytes to the device every 277 microseconds.

I've noticed that the latency of this operation varies immensely. Most 
of the time it completes in 50-80 microseconds, but there are occasions 
when it takes several milliseconds (I've even logged 23 ms).

The pseudo-code looks like this:

   deadline = now;

   while ( 1 )
   {
     deadline += 277 µs
     sleep_until(deadline)
     t0 = now;
     write 1316 bytes to PCI device
     t1 = now;
     if (t1-t0 > 100 µs) scream & panic
   }

Relevant (?) information about the setup:

I'm running a PREEMPT_RT kernel with high-resolution timers.
(Specifically 2.6.20.7-rt8)
http://rt.wiki.kernel.org/index.php/Main_Page
HZ=100
The process is in SCHED_RR with priority 75.
The only "process" (?) with higher priority is posix_cpu_timer.
write() is implemented as an ioctl in the driver.
You might think that write() blocks when the buffers on the PCI board 
are full, but I am 99.9% sure that the buffers are never full.


Here's my question:

When my process comes back from a write operation, and I find that I 
have been blocked for more than X ms, can I call a function from a 
system profiler (oprofile perhaps?) to know exactly where in the kernel 
the CPU has been for the last X ms, and how much time has been spent in 
each function, either sleeping or doing something?

Regards.

Re: Selective system profiling

[John Sigler]

John Sigler wrote:

> Hello everyone,
> 
> Here's my situation:
> 
> I'm pushing data in chunks of 1316 bytes to a PCI device at 38 Mbit/s.
> In other words, I write 1316 bytes to the device every 277 microseconds.
> 
> I've noticed that the latency of this operation varies immensely. Most 
> of the time it completes in 50-80 microseconds, but there are occasions 
> when it takes several milliseconds (I've even logged 23 ms).
> 
> The pseudo-code looks like this:
> 
>   deadline = now;
> 
>   while ( 1 )
>   {
>     deadline += 277 µs
>     sleep_until(deadline)
>     t0 = now;
>     write 1316 bytes to PCI device
>     t1 = now;
>     if (t1-t0 > 100 µs) scream & panic
>   }
> 
> Relevant (?) information about the setup:
> 
> I'm running a PREEMPT_RT kernel with high-resolution timers.
> (Specifically 2.6.20.7-rt8)
> http://rt.wiki.kernel.org/index.php/Main_Page
> HZ=100
> The process is in SCHED_RR with priority 75.
> The only "process" (?) with higher priority is posix_cpu_timer.
> write() is implemented as an ioctl in the driver.
> You might think that write() blocks when the buffers on the PCI board 
> are full, but I am 99.9% sure that the buffers are never full.
> 
> 
> Here's my question:
> 
> When my process comes back from a write operation, and I find that I 
> have been blocked for more than X ms, can I call a function from a 
> system profiler (oprofile perhaps?) to know exactly where in the kernel 
> the CPU has been for the last X ms, and how much time has been spent in 
> each function, either sleeping or doing something?

Perhaps I could take this matter to a different list?