Performance Analysis of DMCL Trace Files

May 11, 2007 at 3:48 pm | Posted in Performance, Troubleshooting, Xense Profiler | 2 Comments

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:

Duration
secs
API Text
3.094 next,s0,q1
0.594 query_cmd,s0,T,F,,,,,select r_object_id from dm_document where folder(‘/WebPublisher Configuration/Content Templates’,descend) OR folder(‘/WebPublisher Configuration/Supporting Templates’,descend)
0.157 next,s0,q1
0.156 execquery,s0,1,select sysobj.r_object_id from dm_dbo.dm_webc_8009c009_s actv, dm_sysobject sysobj WHERE actv.r_object_id = sysobj.r_object_id AND sysobj.r_modify_date > DATE (’01/01/1970 00:00:01′) AND sysobj.r_modify_date
0.156 query_cmd,s1,T,F,,,,,select r_object_id, i_folder_id,r_modify_date, object_name, title from dm_category where r_modify_date > DATE(’01/01/1970 00:00:01′) AND r_modify_date
0.125 connect,dm3,dmadmin,xxxxxxxx
0.109 execquery,s0,1,select sysobj.r_object_id from dm_dbo.dm_webc_8009c009_s actv, dm_sysobject sysobj WHERE actv.r_object_id = sysobj.r_object_id AND sysobj.r_modify_date > DATE (’01/01/1970 00:00:01′) AND sysobj.r_modify_date
0.078 connect,dm3,dmadmin,xxxxxxxx
0.063 query_cmd,s0,T,F,,,,,select r_object_id, i_folder_id,r_modify_date, object_name, title from dm_category where r_modify_date > DATE(’01/01/1970 00:00:01′) AND r_modify_date
0.047 fetch,s0,090000038000f29a,,F

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:

3.875  select r_object_id from dm_document where folder(‘/WebPublisher Configuration/Content Templates’,descend) OR folder(‘/WebPublisher Configuration/Supporting Templates’,descend)

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.

Advertisements

2 Comments »

RSS feed for comments on this post. TrackBack URI

  1. Robin

    What kind of troubleshooting do you try to do when you see what queries are taking the longest?

  2. Austin, I guess this is a follow on from your questions in the support forumns. I generally run a dmcl trace, then run it through the Xense Profiler as above. There are various ways to run a dmcl trace – if you are running a wdk application then you can set a trace running using the url (assuming you are using webtop but just replace the application name as appropriate):

    http://:/webtop/wdk/dmclTrace.jsp?level=10&logfile=c:api.log

    this sets dmcl tracing at level 10 (the one that records timing info in the file) and logs to c:\api.log.

    Now run a slow performing action in the client interface.

    don’t forget to turn off tracing afterwards:

    http://:/webtop/wdk/dmclTrace.jsp?level=0

    There are other ways if you are using other client interfaces


Leave a Reply

Please log in using one of these methods to post your comment:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Blog at WordPress.com.
Entries and comments feeds.

%d bloggers like this: