-----Original Message----- From: kernelnewbies-bounces@kernelnewbies.org [mailto:kernelnewbies- bounces@kernelnewbies.org] On Behalf Of Peter Senna Tschudin Sent: Friday, February 10, 2012 1:48 PM To: kernelnewbies@kernelnewbies.org Subject: Re: How to measure performance inside Kernel?

Dear list,

As Michi suggested, I did some testing with ktime.h, but I found a simpler solution with time.h.

I'm not sure if it is correct, and I would like to have some help... :-)

The code that I'm using for execution time measurement is:

#include <linux/time.h>

getnstimeofday (ts_start); /*stopwatch start*/

for (i = 0; i < q->num_buffers; ++i) q->bufs[i]->state = VB2_BUF_STATE_DEQUEUED;

getnstimeofday (ts_end); /*stopwatch stop*/

diff = timespec_sub(end, begin);

printk ("%lu,", diff.tv_nsec );

Am I doing anything wrong? Can mysterious stuff like out of order execution engine, brake the stopwatch?

The full module code is at: http://goo.gl/cCMIa

Thank you!

Peter

If you didn't disable interrupts before executing the above, the timing of the above loop would include any time spent servicing interrupts. Likewise if there were context switches or soft IRQs running. All would inflate the perceived time to execute your loop. Jeff Haran

Hi Peter, On 02/11/2012 11:22 AM, Peter Senna Tschudin wrote:

Jeff,

Thanks for the fast reply. My goal is to determine if the code:

/* * */ buf_ptr_end = q->bufs[q->num_buffers];

for (buf_ptr = q->bufs[0]; buf_ptr < buf_ptr_end; ++buf_ptr) buf_ptr->state = VB2_BUF_STATE_DEQUEUED; /* * */

is faster than:

/* * */ for (i = 0; i < q->num_buffers; ++i) q->bufs[i]->state = VB2_BUF_STATE_DEQUEUED; /* * */

For starters, I would not be surprised if the compiler produces identical code, and if not, code that has the same performance...

I'm measuring the running time of that portion of code 512 times. Then calculate the geometrical mean of results. See one output example:

Original_code:,

514,110,92,104,107,101,101,99,105,99,87,105,99,105,105,102,108,123,105,113,104,128,107,92,117,117,120,102,105,105,90,105,101,119,119,101,141,111,96,99,93,80,102,78,93,93,108,108,129,105,107,113,104,104,93,95,104,125,104,95,90,108,117,126,93,87,102,99,93,108,96,104,113,89,92,134,107,98,95,104,102,143,102,126,99,111,99,117,105,102,108,108,98,107,104,98,96,81,108,120,102,87,93,93,93,119,104,96,108,93,108,108,111,98,98,116,122,98,101,87,99,99,105,102,108,111,99,96,111,111,102,98,110,125,107,110,132,102,99,105,87,84,108,120,90,101,95,113,101,107,111,105,108,114,126,102,92,110,104,101,99,108,135,105,123,111,108,102,102,110,110,92,98,104,119,102,113,95,107,104,116,131,153,164,152,125,107,101,93,105,96,123,96,111,111,99,93,101,92,107,89,95,108,111,99,111,114,108,99,117,129,107,105,87,87,93,102,99,83,96,84,102,96,90,110,101,116,89,98,119,125,114,99,126,123,102,123,111,102,101,110,107,111,90,105,111,96,105,102,113,104,158,101,87,102,96,108,111,138,102,120,87,90,102,104,107,101,84,102,99,96,111, 99,105,102,99,104,131,116,104,104,105,126,105,116,128,107,101,105,120,132,111,90,90,114,99,86,110,95,81,120,96,126,99,108,114,120,102,120,125,95,104,96,108,105,105,114,123,111,93,104,83,113,107,99,99,99,105,90,78,119,113,98,98,90,99,90,129,96,101,110,77,110,125,101,102,87,87,117,126,117,108,126,108,96,108,99,105,105,114,123,104,104,110,105,84,96,105,96,120,111,120,101,110,110,87,105,114,102,87,108,135,117,132,141,105,113,95,98,84,96,87,98,89,108,105,102,99,99,105,126,99,101,92,98,75,102,102,129,102,99,102,99,108,92,110,125,107,110,102,96,96,117,72,108,123,105,120,120,99,120,98,104,89,102,117,129,123,105,119,107,101,87,117,111,99,108,117,114,114,90,122,113,95,104,125,113,102,108,120,90,108,93,89,86,87,90,84,83,108,99,102,90,108,90,108,87,95,86,90,123,135,93,126,93,102,99,123,108,117,105,102,105,98,107,122,119,125,96,108,131,99,114,104,93,96,95,83,99,84,92,87,

The geometrical mean of the values is: 104.7623578604

Isn't it enough?

That sounds like a perfectly good methodology - It would be interesting to see how many reps are required before the mean settles down to a constant value - Maybe you don't need to run it so many times, or maybe you need to run more... Regards, Graeme

Graeme, I found a problem on my code. I was calling kmalloc() only once for both portions of code. The result is that the first loop that accessed the memory was finding some penalty. Now I'm calling independent kmalloc for each test. The latest results are: Proposed_code: 13.3940560108 Original_code: 37.8944950594 The graph is at: http://i.imgur.com/nPjTE.jpg Source: http://goo.gl/cCMIa Peter -- Peter Senna Tschudin peter.senna@gmail.com gpg id: 48274C36

Hi Mulyadi,

I read your code and I think kmalloc can be streamlined here. I recommend that kmalloc() allocate total memory needed to handle whole q->buf[] array. something like (CMIIW):

q->buf=kmalloc(sizeof(struct vb_buffer)*q->num_buffers,GFP_KERNEL)

then access q->buf[1], q->buf[2] etc.

struct vb2_queue { struct vb2_buffer *bufs[VIDEO_MAX_FRAME]; unsigned int num_buffers; }; bufs is an array of pointers to struct vb2_buffer. I was not able to use your kmalloc code. I get incompatible types errors when trying it. Any ideas? -- Peter Senna Tschudin peter.senna@gmail.com gpg id: 48274C36

Hi! On 22:22 Fri 10 Feb , Peter Senna Tschudin wrote: ...

I'm measuring the running time of that portion of code 512 times. Then calculate the geometrical mean of results. See one output example:

Original_code:, 514,110,92,104,107,101,101, ... The geometrical mean of the values is: 104.7623578604

Isn't it enough?

It should reduce the influence of the scheduler, but you can see a different effect here: The first run takes ~5 times longer than any run which follows. This is most likely caused by CPU cache effects. The question is now whether you can expect the data to be in the cpu cache when this code is run in the real world. If not, you might want to add prefetch instructions (look for "__builtin_prefetch"). These instructions will make the first run faster, but further runs slower. -Michi -- programing a layer 3+4 network protocol for mesh networks see http://michaelblizek.twilightparadox.com

Hi Michi,

Why don't you print the tv_sec part?

It is expected that tv_sec is always zero. But I'll fix the code to check if it really is.

You might also want to replace getnstimeofday with getrawmonotonic or any other monotonic time source. If ntp or something else decides to change system time during the measurement, you would probably get weird results.

I got the getnstimeofday() from line 333 of <linux/ktime.h> /* Get the real (wall-) time in timespec format: */ #define ktime_get_real_ts(ts) getnstimeofday(ts) If the clock changes in the worst time possible, it may affect only one result. But I'll check other functions. Thanks! Peter -- Peter Senna Tschudin peter.senna@gmail.com gpg id: 48274C36