Xense Profiler is a powerful performance analysis tool that enables you to analyse Documentum 5 DMCL (Documentum Client Library) trace files and locate performance data quickly. It is a Windows command line tool that accepts a level 10 DMCL trace as input and outputs a summary report in HTML, text or XML formats.
Xense Profiler supports the following functionality:
Please read the Licensing information in the accompanying file Licensing.txt before installing and using this software.
Version 1.3 contains the following changes and bug fixes:
Version 1.2 is maintenance release that fixes a bug that could cause the profiler to not report the full API in some cases.
Xense Profiler is designed to run as a Windows command line application. It has been tested on Windows Vista, Windows XP, Windows 2003 and Windows 2000. It should run on other Windows 32-bit or 64-bit platforms - if you experience problems running Xense Profiler on other Windows platforms please let us know by mailing to profiler_support@xense.co.uk.
To install, unzip the files (e.g. to c:\Program Files\Xense\Profiler).
To run Xense Profiler open a CMD prompt, CD to the directory where you installed the application. The command line format is as follows:
dmclprof tracefile outputfile [options]
The default operation is to process 'tracefile' and create an HTML report as given by 'outputfile'.
The options that can be specified are as follows:
| Option | Description |
|---|---|
-s[ummary] format |
format can be HTML, XML or TEXT |
-r[pconly] |
filter out API calls that do not generate RPCs |
-l[istthreads] |
filter trace by DMCL thread |
-d[etail] format |
format can be RAW or CSV |
Note. -summary and -detail options are mutually exclusive.
The following command processes the trace file view_draft_cabinet.log and creates an HTML summary report in view_draft_cabinet.htm:
dmclprof view_draft_cabinet.log view_draft_cabinet.htm
The report view_draft_cabinet.htm can be viewed by opening it in a web browser.
To create an XML report:
dmclprof view_draft_cabinet.log view_draft_cabinet.xml -s XML
To create a text report:
dmclprof view_draft_cabinet.log view_draft_cabinet.txt -s TEXT
To filter the HTML report for API calls that generate RPCs:
dmclprof view_draft_cabinet.log view_draft_cabinet.htm -r -s HTML
- or -
dmclprof view_draft_cabinet.log view_draft_cabinet.htm -r
To filter a trace file that contains trace data for 3 different threads (thread numbers 30, 32 and 67) and create a text report:
dmclprof view_draft_cabinet.log view_draft_cabinet.txt -l -s TEXT
When the 'listthreads' option is specified Xense Profiler displays a list of the threads contained in the trace file and prompts you to select one. Just the thread that is selected is then processed.
To transform a DMCL trace file into CSV format:
dmclprof view_draft_cabinet.log view_draft_cabinet.csv -d CSV
To filter a DMCL trace file for just the APIs that generate RPCs:
dmclprof view_draft_cabinet.log view_draft_cabinet_rpconly.log -d RAW -r
The reports generated by Xense Profiler contain 4 sections:
The Top 10 API Calls report lists the 10 API calls that took the most time to complete. For each API the time to complete the API and the full text of the API are reported.
Typically the longest running calls will be one of the query calls (query,query_cmd, execquery, readquery or cachequery) however in some circumstances authentication problems, network problems or database blocking problems can also cause other types of calls to appear in this report.
An example:
| Duration secs |
API Text |
|---|---|
| 81.555 | query_cmd,s1,T,F,,,,,select distinct a.r_object_id, a.object_name,upper(a.object_name) as objname, a.r_object_type, a.a_content_type,a.r_version_label, a.r_lock_owner, a.r_link_cnt, a.r_is_virtual_doc,'y' as selectable, '' as navigatable, 'y' as notnavigatable from dm_document (all) a where a.a_controlling_app = 'dm_dcm' and a.r_lock_owner = ' ' and a.r_object_id != '0900000180050012' and exists (select 1 from dcm_extended_sysobject b where b.parent_id = a.r_object_id and b.document_class in ('Class 1a','Class 1b', 'Class 1c','Class 1d','Class 1e','Class 2') ) and exists (select 1 from dcm_state_extension c where c.parent_id = a.r_policy_id and c.state_no = a.r_current_state and c.document_class = (select d.document_class from dcm_extended_sysobject d where d.parent_id = a.r_object_id) and c.state_type in ('dcm_review') ) and i_latest_flag = '1' order by 3 asc |
| 0.622 | next,s2,q0 |
| 0.376 | execquery,s2,1,SELECT r_object_id,score,text,object_name, r_object_type, r_lock_owner,owner_name, r_link_cnt,r_is_virtual_doc,r_content_size, a_content_type,i_is_reference,r_assembled_from_id, r_has_frzn_assembly, a_compound_architecture,i_is_replica,r_policy_id,subject,r_modify_date FROM dm_sysobject WHERE (object_name LIKE '%XENSE-FORM-99998%' ESCAPE '\') AND (a_is_hidden = FALSE) ENABLE(FTDQL) |
| 0.350 | fetch,s2,57000001800099a0,,T,dm_type_cache_config |
| 0.325 | query_cmd,s2,F,F,,,,,select r_object_id, group_name from dm_group where any users_names = 'John Doe' |
| 0.185 | execquery,s2,0,select category_name from dm_dbo.category where is_active = 1 order by category_name |
| 0.141 | fetch,s2,5700000180009901,,T,dm_type_cache_config |
| 0.141 | fetch,s2,5700000180009909,,T,dm_type_cache_config |
| 0.130 | get,s2,tsop_form:46000001800049b2:Draft.a_status,is_hidden |
| 0.126 | execquery,s2,0,select org_name from dm_dbo.org where is_active = 1 order by org_name |
Clearly the query listed at the top of this report dominates the elapsed time covered by the trace. Performance tuning effort should concentrate on tuning this query.
The API Call Summary reports each type of API call, the number of times the call was made and the total duration for the API call:
| API Call | Duration secs |
Frequency |
|---|---|---|
| close | 0.001 | 150 |
| connect | 0.051 | 5 |
| count | 0.000 | 19 |
| create | 0.008 | 7 |
| disconnect | 0.031 | 5 |
| fetch | 3.433 | 298 |
| get | 0.254 | 32001 |
| id | 0.132 | 72 |
| next | 1.372 | 5215 |
| query_cmd | 4.585 | 180 |
| values | 0.006 | 1789 |
This type of report is particularly useful where there is no single large query dominating the elapsed time covered by the trace. This trace was taken from a system where clicking on a particular folder took 10 seconds to display the contents of the folder. The 10 second elapsed time is 'explained' by the large number of query_cmd, fetch and next statements executed. Tuning effort should concentrate on coding or configuration that reduces the use of these calls or at least reduces the number of times the calls result in RPCs.
The Top Queries report lists the 20 queries that took the most time to complete. For each query the following information is detailed:
An example:
Top Queries
The Top Query report includes the true cost of executing a DQL query. When a query is executed a query API call such as query_cmd, query, readquery, execquery or cachequery is issued to the Content Server and a collection identifier is returned. A 'next' API call is then issued on the collection each time the client application retrieves a row from the query collection. The true cost of the query is not just the duration of the API call to execute the query, it should include the time to execute the 'next' calls on the collection returned by the query call. In many cases a 'problem' query does not show up in the Top 10 API Calls report because no single API call takes long to execute. However aggregating over all the API calls associated with the query shows the true cost of the query. The Query Summary reports all the queries in the trace in the order that they were executed. This report is useful for viewing the overall flow of queries in the application being traced; it can help the performance analyst identify queries that are being executed unnecessarily. RPC Only Filter OptionThe Documentum Client Library (aka DMCL) communicates with the Content Server using Remote Procedure Calls (RPCs). However very many API calls don't generate RPC. A typical ratio is 1 in 10 API calls generate an RPC. Calls that don't generate RPCs usually complete very quickly and their presence in the DMCL trace is often unhelpful noise to the performance analyst. The RPC-Only filtering causes the Profiler engine to ignore API calls that don't generate RPCs. Multi-thread Trace FilesMulti-threaded access to the DMCL is one of the most significant consequences of the move to WDK-based applications. The architecture of WDK applications running in a Java application server means that many DMCL sessions are operating concurrently in the same process. When DMCL tracing is turned on for a DMCL session all the DMCL sessions running in the App server will start logging to a single DMCL trace file. In fact, if you have multiple WDK applications installed into the same application server instance all sessions from all applications will log to the same trace file. The different sessions are identified in the trace by the prefix to each trace line; e.g. in this example trace line the thread number is 324: # [ 324 ] Thu Jan 15 22:31:25 2004 689000 ( 0.000 sec) ( 136 rpc) API> retrieve,c,dm_document The most obvious problem with this is that the size of the DMCL trace can be massively increased. One of the traditional approaches to analysing DMCL traces is to convert the trace into a CSV file and then load the CSV file into Excel. Documentum provide some scripts to do this however the larger API traces now created can exceed the 65000 line limit for a single Excel sheet. There is a more critical problem with the traditional approach to parsing DMCL traces. Consider the following DMCL trace fragment:
# [ 32 ] Thu Jul 6 13:22:24 2006 854499 ( 0.000 sec) ( 1116825 rpc) API> query_cmd,s4,T,F,,,,,select distinct a.r_object_id, a.object_name, ...
# [ 32 ] Thu Jul 6 13:22:24 2006 854865 ( 0.000 sec) ( 1116825 rpc) Server RPC: EXEC (0000000000000000) select distinct a.r_object_id, a.obj...
# [ 33 ] Thu Jul 6 13:22:35 2006 310248 ( 0.000 sec) ( 1116825 rpc) API> get,s2,1100000180003501,user_privileges
# [ 33 ] Thu Jul 6 13:22:35 2006 310663 ( 0.000 sec) ( 1116825 rpc) Res: '0'
# [ 33 ] Thu Jul 6 13:22:35 2006 313807 ( 0.000 sec) ( 1116825 rpc) API> get,s2,0c0000018000555f,_changed
... <58 seconds of thread 33 trace omitted here>
# [ 33 ] Thu Jul 6 13:23:33 2006 355773 ( 0.000 sec) ( 1118181 rpc) API> get,s2,0b00000180005561,object_name
# [ 33 ] Thu Jul 6 13:23:33 2006 355883 ( 0.000 sec) ( 1118181 rpc) Res: 'Draft'
# [ 32 ] Thu Jul 6 13:23:46 2006 409286 ( 81.555 sec) ( 1118182 rpc) Res: 'q0'
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 as the APIs you are most likely to be interested in are the long-running ones, the ones most likely to suffer from incorrect attribution. Xense Profiler addressed all these problems:
Bugs, Feature Requests and CommentsPlease let us know what you think of Xense Profiler and how it can be improved by mailing to profiler_development@xense.co.uk. Known Issuesnone
|