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.

At times, some of the tags appear along with others. for example, you will often see xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>[S]

and xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>[started]

on the same trace entry, meaning the
method is xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>S

tatic and it is at the method entry point. Other times, you might see xmlns:xsi="https://www.w3.org/2001/XMLSchema-instance">.<init>

and
xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>[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 xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>[S SYNCH]

dfc.properties Configuration

DFC tracing is enabled and configured via two different configuration files. The xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>dfc.properties

file controls the trace messages that DFC generates. The xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>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 xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>dfc.properties

file. This file controls numerous aspects of DFC including tracing. This file is located in the xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>%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 xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>dfc.properties

can be found at xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>%DFC_DATA%/config/dfcfull.properties

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 xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>recordParameters

property is set to xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>on

, you can see the values of method arguments in the trace output.
In this example, you can see xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>’owner_name’

as an argument to xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>getString()

. You can also see the arguments to xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>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 xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>recordReturnValue

property is set to xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>on

, you can see the return values of method calls.
In this example, you can see xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>’testdev’

as the return result to xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>getString(‘owner_name’)

. You can also see how this
was returned from the call to xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>apiGet()

. return values are included by adding them to the end of a method line. Sometimes they are
placed at the end of the xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>[finished]

line (see xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>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 xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>combineDMCL

property is set to xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>on

, DMCL log information is included with the DFC trace. DMCL trace lines
are prefixed with xmlns:xsi="https://www.w3.org/2001/XMLSchema-instance">dmcl::API>

for the command or xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>dmcl::Res:

for the result.

Note:
xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>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 xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>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 xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>stackDepth = 0

buffering is effectively turned off so each call is marked as xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>[started]

and the return result isn’t
displayed until the call returns which is marked with a xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>[finished]

.

Note:
The return value summarization was intended to be controlled via the xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>dfc.tracing.compactMode

property but as
of 5.2, return value summarization is controlled entirely by the xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>stackDepth

property.

log4j.properties Configuration

The tracing facility is based on DFLogger which utilizes Apache’s log4j logging infrastructure. The xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>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 xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>log4j.properties

file is located in the xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>%DFC_DATA%/config

directory.

Trace files are often very large. By default most installations have a xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>RollingFileAppender

and a 10MB xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>MaxFileSize

. That is sufficient for most uses.

By default xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>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:
xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>log4j.properties

is a Java properties file. Strings are interpreted using standard Java String
substitutions including xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>n

, xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>

, etc. Backslash ( xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>

) is the escape character. File paths must
either be expressed using forward slashes ( xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>/

) or escaped backslashes ( xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>

).

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 xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>”tracing”

argument to DFLogger. Typically you would pass xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>this

to DFLogger
as the first argument. Tracing is handled as a separate logging category. This corresponds to the line in the
xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>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:

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
xmlns:xsi=”https://www.w3.org/2001/XMLSchema-instance”>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.