I love doing performance tuning... It's typically a mundane process of tiny tweaks and digging for gold in log files, but for some reason I find it a blast. I usually do it for every client, and sometimes I have projects dedicated exclusively to tuning.
One cropped up recently, where a client was having craaaaazy slow performance with an 11g custom component that Shall Remain Nameless. It worked fine with small data sets, but on a page with 1000 items, the load time was 12 minutes. Thus begins our adventure! But first, some wise words from the grandfather of performance optimization:
"We should forget about small efficiencies, say about 97% of the time: premature optimization is the root of all evil" -- Donald Knuth
Yarp... The first thing to do is establish a benchmark. Run some kind of automated test to time performance, and then start your tweaking. Also, be sure to put it in a nice table, so you can visually see just how awful the starting point is!
It's kind of a dull process-of-elimination to disable components, restart, and run another benchmark... but you have to do that in order to narrow down the offending code. I initially thought the problem was in one component... I was wrong... So, as boring as it is, it must be done to eliminate red herrings.
Once I found the offending component, I turned on some low-level tracing parameters. You can do this from the System Audit Information administration page. I usually turn on Verbose tracing, as well as these sections: requestaudit, pagecreation. When I did a small manual test, what I got back shocked me a bit:
pagecreation/6 09.13 17:55:47.774 IdcServer-31333 page generation took 10766 ms; gets 58863 funcs 24362 incs 9256 eval 160 requestaudit/6 09.13 17:55:48.012 IdcServer-31333 FOO_SERVICE 14.5684232711792(secs)
Woah... even a simple page was taking 14 seconds, 10 of which was in rendering the IdocScript! I checked, and these pages were far too complex for words. On a page with a 1000-item list, the component that Shall Remain Nameless was spitting out 15 Megs of HTML! Danger! Danger!
Problem solved, right? Not so fast... even with that the site was still slow. Next I suspected something in the database: bad histogram, missing index, whatever. So I turned on another low-level flag: systemdatabase. Please note: enabling this will turn your log files into a frigging Russian novel, so don't leave it on for too long... I ran another test, and got something like this:
systemdatabase/6 09.14 15:13:36.548 IdcServer-18413 53 ms. SELECT FOO_QUERY [Executed. Returned row(s): true] systemdatabase/6 09.14 15:13:58.803 IdcServer-18413 Closing active result set systemdatabase/6 09.14 15:13:58.804 IdcServer-18413 Closing statement in closing internals
Well... I was wrong again! Can you see the issue here? The query only took 53 milliseconds to run, so the database is hunky dory! But, it takes a full 12 seconds for UCM to release the connection. That means, somewhere deep inside the component that Shall Remain Nameless, some Java code is taking 12 seconds to post-process the database results. In some scenarios, it took over 40 seconds just to post-process the results.
What the heck is it doing???????
Don't know, don't care! Instead of digging through the component's code and trying to optimize that 40 second delay, I did what any sane web developer should do when faced with a poor performing black box: make a data cache! After quite a bit of digging, I found the magic function that was so very important that it took 40 seconds to run. So instead of calling it directly, I wrapped it up in a secure data cache. That cut the 40,000 milliseconds down to 4. You sometimes see stale data on the page, but that's always the case with a web interface... so it's usually a good tradeoff.
So... after improving their performance by 5 orders of magnitude, I patted myself on the back, and flew home...
The final benchmark numbers looked amazing... and I think that's why I find performance tuning is so satisfying. It's so very lovely to see the difference between the initial and final performance... and it's even better if you need to use a logarithmic scale to see them! ;-)