Inside Documentum

DMCL trace analysis problems – misattribution

DMCL level 10 trace is a fantastic source of performance tuning information. Every command and query that is submitted to the content server is captured along with timing information. But it does pose some problems for the performance analyst. There is often reams of trace information. A typical client action will involve thousands of calls into the dmcl. In all likelihood you are only interested in a fraction of these. To make matters worse a web application like WDK that runs many user sessions in a single DMCL instance will record trace information for all active sessions.

Documentum does provide some awk scripts that analyse the traces and pick out the longest running apis but they don’t work terribly well with the multi-threaded dmcl trace created by WDK applications. Consider the following DMCL trace fragment.

2 DMCL threads are being run concurrently, threads 32 and 33. Thread 32 runs a query using a query_cmd call that takes 81.555 seconds to complete. In between the time the query_cmd call is issued and the response is received thread 33 is making calls into the DMCL as well.

The standard parsing script provided by Documentum (parsetrace.awk) shows the following API consuming 81.555 seconds:

32 81.555 1118182 get,s2,0b00000180005561,object_name q0

The problem is one of incorrect attribution. The duration obtained from the thread number 32 Res: trace line (81.555) is attributed to the immediately preceding API> trace line. In this case however this turns out to be an API call from a completely unrelated thread number 33.

This is a major problem for any DMCL trace involving multiple threads. The APIs you are most likely to be interested in are the long-running ones, the ones most likely to suffer from incorrect attribution. One of the features of Xense Profiler is to attribute the correct timings to every API, enabling the performance analyst to quickly identify the true performance problems.