Forum Discussion
Craig_Hammer_10
Nimbostratus
NimbostratusTiming iRules
I have inserted "timing on" into a couple of scripts, and collected stats (on test sites) for a few days. The timing statistic is expressed in "Cycles." I have not found a description of what "Cycles" is measuring. I thought perhaps it was CPU clock cycles, but that is not making sense.
For instance, I ran a brief test this morning of a script that does one "if" and one "else". Should be very lightweight. This is the listing from "bigpipe rule blah show all":
RULE loadtest
+-> HTTP_REQUEST 729 total 0 fail 0 abort
| Cycles (min, avg, max) = (3693, 3959, 53936)
How can I communicate this statistic in a meaningful way to management and support staff ?
Thanks,
- Yes, these cycles are cpu cycles as measured by the TSC (time stamp counter) on the cpu. Before evaluating the rule we read the TSC and then read it again at completion of the rule and add the delta to the average.
To convert the number into something more meaningful, you will need to know the clock rate of your cpu. You can generally find this out by doing a 'cat /proc/cpuinfo'.
So, in an example, if you are running on a 5100 which uses a 1.266 GHZ cpu, you could measure the latency the rule incurs by dividing 3959 by 1266000000 which yields .000003127 sec or 3.127 usec.
Perhaps a more useful way to look at it is in cpu percentage. If you can estimate the number of times this rule runs per second (you should be able to deduce this number from the number of connections per second on that virtual), then you could calculate the amount of cpu percentage spent on the rule with the following formula: avg cycles * number of rule evaluations per sec / cpu clock rate. So, in your example, let's say you were running ~ 100 rule evaluations per second, then your rule would be using: 3959 * 100 / 1266000000 = .03127 % of the cpu per sec.
I realize this probably still isn't the most useful statistic to give to management, other than to demonstrate that rules for the most part are not really impacting your performance much. The rationale behind providing this number was more for an optimization purpose so you could attempt to improve your rule and then measure the improvement or degradation. For example, time the difference between using "contains" vs. "matches_regex" and you'll see quite a difference in the numbers.
Hope this has been helpful. - Oh, I should add that the number for "max" is often grossly out of proportion. This is because at least once per tick, the operating system takes control and makes sure the right process is running (this is called scheduling). Because we simply read the TSC and then measure the difference, we can't account for this operating system overhead that occasionally happens in the middle of a rule evaluation. So, unfortunately, this max number is actually quite useless (originally, I had hoped it would show the longest path through the rule). Eventually, we are planning on adding more detailed statistics to further help diagnose and improve rule performance.
Craig_Hammer_10Excellent info!
In my case, 2.4 microseconds of latency for my "slowest" iRule, which is obviously not a bottleneck. We're running the 6400 model, which has the 1.6 (1594.290) proc, and uses hyper-whatever. .0245% of a single proc is very little usage.
Al_Carandang_11If we divide 1266000000 CPU cycles per second by 3959, we would get about 320000. Would it be safe to say that this is the theoretical maximum number of times we could execute this code per second? Of course there would be other factors which would lower this value. I'm also assuming the second CPU on my box would handle all the other tasks the box would need to do.
-Al
uniAltostratus
Posted By unRuleY on 8/02/2005 11:27 AM
Oh, I should add that the number for "max" is often grossly out of proportion. This is because at least once per tick, the operating system takes control and makes sure the right process is running (this is called scheduling).
The simple solution to this is to wait until the first time the rule is hit, then issue the commandbigpipe rule [ | all] stats reset
Ed_Hammond_2611I've been look this over in more detail again. I have a script that does the "stats reset" once, then issues the "show all" at regular intervals. Looking at the results does not make much sense... The values continue to grow, including the "min" value. How can the "min" value grow over time? Are these all cumulative values? If so, what does "min" mean?
Also, is there a way to defeat the "rounding" when the values are in the millions?
This is from a preatty heavyweight iRule that I'm trying to tune.
+-> HTTP_REQUEST 12650 total 0 fail 0 abort
| | Cycles (min, avg, max) = (14.52M, 15.62M, 18.33M)
+-> HTTP_RESPONSE 11392 total 0 fail 0 abort
| | Cycles (min, avg, max) = (2.805M, 3.166M, 4.807M)