WebCenter/UCM Performance Tuning, Black Box Style!

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!

The fix? I used some of my tips from my web site performance tuning presentation, of course. I made a new custom interface, and leveraged the YUI Library that's built-in to UCM... specifically the DataTable widget. By bye IdocScript, hello JavaScript! That slimmed down the page from 15,000 KB to a manageable 300 KB, and all but eliminated the page generation time.

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! ;-)


secure data cache means

What is the actual code you have implemented for secure data cache ?
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

please tell me the details of secure datacache .

several ways...

There are hundreds of ways to do a secure data cache. What I did was execute the code with "superuser" credentials, and then stored the result. Then, when a specific user executed that code, I'd get the data from the cache, and filter it based on whether or not they had "read" access to the item.

Depending on the use case, there might be faster ways to do the cache... but in this case it was sufficient.

Really interesting post.

Great post Bex, really interesting stuff.
Did you consider using Coherence, it's part of the WebLogic infrastructure and offers pretty straight forward (distributed) data cache?

How to find the logs you are looking at?

Hi Bex,

I'm quite new to WebCenter suite and we are experiencing very poor performance once inside our webcenter spaces. I'm trying to run the logging as you have above, but I'm not sure how to get to the logs you are viewing after setting up the verbose logging with requestaudit, pagecreation enabled?

Did you do this within UCM? This is where I found the page to enable these parameters - is this page also somewhere in EM or Console?

That is all for now!

Best Regards,

Recent comments