Timing Queries

Recently some colleagues and I were trying to debug some slow running DQL.  We decided that it would be really convenient if iDQL32 or one of the various Documentum utilities (RepoInt, Samson, etc.) included a feature that captured timing statistics.  For example, it would be nice to know that the query ran for 5 seconds, it took 1 second to parse the results and 1 second to transmit the results back to the client for a total cost of 7 sec.  Well, as far as I know, no such feature exists, but the same thing can be accomplished using tracing.  For example, using iAPI32, issue the following command before you run your query to turn on tracing with timing statistics:

API> trace,c,10,c:\query.log

Then run your query.

Then issue the following command to turn tracing off:

API> trace,c,0.

The query we were interested in tracing used the DATEFLOOR command.  I was curious about how “expensive” the DATEFLOOR command was.  Here are the two queries I tested followed by the results of the trace.

  • select r_object_id from dm_document where DATEFLOOR(day, "r_creation_date") > DATE("08/01/2000");
  • select r_object_id from dm_document where r_creation_date > DATE("08/01/2000");
1.985  0.109 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.get("readquery,c,select r_object_id from dm_document where DATEFLOOR(day, r_creation_date) > DATE('08/01/2000')") ==> "q0" 
2.094  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.get("get,c,q0,_count") ==> "1" 
2.094  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.get("get,c,q0,_names[0]") ==> "r_object_id" 
2.094  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.get("get,c,q0,_types[0]") ==> "2" 
2.094  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.get("get,c,q0,_lengths[0]") ==> "16" 
2.094  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.exec("next,c,q0") ==> true 
..... 
3.891  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.exec("close,c,q0") ==> true 
3.907  0.031 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.get("readquery,c,select r_object_id from dm_document where r_creation_date > DATE('08/01/2000')") ==> "q0" 
3.938  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.get("get,c,q0,_count") ==> "1" 
3.938  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.get("get,c,q0,_names[0]") ==> "r_object_id" 
3.938  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.get("get,c,q0,_types[0]") ==> "2" 
3.938  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.get("get,c,q0,_lengths[0]") ==> "16" 
3.938  0.016 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.exec("next,c,q0") ==> true 
..... 
5.641  0.000 N/A  [main] com.documentum.dmcl.impl.DmclApiNativeAdapter@9fea8a.exec("close,c,q0") ==> true

So, to get the execution time for the first query, subtract 1.985 from 2.094 to get 0.109 seconds.  This gives you the time from the beginning of the readquery API to the beginning of the get API on the returned collection.  If you subtract the time for the first get API from the time for the close API command, you find that it took 1.797 seconds to parse the results from the collection object and return them to client.  Similarly, the second query execution was 3.938 – 3.907 = 0.031 seconds.  It took 1.703 seconds to parse the results.

The conclusion is that using the DATEFLOOR command is approximately 3 times more ‘expensive’ than not using it, and as it turns out, not really necessary for this query any way.

Additional Notes:

The granularity of the timer results will depend upon your system hardware.  On Windows-based systems you can usually expect about 10-15ms granularity.

By the way, you never have to leave iAPI32 to run your queries if you use the “?” operator.  For example:

API> trace,c,10,c:\query.log
API> ?,c,select r_object_id from dm_document where DATEFLOOR(day, r_creation_date) > DATE('08/01/2000');
API> trace,c,0.

For a good explanation of trace files, see: http://www.xense.co.uk/resources_dmcltr_overview.htm

Advertisements

About Scott
I have been implementing Documentum solutions since 1997. In 2005, I published a book about developing Documentum solutions for the Documentum Desktop Client (ISBN 0595339689). In 2010, I began this blog as a record of interesting and (hopefully) helpful bits of information related to Documentum, and as a creative outlet.

3 Responses to Timing Queries

  1. doquent says:

    Scott,

    Thanks for this great tip. It should be handy in many situations.

    Also, I think that you meant IAPI32 where it says IDQL32 in the Additional Notes.

    I often use dqMan (a free GUI-based query client, similar to repoint or Samson) for its various features such as export results to Excel/CSV. It allows starting a trace tab from Menu (Session > Trace) and you can immediately review trace as you execute a query. Once you are done tracing just close the tab.

    Pawan

    Like

    • scott says:

      Thanks, Pawan. I fixed the typo you mentioned and fired my editor (me!). I’ve used dqMan a few times and included it in the list of open source utilities I knew about (Open Source Utilties). Obviously I am not familiar enough with it to realize it might have been easier than the method I described.

      Like

  2. Pingback: DFC Query Timing, Take 2 | dm_misc: Miscellaneous Documentum Information

Leave a Reply

Fill in your details below or click an icon to log in:

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

%d bloggers like this: