Inside Documentum

A couple of weeks ago I was investigating a slow running application. As usual I started a dmcl trace to work out where the performance problem was occurring. The largest API time was the following:

# [ 712 ] Thu Apr 12 15:45:58 2007 109000 ( 0.000 sec) ( 69 rpc) API> next,s0,q1
# [ 712 ] Thu Apr 12 15:45:58 2007 109000 ( 0.000 sec) ( 69 rpc) Server RPC: MultiNext (17)
# [ 712 ] Thu Apr 12 15:46:01 2007 203000 ( 3.094 sec) ( 70 rpc) Res: 'OK'


This trace excerpt indicates that:

1. a ‘next’ api call took 3.094 seconds to complete
2. The session involved was s0
3. The next call was on a collection called q1

The next api is simply a call to retrieve the next row from a collection; in this case the collection is q1. Usually this collection originates from a query although certain other API calls also return collections, most notably the apply api to run an administration method.

So to find out which query is causing the performance problem we would have to search backwards in the trace file to find the last API that returned a collection q1 on session s0. This is all rather messy and if you have a large trace file (perhaps generated from a WDK application with a large numbers of users) rather error prone.

Luckily this work is automated by the Xense Profiler, a Windows command-line tool that takes a DMCL trace file as input and generates a performance profile report. For example if my trace file is called api.log then the following command creates a HTML report:

dmclprof api.log api.htm

If you view the report in your browser you will see a number of sections including a Top 10 API calls and a query summary. The Top 10 API Calls looks like this:

Here you can see the next API is the longest running call in the trace. Looking at the Query Summary report however shows all the queries that have been run in the system and provides a total elapsed time for each query – the total elapsed time for a query includes the time to run all the next APIs as well as the initial query call. The one that stands out is:

Having identified the culprit we can now start remedial action.

Before we developed the Xense Profiler analysing DMCL traces could be a time-consuming and frustrating business. Using the Xense Profiler I can pinpoint the performance problem in minutes.

By the way although the tool runs on Windows it will accept a DMCL trace generated on any platform. I am planning to provide a Java-based port of the tool, if you are interested in hearing more about this then drop me a mail at robin.east@xense.co.uk.