iRule performs 100x slower under load

Aaron:

 

• Case C850935
• Thank you for the heads up on the timing reporting accuracy. I believe the timing reflected real issues in that you could see the delay when exercising the application. The slow performance of the app vanished when the problem iRule was reverted to an earlier version.
• Definitely looking forward to upgrading to version 10+ but it's a big company and things move slowly.
• Lastly, I will modify the rule to use AES encryption instead of HTTP::cookie encrypt and compare performance.

Thanks for all the great suggestions.

 

 

iRule logic may not be the issue:

 

After doing a bunch of load testing in DEV, I believe the problem must not be with the iRule itself but with something environmental in production.

 

 

Production traffic is at a scale of a 100 requests a minute - a trickle really. In dev I loaded up roughly 40,000 requests in 20 minutes (2,000/minute) and this is the performance I saw:

 

+-> CLIENTSSL_CLIENTCERT 2 total 0 fail 0 abort | | Cycles (min, avg, max) = (39284, 74243, 91724) +-> CLIENTSSL_HANDSHAKE 299 total 0 fail 0 abort | | Cycles (min, avg, max) = (6484, 30481, 174556) +-> CLIENT_ACCEPTED 296 total 0 fail 0 abort | | Cycles (min, avg, max) = (21288, 62419, 112668) +-> CLIENT_CLOSED 291 total 0 fail 0 abort | | Cycles (min, avg, max) = (3420, 24984, 58528) +-> HTTP_REQUEST 43262 total 0 fail 0 abort | | Cycles (min, avg, max) = (52624, 238869, 9670788) +-> HTTP_RESPONSE 43176 total 0 fail 0 abort | | Cycles (min, avg, max) = (18668, 1455857, 10122004) +-> RULE_INIT 1 total 0 fail 0 abort | Cycles (min, avg, max) = (182880, 182880, 182880)

An second test run containing a different mix of traffic - one that has heavier reliance on cookie encryption produced the following metrics:

 

+-> CLIENTSSL_CLIENTCERT 0 total 0 fail 0 abort | | Cycles (min, avg, max) = (0, 0, 0) +-> CLIENTSSL_HANDSHAKE 18 total 0 fail 0 abort | | Cycles (min, avg, max) = (21828, 51560, 227392) +-> CLIENT_ACCEPTED 17 total 0 fail 0 abort | | Cycles (min, avg, max) = (48332, 90744, 110596) +-> CLIENT_CLOSED 18 total 0 fail 0 abort | | Cycles (min, avg, max) = (19092, 48822, 52680) +-> HTTP_REQUEST 6878 total 0 fail 0 abort | | Cycles (min, avg, max) = (78288, 1062803, 9434612) +-> HTTP_RESPONSE 6877 total 0 fail 0 abort | | Cycles (min, avg, max) = (31408, 1975720, 9943836) +-> RULE_INIT 0 total 0 fail 0 abort | Cycles (min, avg, max) = (0, 0, 0)Obviously nothing close to the 100 million cycles/request measured in production.

 

Output from 'b memory' showed no memory usage growth at all over the test:

 

| ssl 7.116M 7.212M 0 | tcl 1.201M 1.647M 0

 

 

The back-end java app server was i/o bound to the DB but still had an 15 minute average load (uptime-top-/proc/loadavg) of 1.67 on a 2 processor machine.

 

 

JMeter reported an average HTTP request/response time of 22 seconds. That is hellishly slow but must be from the app server as the iRule timing metrics are still snappy.

 

JMeter Samples 3361, Average 22073ms, Median 21883ms, 90% line 30147ms and Max of 55250ms

 

Session Table: we are writing a value into the session table and doing it a little oddly:

 

session add ssl "s[SSL::sessionid]" $ccSubject $::timeout

 

 

Note the prepended 's' to the sessionid. This is vestigial - an earlier iteration of the rule attempted to save 4 different values for each SSL session by prepending a different letter to the ssl sessionid. I did this with Brice Spreitzer's (F5 iRule consultant) collaboration. Currently, the script saves only a single value. I still don't have a solid understanding of the scope of these entries.

 

 

Thanks for your time - you don't know how much I appreciate it,

 

-- Chris