DFC Session Acquisition Delays

jasonduke

Hello Documentum/DFC experts!

I am troubleshooting some performance problems in a Documentum 5.3 SP4 application, and I’m looking for ideas and recommendations about what could be going on, and what logs, tracing, or other lines of inquiry would be most useful.

The basic architecture:
- two content servers, one repository
- four Weblogic nodes
- thousands of concurrent users making perhaps dozens or hundreds of repository requests at any one time

Our logging output shows that the application is suffering inordinate delays trying to acquire a DFC session, which is having a severe impact on usability across the application. The problem occurs in all four web application instances. (I am working today to determine whether it is also present in command-line applications which utilize the same code, or if it is only happening within Weblogic.)

2009-06-18 18:34:57,249 Constructing session manager for user **** and storing on threadlocal for use by the current thread.
2009-06-18 18:34:57,249 Attempting to initialize DFC session manager for user **** on repository YYY
2009-06-18 18:34:57,249 Successfully initialized DFC session manager for user **** on repository YYY
2009-06-18 18:34:57,249 Setting a new thread-local session manager...
2009-06-18 18:35:20,437 Acquired session s2
2009-06-18 18:35:20,905 0.47 DFC getObjectByQualification dm_webc_config where object_name = '...'
2009-06-18 18:35:20,921 0.02 DFC select a_last_completion, a_current_status from dm_job where any method_arguments like '%0801bc828000b133%' order by a_last_completion DESC
2009-06-18 18:35:20,921 Cleaning up session s2
2009-06-18 18:35:20,921 Clearing current thread-local session manager...

This example took 23 seconds to acquire a session. I’ve seen cases in the logs taking more than 60 seconds. Notice that once the session is acquired the queries execute relatively quickly (sub-second).

Why should it ever take 23 seconds to acquire a session?

Full Disclosure: I am not certain yet whether the delay is truly within the getSession call, or if it’s really context-switching or otherwise application/Weblogic related... I’ll be working today to add additional logging to the code to get at some of this deeper information.

The session manager it is using has typically been recently created (within seconds), though in some cases it may have been pulled from a pool of longer-lived session managers, but never anything more than a few minutes old.

My first thought was that we were hitting some connection/session pool threshold, so I dug into server and client settings…

concurrent_sessions
In Production, the concurrent_sessions property of server.ini on both content servers is currently set to 100, which suggests this could just be too many sessions coming from the application into Documentum. But the Sessions listing in DA never shows more than about 60-70 sessions. This could mean we aren’t hitting the 100 or it could mean DA is not showing all the sessions, or maybe Documentum begins throttling before it gets to the max… Need to study up on this one.

Tonight we’ll be bumping that value up to 1000. I have hopes, but given what I’m seeing in DA I’m not so confident this is going to help.

max_session_count
In Production, the max_session_count property of dmcl.ini/dfc.properties for all the web application servers is set to 1000, which is part of our installation because we found 10 and 100 were too few in our performance tests during launch.

As I said, I’m working today to add more logging code so I can get a more granular view of what’s happening. I won’t get to see the results of those changes until Tuesday at the earliest.

Also, it’s unlikely I’m going to have an opportunity to do any serious profiling in Production, although I’m not ruling it out if it looks like our best chance of figuring things out soon.

Could the multiple content servers be adding some overhead to session creation? Seems like a session manager would always be bound to a specific content server, but I really don’t know much about this.

I’m looking for ideas and recommendations about what could be going on here, and what logs, tracing, or other lines of inquiry would be most useful. I’m not very well-versed in content server tuning and tracing and logs, so any pointers would be appreciated!!

Thanks!

-Jason

__________________
Jason Duke
Senior Consultant
Blue Fish Development Group

jasonduke

Someone pinged me a few days ago to ask if I ever got to bottom of this issue. I'm happy to say that we did resolve it, although it took several weeks of intensive back and forth between myself, the client, and EMC support. I thought I had posted an update here, but apparently not, so here's an attempt to correct that oversight.

The root cause turned out to be a compiler bug which caused the Content Server to hang during certain directory creation activity.

I've provided a summary below for anyone who is interested. I have no idea whether this will prove applicable to anyone else's troubles, but considering the many hours we spent tracking it down, this should save you some time if you're up against a similar issue.

This issue taught me a lot about how to troubleshoot Documentum performance issues, but more importantly it taught me when to hand things over to the developers and support engineers at EMC.

Anyway, on with the summary...

The Problem Surfaces

The problem started with minor complaints of system-wide delays and general “slowness” throughout the application's user community. Eventually there were more and more complaints of major delays when performance Documentum-related activities such as document submission, workflow tasks, and more.

Initial Troubleshooting

Initial troubleshooting focused on our custom application logs, which utilize a powerful trace and performance logging framework, including timings of many different activities. Logging showed plainly that DFC session acquisition was almost universally to blame for the delays, with a few problem database queries also standing out.

Low-Hanging Fruit

The problem SQL and DQL queries were quickly addressed by tuning the queries and/or adding database indexes, but the DFC session acquisition was not so simple.

Zeroing in on Session Acquisition

Interestingly, DFC session acquisition delays were inconsistent and intermittent, and were almost always followed by sub-second response times for the subsequent DFC activity. In other words, the DFC activity was fast, but the session acquisition was somehow being delayed intermittently.

Isolating the Delay to DFC/DMCL Code

Additional performance and trace logging was added to the code to further isolate the delay to the specific DFC session acquisition calls. DFC and DMCL trace logging were enabled on the web applications to provide additional data. These logs were all reviewed and correlated to show clearly that the DFC session acquisition calls were being delayed during authentication. This information was handed off to EMC support engineers, who worked with the client's IT team to generate additional trace logs on the content server.

Engaging EMC Support Engineers

Over several weeks, EMC worked with the client IT team to pursue several leads, during which they identified and addressed several issues, including missing authentication configuration, faulty DMCL configuration, and other issues. Additional trace logs were generated and reviewed, and after several more cycles, EMC finally acknowledged that there was a bug in the content server code, and that they would be providing a hotfix ASAP. (See below for additional details about the bug itself.)

The Root Cause

Ultimately, EMC described the root cause of our session acquisition delays as follows: From an analysis of the latest Content Server logs, EMC confirmed seeing delays on the Content Server side. EMC was able to identify the root cause as Microsoft Visual Studio 2003 .NET compiler bug (KB925362) causing Content Server hang during directory creation. EMC observed the same delays during file creation in the latest logs.

Testing the Hotfix in UAT

Unfortunately, EMC was unable to reproduce the problem in their environments, which meant the hotfix would need to be tested extensively in our client environment. The hotfix consisted of a new DLL/PDB for the content server, which was deployed and tested in our UAT environment, with all relevant trace logging enabled. (Although the delay was not presenting in UAT previously, it seemed prudent to test the code in UAT nonetheless, since EMC hadn’t tested it much at all.) Once the hotfix was found to be functioning properly in UAT, it was promoted to Production.

Testing the Hotfix in Production

Once the hotfix was deployed to Production, all relevant trace logging was enabled again. Analysis of the application trace and performance logging showed that the DFC session acquisition delays were  no longer occurring. Additional analysis of the DFC, DMCL, and content-server trace logs by EMC also showed that the underlying delays observed by EMC were no longer occurring.

Problem Solved

It has been several months, and since the hotfix was applied we have not observed Documentum session acquisition to be a problem. EMC indicated the fix would be incorporated into the code line starting 6.5 SP3, but the client has not yet upgraded so I can't personally vouch for whether this ever happened. Presumably it did.

Anyway, that's it! It was quite a ride.

Thanks again to EMC for all their help and support figuring this one out. My only hope is that next time this sort of issue presents it only takes hours, not weeks.

-Jason