Tracing in DFC 5.2 and Beyond

Introduction

Software developers wield an arsenal of tools to track down bugs and improve code efficiencies. There are debuggers, code analyzers, and profilers, but one of the simplest and most effective ways to gain insight into what is going on in an application is to use tracing.

Documentum has offered tracing as a feature of DFC and DMCL since they were originally introduced, but prior to DFC 5.2, these application layers utilized different tracing technologies. This resulted in a slow, manual, and often inexact process for following the execution path from your DFC application through to DMCL. DFC 5.2 introduces an integrated tracing system that combines tracing output from numerous Documentum products. It is now possible to see an entire execution path from a WDK-based application through DFC and into DMCL. This can be an invaluable tool for figuring out why a certain block of application code isn’t behaving properly or why it isn’t demonstrating desirable performance characteristics.

The tracing offered in DFC 5.2 is much more granular that in previous versions so it’s possible to inspect the execution in as much detail as needed. Each DFC method now implements tracing in a uniform manner.

In this article we’ll review how to configure tracing in DFC 5.2 and how to interpret the tracing output.

Interpreting Trace Output

The following trace tags are commonly seen in the trace output. These tags point out different events during the flow of execution.

Trace Tag	Comments
.<init>	Constructor
.<clinit>	Static initializer. Usually coupled with [S]
[started]	DFC tracing preamble (method entrance)
[finished]	DFC tracing postscript (method exit)
[S]	static method
[SYNC]	Synchronized method

At times, some of the tags appear along with others. for example, you will often see [S] and [started] on the same trace entry, meaning the method is Static and it is at the method entry point. Other times, you might see .<init> and [started] on the same trace entry, meaning it is just entering a constructor method. Sometimes, you will also encounter tags combined. A static and synchronized method is tagged as [S SYNCH]

dfc.properties Configuration

DFC tracing is enabled and configured via two different configuration files. The dfc.properties file controls the trace messages that DFC generates. The log4j.properties file controls the filtering and display of the log information. We’ll take a look at that file in a later section.

DFC 5.2 introduced the dfc.properties file. This file controls numerous aspects of DFC including tracing. This file is located in the %DFC_DATA%/config directory. There are eight properties related to tracing. They are listed below for reference. A file describing all of the possible options for dfc.properties can be found at %DFC_DATA%/config/dfcfull.properties

Property	Values	Default	Description
dfc.tracing.enabled	true | false	false	Specifies whether to enable or disable trace.
dfc.tracing.recordParameters	on | off	on	Specifies whether to record the parameter information of methods, if any, while tracing.
dfc.tracing.recordReturnValue	on | off	on	Specifies whether to record the return value of methods, if any, while tracing
dfc.tracing.recordTiming	on | off	off	Not implemented in 5.2. Specifies whether to include system time with the trace information. Control this behavior via log4j layout pattern
dfc.tracing.recordThreading	on | off	off	Not implemented in 5.2. Specifies whether trace entry should identify the executing thread. Control this behavior via log4j layout pattern
dfc.tracing.compactMode	on | off	on	Not implemented in 5.2. Specifies whether to “roll-up” trace output. Use dfc.tracing.stackDepth > 0 instead. See dfc.tracing.stackDepth
dfc.tracing.stackDepth	positive integer	100	Specifies how many levels deep the method calls need to be traced. When used with compactMode determines a summary level for return values. In DFC 5.2 compactMode is ignored and the dfc.tracing.stackDepth determines the summary level for return values.
dfc.tracing.combineDMCL	on | off	off	Specifies whether to combine the trace of DMCL along with other traces

By default, the tracing facility is disabled. Tracing each method call and its arguments can dramatically impact performance. Tracing should only be used when trying to track a specific problem and should only be used for the duration of the test.

Each configuration option will be presented separately in the folling set of configuration examples.

Example: recordParameters = on

DFC Trace Settings

                
dfc.tracing.enabled = true
dfc.tracing.recordParameters = on
dfc.tracing.recordReturnValue = off
dfc.tracing.stackDepth = 100
dfc.tracing.combineDMCL = off

            

Example

                
15:01:47,240 [HttpProcessor[85][4]] .com.documentum.fc.client.DfDocument@ac06d4.getString (’owner_name’) 
15:01:47,240 [HttpProcessor[85][4]] ..com.documentum.fc.client.DfDocument@ac06d4.getAttachedSession() 
15:01:47,240 [HttpProcessor[85][4]] ..com.documentum.fc.client.DfDocument@ac06d4.getObjectId() 
15:01:47,240 [HttpProcessor[85][4]] ..com.documentum.fc.common.DfId@6b443cec.isNull() 
15:01:47,240 [HttpProcessor[85][4]] ..com.documentum.fc.client.DfSession@6e41b5.apiGet [SYNCH] (’get,s0,0901889e8000e4c2,owner_name’) 

            

When the recordParameters property is set to on, you can see the values of method arguments in the trace output. In this example, you can see 'owner_name' as an argument to getString(). You can also see the arguments to apiGet()

Example: recordReturnValue = on

DFC Trace Settings

                
dfc.tracing.enabled = true
dfc.tracing.recordParameters = on
dfc.tracing.recordReturnValue = on
dfc.tracing.stackDepth = 100
dfc.tracing.combineDMCL = off

            

Example

                
15:20:57,572 [HttpProcessor[85][4]] .com.documentum.fc.client.DfDocument@1b7b407.getString (’owner_name’) testdev
15:20:57,572 [HttpProcessor[85][4]] ..com.documentum.fc.client.DfDocument@1b7b407.getAttachedSession() com.documentum.fc.client.DfSession@a1aa85
15:20:57,572 [HttpProcessor[85][4]] ..com.documentum.fc.client.DfDocument@1b7b407.getObjectId() 0901889e8000e4c2
15:20:57,588 [HttpProcessor[85][4]] ..com.documentum.fc.common.DfId@6b443cec.isNull() ‘false’
15:20:57,588 [HttpProcessor[85][4]] ..com.documentum.fc.client.DfSession@a1aa85.apiGet [SYNCH] (’get,s0,0901889e8000e4c2,owner_name’) testdev

            

When the recordReturnValue property is set to on, you can see the return values of method calls. In this example, you can see 'testdev' as the return result to getString('owner_name'). You can also see how this was returned from the call to apiGet(). return values are included by adding them to the end of a method line. Sometimes they are placed at the end of the [finished] line (see dfc.tracing.stackDepth). Boolean values appear inside single quotes (’true’).

Example: combineDMCL = on

DFC Trace Settings

                
dfc.tracing.enabled = true
dfc.tracing.recordParameters = on
dfc.tracing.recordReturnValue = on
dfc.tracing.stackDepth = 100
dfc.tracing.combineDMCL = on

            

Example

                
12:06:05,093 [HttpProcessor[85][4]] .com.documentum.fc.client.DfDocument@a86d12.getString (’owner_name’) testdev
12:06:05,093 [HttpProcessor[85][4]] ..com.documentum.fc.client.DfDocument@a86d12.getAttachedSession() com.documentum.fc.client.DfSession@da9ea4
12:06:05,093 [HttpProcessor[85][4]] ..com.documentum.fc.client.DfDocument@a86d12.getObjectId() 0901889e8000e4c2
12:06:05,093 [HttpProcessor[85][4]] ..com.documentum.fc.common.DfId@6b443cec.isNull() ‘false’
12:06:05,093 [HttpProcessor[85][4]] ..com.documentum.fc.client.DfSession@da9ea4.apiGet [SYNCH] (’get,s0,0901889e8000e4c2,owner_name’) testdev
12:06:05,093 [HttpProcessor[85][4]] ..dmcl::API> get,s0,0901889e8000e4c2,owner_name
12:06:05,093 [HttpProcessor[85][4]] ..dmcl::Res: testdev

            

When the combineDMCL property is set to on, DMCL log information is included with the DFC trace. DMCL trace lines are prefixed with dmcl::API> for the command or dmcl::Res: for the result.

Note: IDfClient.traceDMCL(true) does not affect this tracing facility

Example: stackDepth = 0

DFC Trace Settings

                
dfc.tracing.enabled = true
dfc.tracing.recordParameters = on
dfc.tracing.recordReturnValue = on
dfc.tracing.stackDepth = 0
dfc.tracing.combineDMCL = off

            

Example

                
12:49:03,605 [HttpProcessor[85][3]] .com.documentum.fc.client.DfDocument@196bac4.getString (’owner_name’) [started]
12:49:03,605 [HttpProcessor[85][3]] ..com.documentum.fc.client.DfDocument@196bac4.getAttachedSession() [started]
12:49:03,605 [HttpProcessor[85][3]] ..getAttachedSession [finished] com.documentum.fc.client.DfSession@1c21ece
12:49:03,605 [HttpProcessor[85][3]] ..com.documentum.fc.client.DfDocument@196bac4.getObjectId() [started]
12:49:03,605 [HttpProcessor[85][3]] ..getObjectId [finished] 0901889e8000e4c2
12:49:03,605 [HttpProcessor[85][3]] ..com.documentum.fc.common.DfId@6b443cec.isNull() [started]
12:49:03,605 [HttpProcessor[85][3]] ..isNull [finished] ‘false’
12:49:03,620 [HttpProcessor[85][3]] ..com.documentum.fc.client.DfSession@1c21ece.apiGet [SYNCH] (’get,s0,0901889e8000e4c2,owner_name’) [started]
12:49:03,620 [HttpProcessor[85][3]] ..dmcl::API> get,s0,0901889e8000e4c2,owner_name
12:49:03,620 [HttpProcessor[85][3]] ..dmcl::Res: testdev
12:49:03,620 [HttpProcessor[85][3]] ..apiGet [finished] testdev
12:49:03,620 [HttpProcessor[85][3]] .getString [finished] testdev

            

The stackDepth property determines how many trace entry lines are buffered before they are flushed to output. Buffering trace lines enables return values to be summarized on the same line as the original call. By setting stackDepth = 0 buffering is effectively turned off so each call is marked as [started] and the return result isn’t displayed until the call returns which is marked with a [finished].

Note: The return value summarization was intended to be controlled via the dfc.tracing.compactMode property but as of 5.2, return value summarization is controlled entirely by the stackDepth property.

log4j.properties Configuration

The tracing facility is based on DFLogger which utilizes Apache’s log4j logging infrastructure. The log4j.properties file determines how tracing messages are rendered and where and how they are stored or displayed.

A detailed description of log4j is beyond the scope of this article. Please see the log4j documentation for in-depth coverage of log4j.

The log4j.properties file is located in the %DFC_DATA%/config directory.

Trace files are often very large. By default most installations have a RollingFileAppender and a 10MB MaxFileSize. That is sufficient for most uses.

By default log4j.properties sets additivity for tracing to false. This is recommended as it forces the tracing category NOT to inherit from the root logger. This generally yields more predictable tracing behavior.

An example set of log4j.properties related to tracing (from a default Web Publisher 5.2 installation) is below:

                
log4j.additivity.tracing=false
log4j.category.tracing=DEBUG, FILE_TRACE
log4j.appender.FILE_TRACE=org.apache.log4j.RollingFileAppender
log4j.appender.FILE_TRACE.File=C:\\dfctrace.log
log4j.appender.FILE_TRACE.MaxFileSize=10MB

            

Note: log4j.properties is a Java properties file. Strings are interpreted using standard Java String substitutions including \n, \\, etc. Backslash (\) is the escape character. File paths must either be expressed using forward slashes (/) or escaped backslashes (\\).

Inserting Custom Trace Messages

Sometimes it’s useful to inject custom debugging output into the trace stream. An example of when this might be the case is if you require very detailed tracing over an extended operation. In this case, large amounts of tracing information might be generated and inserting a custom trace message as a focal point might help in finding relevant information in the trace file.

                
DFLogger.info("tracing", "<-- Begin My Custom Trace Here -->", null, null);
... traceable actions ...
DFLogger.info("tracing", "<-- End My Custom Trace Here -->", null, null);

            

In this example, we delimit the trace information that we’re interested in with begin and end focal points to help locate the relevant traces.

Notice the "tracing" argument to DFLogger. Typically you would pass this to DFLogger as the first argument. Tracing is handled as a separate logging category. This corresponds to the line in the log4j.configuration file that looks like this:

                
log4j.category.tracing=DEBUG, FILE_TRACE

            

Changes to DFTrace

The changes introduced with the new DFC tracing infrastructure dictated a few changes to DFTrace. Much of DFTrace has been deprecated. The changes are listed below:

Method	Comments
setTraceLevel()	Levels 0-3 are interpreted as off. Levels 4-10 are interpreted as on
getTraceLevel()	Deprecated. Use DfTracer.isEnabled()
setTraceFileName()	Deprecated. Use log4j.properties
getTraceFileName()	Deprecated. Returns the shared file name
setTraceTime()	Deprecated. Use recordTiming in dfc.properties
getTraceTime()	Deprecated
flushTrace()	Ignored
closeTrace()	Deprecated
traceMsg()	Deprecated. Use DfTrace.message()
traceMsgCond()	Deprecated

Summary

In this article we have explored the changes to tracing introduced in DFC 5.2. The tracing features are consistent across Documentum applications and it is now possible to trace a thread of execution through each of the application layers.

We reviewed how to interpret the tracing output and examined how each of the settings in dfc.properties affects the traces. Utilizing the appropriate logging features will enable you to find just the information that you are interested in without swimming in oceans of traces.

This article only touches on the basics of tracing in DFC 5.2. As much of the tracing infrastructure is currently layered on top of log4j, it is highly recommended to become familiar with that technology so as to be able to fully utilize the advances in Documentum’s tracing tools.