Misusing Execution Time Profiles

One of my favourite sayings is "when the only tool you have is a hammer, all your problems look like nails".

We've been analyzing the response time of our website by tracking the ping response times, and I saw an opportunity to use one of RapiTime's reports to visualise this data.

An ETP (Execution Time Profile) reports the distribution of execution times measured for a piece of code in a RapiTime. This also happens to provide a great way of looking at lots of ping response times. I should note at this point, this is a misuse of the report - it's intended to show execution times of pieces of code, rather than how long it takes a web server to respond to a ping!

To persuade RapiTime to display the website response times, I needed to create a source file that would correspond to the log of ping response times. Note that this code was only written so that RapiTime could generate a report from it - it was never intended to be executed.

#pragma RVS default_instrument("TRUE","TIME_FULL");
void uptime(void) {
   int i = 0;
   while (!i) {
       i = ping();
   }
}

I then ran the code through our instrumenter, which gave us this code with added Ipoints:

void uptime(void) {RVS_I(65535);{
   int i = 0;
   {RVS_I(10);while (!i) {RVS_I(11);{
       i = ping();
   }}}
}RVS_I(65534);}

This tells me that the trace data that RVS is expecting to see has the following pattern:

65535     time1
10     time2
11     time3
11     time4
...
65534     timeN

So it was a straightforward step to transform the text file containing the list of ping response times into a trace, and to analyze this.

Once analyzed, I was able to view the ETP for Ipoint 11: This can also be viewed as a cumulative distribution: So what's the point of doing this? It was mainly a bit of fun. Although, from the point of view of our website work, we can use these measurements as a baseline to compare future website optimizations against.

It is also a useful illustration of how the RapiTime measurement is working.