title: Measuring execution time of a function inside linux kernel
body: <p>I am using Linux Security Module hooks to add some custom functionality to recv() system call. I want to measure the overhead of this functionality as compared to the pristine recv(). I have written a simple tcp server that I run with and without my module. This tcp server calls a recv() function 'N' number of times. It measures time taken for each recv with something like:</p>
  
  <pre><code>clock_gettime(before);
  recv()
  clock_gettime(after);
  global_time += after - before.
  </code></pre>
  
  <p>In the end, I print the average time for a single recv() with "global_time/N". Lets call this time as "user_space_avg_recv" time.</p>
  
  <p>Inside my module, I want to place time measurement functions to calculate exact execution time of my hook. I tried 3 methods.</p>
  
  <ol>
  <li><p>I used jiffies as follows:</p>
  
  <pre><code>sj = jiffies;
  my_hook();
  ej = jiffies;
  current-&gt;total_oh = ej - sj;
  </code></pre>
  
  <p>But I see that there is no difference between sj and ej values. Hence total_oh is unchanged.</p></li>
  <li><p>I used current_kernel_time() since I thought it returns the time in nanoseconds. However, once again, there was no difference in before and after time.</p></li>
  <li><p>I used get_cycles. I print the total cycles when the process exits. However, when I convert that total cycles values to milliseconds, it comes out be much greater than 
  "user_space_avg_recv" value. This does not make sense as measured value inside kernel  always be lesser than the time value measured from user space. This could mean that I am either not measuring using correct API or I am making a mistake while converting value from cycles to milliseconds.</p></li>
  </ol>
  
  <p>I am basically using following formula to convert cycles to milliseconds:</p>
  
  <pre><code>avg overhead of my hook in milliseconds = 
               (((cycles / 2.99) / 10^6) / N)
  </code></pre>
  
  <p>2.99 because my clock frequency is 2.99Ghz</p>
  
  <p>Some points:</p>
  
  <ul>
  <li><p>My user space program is tied to a single core using set affinity.</p></li>
  <li><p>I am using kernel 2.6.22.14</p></li>
  <li><p>To stop kernel from switching contexts while inside my hook, I use preempt_disable() and preempt_enable(). Thus it will not count the execution times of other kernel threads. Even then, since my hook use some I/O, my thread might release the control voluntarily or some interrupt might occur that might increase the total cycles count.</p></li>
  </ul>
  
  <p>Question:
  How can I measure function execution times accurately inside the kernel?</p>