Writing great code with the IBM FileNet P8 APIs, Part 2

Spying on your handiwork

Techniques for seeing what you're putting on the wire


Content series:

This content is part # of # in the series: Writing great code with the IBM FileNet P8 APIs, Part 2

Stay tuned for additional content in this series.

This content is part of the series:Writing great code with the IBM FileNet P8 APIs, Part 2

Stay tuned for additional content in this series.

If you're using P8 APIs, it's probably because you are involved in writing enterprise applications. If you're involved in writing enterprise applications, performance is sooner or later going to work its way to the top of your priority list. Even if performance is just great in the isolation of your development environment, it's sometimes hard to predict what will happen when your application is deployed under a realistic multi-user load. Future articles will deal with some specific coding techniques for squeezing out the best performance. This article lays the groundwork for that by discussing some tools and techniques to see what data you are passing around. It might seem like a temporary diversion from the nuts and bolts of coding, but you will find the information valuable as you read future articles in this series and as you develop your own applications.

For a great many applications, there are two key performance drivers:

  • First, the overall performance picture is often dominated by the number of network calls your client application makes to the P8 servers. Depending on who you ask, network calls can be referred to by a number of names: round trips (R/Ts), remote procedure calls (RPCs), server hits, and other similar sounding names. They all mean about the same thing: the plumbing involved in transmitting a request from the client to the server and having the server compute and transmit a response. In a development environment, an RPC might take only a few tens or hundreds of milliseconds. In fact, it's relatively rare for a P8 RPC to take a significant fraction of a second in an isolated environment. In a fully loaded environment, those times stretch out as requests compete with each other on the network, on the server, and, in some cases, on the client. Where everything is being magnified, it pays to eliminate or reduce as much overhead as you can. For two discrete pieces of work that need to be done on the P8 server, it's always cheaper (except in really pathological cases) if you can do them in a single RPC instead of two RPCs.
  • Second, performance is affected by the amount of data—the number of bytes—that actually travel across the wire in an RPC. This isn't just a matter of how fast a network router can handle bits. The more data that's involved, the harder the client APIs and their server counterparts need to work to assemble and interpret the requests. In a P8 environment, the sizes of requests are almost always a small fraction of the sizes of the responses, so trying to tune the sizes of requests is seldom worth the trouble. Tuning the sizes of RPC responses can often have a significant performance impact, and it is always worth at least an investigation.

This article addresses a few things that will help you get a feeling for what your application is doing in both of those areas.

  • A network tracing tool helps you look at the low-level data traveling over the network. Although it sounds complicated, modern tools in this area are reasonably easy to operate, and they can make it straightforward to drill down into particular areas.
  • With P8 Content Java API logging, you can instruct the API to tell you what it is doing at various points. This is a good technique for assessing both the number and size of RPCs.
  • You can use ObjectDumper in your own developing code to get a snapshot of what's inside a P8 API object. That's useful for judging how much data an object is carrying behind the scenes and also for seeing the differences that various actions have on that data.

Using network tracing

What is a sniffer?

Network tracing refers generically to the capture of raw data flowing over a network. Tools for this are sometimes called network analyzers, network sniffers, or packet sniffers. The original sniffers were specialized pieces of standalone equipment that could be physically attached to a network segment. Such equipment still exists, but there are now software equivalents for everyday use. Although the primary original use of sniffers was to diagnose networking problems at a fairly low level, they can also sometimes be used very effectively to get a picture of the communication between components of a distributed application. Network tracing sounds like an arcane and unapproachable topic for anyone but a specialist, but it is very approachable for the average developer. The tools available today generally have good user interfaces and quite reasonable documentation.

Besides the capture and analysis of live network traffic, sniffers can also be used to save the traffic to a file or to read such a file of saved traffic. Such files are commonly called capture files. There are a few de facto industry-standard capture file formats, so there is a good chance (but no guarantee) that a capture file produced by one sniffer application can be understood by a different sniffer program.

If you don't already have a network tracing tool, a Web search for any of the terms mentioned above will present several popular alternatives, including some that are open source or otherwise free. For the purposes of illustration, this article uses Wireshark, a powerful and popular open source sniffer available from Wireshark version 1.0.5 was used for this article, but if you use an earlier version or a different tool entirely, the concepts discussed can still apply, and you should have no trouble following along. The goal here is not to make you an expert in any particular sniffer tool. Rather, this article gives you a glimpse of the possibilities so that you can explore further on your own.

Capturing a network trace

The main purpose of a software sniffer is that it listens to traffic flowing through the networking stack on a computer without interfering with that traffic. That's not really the same thing as listening on the network itself, but it's more than close enough for the things you will be doing. Because the sniffer is just a program running on a computer, the first thing you have to think about is which computer you will run it on. This is sometimes dictated functionally by the things you are trying to examine. The sniffer only sees things from the point of view of the computer it's running on, and it usually cannot see network traffic between two or more other computers. In fact, in more complex cases, it is sometimes necessary to run sniffers on multiple computers simultaneously so that activities can be correlated. That's not the case for this scenario, though, because you have only point-to-point conversations to watch. Your choice boils down to the computer where your API client is running or the computer where the P8 server is running. Assuming you have equal access to both computers, it might make sense to run it on your client machine. That enables you to avoid the minor clutter of requests coming in from other clients if your P8 server is shared. If your P8 server is not shared or has very little activity on it, the choice is just a matter of your own convenience. For the routine sorts of tasks that are in this article's scenario, a software sniffer generally imposes a minimal load on its host. This article assumes you are running the sniffer on the client machine, but it should be pretty easy to see what you'd do differently if that's not the case.

Suppose you have a running application and want to observe and tune the performance-related factors described earlier. If you're not yet at that stage and just want a simple application to run to see how the techniques in this article work, you can download the HelloDocument sample application from the first article in this series. There are a couple of caveats you should consider when running a sniffer along with your application:

  • Use WSI transport instead of EJB transport. WSI transport uses XML transmitted using HTTP. EJB transport, on the other hand, uses formats and protocols dictated by the application server being used. In general, EJB transport employs compressed or terse binary formats. Those are great for client/server communication, but they are difficult to deal with when inspecting network traffic visually.
  • Do not use TLS/SSL protection on your connections. By its very intent, TLS/SSL makes it impossible to look inside intercepted traffic. Even if a third party listens to the entire TLS/SSL connection setup conversation, it won't be able to decrypt the subsequently protected traffic. Sniffers don't have any magical power to see through the TLS/SSL veil. Running without TLS/SSL protection exposes your traffic and raw credentials to potential eavesdropping, so you'll want to use non-sensitive information and accounts while you are running your sniffer tests. Because you are probably doing this in a development or test environment, that should be easy to arrange.

In case it's not obvious, the above points taken together mean that your Content Engine connection URI should be an HTTP URI (not HTTPS and not a non-HTTP URI).

The general pattern is to turn on the sniffer, run the application, turn off the sniffer, and analyze the network traffic. Figure 1 shows the beginning of a capture session. Each line in the top window represents a single captured IP packet. In the jargon of sniffers, packets are also called frames. It would be an understatement to say that this is a complex and busy screen for the uninitiated. Where is the interesting P8 RPC data that you are looking for? Actually, there is none in Figure 1. Figure 1 shows less than the first second or so of network activity, which is not even enough time to have switched to another window and started your application.

Figure 1. Raw, unfiltered network trace
Raw, unfiltered network trace
Raw, unfiltered network trace

Of course, you can scroll down through the list of packets to find the packets you're looking for. Wouldn't it be nice, though, if there were a way to get rid of the things you know you're not interested in? Of course, you can. There are two approaches to that: you can tell the sniffer tool to hide irrelevant frames from the display, or you can tell the sniffer to ignore irrelevant frames while it is capturing traffic. With the first approach, you can change your mind later and redisplay hidden frames. With the second approach, those frames are gone forever. The advantage of the second approach is that the sizes of capture files are correspondingly smaller. That makes a difference if you run a trace for a longer time. Because you will mainly be doing network tracing in small sessions and can rerun the entire session if you miss something, the choice is pretty much a matter of your own convenience. If you end up capturing a network trace to send to someone else, that person might have a preference for how things are filtered (or not filtered) during the capture.

Each sniffer has its own user interface and methods for setting up filter conditions. For some of them, there are differences for how the filtering is done for the two approaches. Almost all make it pretty easy, though there is some jargon to get used to before you know exactly what the tool is talking about. Here are some useful criteria for filtering out frames. These figures simply refine the data shown in Figure 1.

  • TCP only. For WSI transport, all P8 traffic flows over TCP connections. It therefore makes sense to filter out all UDP traffic. There is one case where you might find it useful to keep UDP traffic. If you are troubleshooting a DNS problem (this article assumes that you are not), you see that most DNS traffic travels over UDP. Your local network also typically has odds and ends of traffic that is neither TCP nor UDP. In fact, unless you are on a very isolated network, you will probably be surprised to see how much there is. It can be entertaining and educational to see those packets and try to figure out what they are, but they are not relevant for this scenario. Figure 2 shows the same network trace as in Figure 1 with only the TCP frames shown.

    Figure 2. Network trace filtered to TCP
    Network trace filtered to TCP
    Network trace filtered to TCP
  • Target host only. Even by restricting the trace to TCP frames, you still see many irrelevant frames. In fact, in Figure 2, none of the frames are relevant, and you still see less than the first two seconds of traffic on the first screen. The conversation you want to capture is point-to-point. Because you are running the sniffer on the client machine, filter the trace to show only frames for the server host. Be careful when setting this filter that you include packets both to and from the target host. Otherwise, you will see only half of the conversation. For the example scenario, the target host has the IP address Figure 3 shows the network trace further filtered by destination IP address. Depending on your sniffer tool and settings, you might be able to do the same thing using host name instead of IP address.

    Figure 3. Network trace filtered to target host
    Network trace filtered to target host
    Network trace filtered to target host
  • Target port only. You can further filter the trace to the particular destination port that you are using. Again, you want packets to or from that target port. In the example scenario, the port number is 9080, which is the WebSphere™ default for the P8 WSI transport. Figure 4 shows the trace further filtered according to destination port.

    Figure 4. Network trace filtered to target port
    Network trace filtered to target port
    Network trace filtered to target port

    As a side note, you might wonder why the Info column seems to be calling the target port glrpc. Wireshark, by default, tries to label things for user convenience. In the official port number registry (see Related topics) maintained by the Internet Assigned Numbers Authority (IANA), TCP port 9080 is designated for Groove GLRPC, so that is how Wireshark labels it. It's just a label, and you don't have to worry about it, as you'll see in the next item. In the middle window of Figure 4, you can just make out that glrpc is really port 9080.

  • Wireshark can do many types of protocol-specific decoding if it knows what protocol it's actually dealing with. Click Analyze > Decode as to interpret port 9080 traffic as HTTP. See Figure 5.

    Figure 5. Wireshark decoding
    Wireshark decoding
    Wireshark decoding

    Figure 6 shows the trace with HTTP decoding applied. Some packets continue to be marked as TCP even though they involve port 9080. That's because they don't have any real HTTP specifics to them. Those packets are network acknowledgment packets and other TCP bookkeeping. In theory, you could be falsely marking some packets with a source port of 9080 as HTTP, where only target port of 9080 is relevant. In practice, this is seldom an issue.

    Figure 6. Network trace decoded as HTTP
    Network trace decoded as HTTP
    Network trace decoded as HTTP

Now that you have the trace filtered down to just the interesting packets, what should you look at? Figure 6 highlights frame 295 and expands the bottom two windows to show more detail. You can probably deduce from just the information shown that you are looking at a success response from the Web services listener on the P8 Content Engine server. The sniffer tool is showing things at the packet level, so you can see the values of all of the IP and TCP header fields as well as the HTTP payload itself. That's handy for some things, but an HTTP conversation can span many TCP packets. Obviously, there's going to be at least one packet for the request and one packet for the response, but there is a good chance that either or both of them will spill over into continuation packets. Because you're mostly interested in the HTTP payload, it would be nice if you could just see that without all of the other packet bookkeeping. It would also be nice if you could readily visualize the request along with the response. Wireshark has a feature that does just that. If you right-click an HTTP packet and select Follow TCP stream, Wireshark pops up a window like the one shown in Figure 7.

Figure 7. Following a TCP stream
Following a TCP stream
Following a TCP stream

Because Figure 7 might be a little difficult to read, Listing 1 contains the same information with only minimal changes. To make it fit the page width constraints, some of the continuous lines of XML and other long lines are broken at arbitrary points. Embedded carriage returns are translated into the visible two-character sequence ^M.

Listing 1. Text from Figure 7
User-Agent: IBM FileNet P8 CE Java API (X.Y.Z / dapNNN.MMM)^M
Date: Sat, 24 Jan 2009 00:58:55 +0000^M
Content-Type: application/soap+xml; charset=UTF-8^M
Host: MyCEServer:9080^M
Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2^M
Connection: keep-alive^M
Transfer-Encoding: chunked^M
<?xml version="1.0" encoding="UTF-8"?><e:Envelope 
<e:Body><GetObjectsRequest><ObjectRequest id="1" cacheAllowed="1">
<SourceSpecification i:type="ObjectReference" classId="Domain">
HTTP/1.1 200 OK^M
Server: Systinet Server for Java/6.5.4 (Java/1.5.0; Windows Server 2003/5.2 
    build 3790 Service Pack 2; build SSJ-6.5.4-20060829-1824)^M
Content-Type: multipart/related; 
    type="application/xop+xml"; start-info="application/soap+xml"; 
Content-Language: en-US^M
Transfer-Encoding: chunked^M
Date: Sat, 24 Jan 2009 01:01:06 GMT^M
Content-Transfer-Encoding: binary^M
Content-Type: application/xop+xml; type="application/soap+xml"; charset=UTF-8^M
X-WASP-Message-ID: 101-bcH4nI/ftBJRilNZkDiIkg==^M
Content-ID: <32bb849648573a7a-1c0d723b50a78063-2392a2760337fe0f-f87db666f64901d6>^M
<?xml version="1.0" encoding="UTF-8"?>
<e:Envelope xmlns:e="" 
<ObjectResponse id="1" i:type="SingleObjectResponse">
<Object i:type="ObjectValue" classId="Domain" 
objectId="{064735FF-3160-45D3-8258-ABA3AAE8F204}" updateSequenceNumber="5" 
accessAllowed="459267"><Property i:type="UnevaluatedCollection" 
propertyId="RenditionEngineConnections" collectionType="Enum"/>
<Property i:type="UnevaluatedCollection" propertyId="ContentCacheAreas" 
collectionType="Enum"/><Property i:type="SingletonId" 
</Property><Property i:type="UnevaluatedCollection" propertyId="FixedContentDevices" 
collectionType="Enum"/><Property i:type="SingletonBinary" 
</Property><Property i:type="UnevaluatedCollection" 
propertyId="PEConnectionPoints" collectionType="Enum"/>
<Property i:type="UnevaluatedCollection" propertyId="AddOns" 
collectionType="Enum"/><Property i:type="UnevaluatedCollection" 
propertyId="ObjectStores" collectionType="Enum"/><Property 
i:type="SingletonString" propertyId="EncryptionAlgorithm">
i:type="UnevaluatedCollection" propertyId="Sites" 
collectionType="Enum"/><Property i:type="UnevaluatedCollection" 
propertyId="SubsystemConfigurations" settable="1" 
collectionType="List"/><Property i:type="SingletonString" 
propertyId="Name" settable="1"><Value>WAS_SQL</Value>
</Property><Property i:type="UnevaluatedCollection" 
propertyId="DirectoryConfigurations" settable="1" collectionType="List"/>
<Property i:type="SingletonObject" propertyId="DefaultSite" 
settable="1"><Value i:type="ObjectReference" classId="Site" 
<Property i:type="SingletonObject" propertyId="VerityDomainConfiguration">
<Value i:type="Unevaluated"/></Property><Property i:type="UnevaluatedCollection" 
propertyId="IsolatedRegions" collectionType="Enum"/><Property 
i:type="UnevaluatedCollection" propertyId="PermissionDescriptions" 
collectionType="List"/><Property i:type="UnevaluatedCollection" 
propertyId="MarkingSets" collectionType="Enum"/><Property 
i:type="SingletonObject" propertyId="ClassDescription"><Value 
i:type="ObjectReference" classId="ClassDescription" 
i:type="UnevaluatedCollection" propertyId="Permissions" settable="1" 

If you haven't seen it before, you might wonder about the isolated numbers sprinkled in with the request and response (29a, d14, and so on) in Listing 1. Those appear because you are using HTTP chunking. They're hexadecimal numbers that indicate how many bytes will come in the next chunk. Notice that in both cases, the final chunk contains 0 bytes. In Listing 1, the numbers won't add up exactly because of formatting tweaks. If you want to find out more about chunking, you can consult the HTTP 1.1 specification, RFC-2616 (see Related topics). Otherwise, you can just ignore those little numbers.

It doesn't happen in the example scenario, but you might see multiple request and response pairs in the same TCP stream. Again, it's because you are using persistent HTTP connections. There are multiple requests and responses from the HTTP point of view, but there's only one conversation from the TCP point of view. An important special case occurs when an exception is thrown from the server. An exception is transmitted back to the client as a SOAP fault, and usually the connection is closed after the SOAP fault is sent. That makes no difference above the API level, and you wouldn't even know about it if you weren't looking at network traces.

Now that you have the details of the conversation in front of you, how can you interpret them? You might already have guessed that the XML is completely specified by the Content Engine Web Services (CEWS) Web Services Definition Language (WSDL) file. For the routine types of things you will be looking for (the presence or absence of specific properties, numbers of objects, and so on), you will probably find it relatively easy to pick out the information from the XML without the need to fully understand all of the WSDL file nuances. You might find it helpful to display the XML in a more readable format, though. If you save it to a file with an xml filename extension, most Web browsers will do a good job of displaying it in a structured, readable format. The interaction shown in Figure 7 and Listing 1 is an RPC resulting from a call to Factory.Domain.fetchInstance with a null domain name and property filter. The response is a domain object that includes a collection of properties (most of which are unevaluated collections, which will be discussed in a future article about property filters).

Pros and cons of network tracing


  • Network tracing gives you an absolutely faithful rendering of which bytes are on the wire. You never have to worry about seeing an approximation or missing part of the information.
  • A network trace is non-invasive. You can choose to run a network trace at any time without a lot of finagling with the configuration of your application (but see the Cons section).
  • Performance impact is generally negligible. Even though software sniffers run on one of the computers involved, they tend to be fairly lightweight in resource consumption.


  • For the particular case of doing a network trace of the P8 Content Engine Java and .NET API interactions, you really only stand a chance of seeing anything meaningful if you use WSI transport (always the case for the .NET API) and avoid TLS/SSL encryption. In that sense, you might or might not be using a realistic configuration for your application. However, for the purposes of looking at the performance aspects that you can influence with your coding techniques, those things won't matter.
  • Likewise, due to encryption and other factors, you might not be able to get meaningful traces of network traffic going over a Virtual Private Network (VPN). That can be a considerable inconvenience for telecommuters and other remote workers.
  • As reflected in the figures above, the clutter of a network trace can be a bit overwhelming until you get used to it. It also has a pretty technical feel to it. In practice, you'll get used to it pretty quickly, and you will be able to configure your network trace tool to show you what you want.
  • If you run network tracing for long sessions, the capture files can become quite large. This tends to be an issue when using network tracing for other sorts of problems. In any case, it can be mitigated by setting up filtering rules for the capture phase.

Using API trace logging

The P8 Content Engine uses the popular open source package log4j, an Apache Software Foundation project (see Related topics), for trace logging, both on the CE server and within the Java API. This section of the article discusses how to configure and use the package.

Logging configuration

As was the case for network tracing, you can do API trace logging either on the CE server or from your API client. The choice is yours, but, again, consider that there might be a considerable amount of irrelevant material in the server logs if the CE server is shared or otherwise busy. For the .NET API, you must use server-side trace logging. This article scenario assumes you're doing client-side API logging in the Java API.

The FileNet Enterprise Manager (FEM) contains a user interface for configuring server-side logging, but a configuration file controls client-side API logging. A log4j configuration file can be in either XML format (conventionally called log4j.xml) or Java property file format (conventionally called Full details about those formats can be found at the log4j Web site (see Related topics). The XML format is more flexible and has more features, but the property file format can be slightly simpler to work with, depending on your personal preference. The IBM FileNet Content Manager product includes a sample configuration file ( that you can edit and rename to Listing 2 shows the contents of that file as it shipped with IBM FileNet Content Manager 4.5 (with only a couple of inconsequential changes to make it fit the format of this article).

Listing 2. Sample
# Root logger
log4j.rootLogger=off, FileNetNullAppender
# Appenders
#=== FileNetNullAppender

#=== FileNetConsoleAppender
log4j.appender.FileNetConsoleAppender.layout.ConversionPattern=%d %5p [%t] - %m\r\n

#=== FileNetErrorAppender
log4j.appender.FileNetErrorAppender.layout.ConversionPattern=%d %5p [%t] - %m\r\n

#=== FileNetTraceAppender
# This is the layout that the TraceLoggingConfiguration framework on the server uses.
# To use this layout , jace.jar must be present in the classpath.
# Comment out the following lines if using the FileNet TraceLayout
log4j.appender.FileNetTraceAppender.layout.ConversionPattern=%d %5p [%t] - %m\r\n

#=== FileNetErrorRollingAppender
log4j.appender.FileNetErrorRollingAppender.layout.ConversionPattern=%d %5p [%t] - %m\r\n

#=== FileNetTraceRollingAppender
# This is the layout that the TraceLoggingConfiguration framework on the server uses.
# To use this layout , jace.jar must be present in the classpath.
# Comment out the following lines if using the FileNet TraceLayout
log4j.appender.FileNetTraceRollingAppender.layout.ConversionPattern=%d %5p [%t] - %m\r\n
# Error Loggers:
# Set log level to either one of off/fatal/error/warn/info.
# Child logger's value overwrites parent logger's value.
# If a logger is not specified, it inherits its value from its parent.
# By default, error logging is set to level ERROR.
# Don't comment out the following line since it has appenders.
log4j.logger.filenet_error = error, FileNetConsoleAppender, \
                     FileNetErrorRollingAppender, FileNetTraceRollingAppender

#=== SubSystem: api
# Uncomment to set error logging level to WARN.
#log4j.logger.filenet_error.api = warn
# Trace loggers:
# Setting log level to "off" will turn off trace logging.
# Setting log level to "debug" will turn on trace logging.
# Child logger's value overwrites parent logger's value.
# If a logger is not specified, it inherits its value from its parent.
# By default, trace logging is off. 
# The general message trace logging has a hierarchy of three detail levels represented
# with hierarchical logger names:
#    ...detail.moderate.summary  -- Enables a summary level of tracing
#    ...detail.moderate          -- Enables a moderate level of tracing
#    ...detail                   -- Enables the most detailed level of tracing
# Uncomment corresponding lines to turn tracing on.  To enable trace logging
# for all subsystems and all flags, set the level of the filenet_tracing
# logger to debug.
# Here are the trace flags used for each sub system.  For message tracing, enable the line
# corresponding to the desired detail level.
#    log4j.logger.filenet_tracing.<SubSystem>.timer                   = debug
#    log4j.logger.filenet_tracing.<SubSystem>.detail.moderate.summary = debug
#    log4j.logger.filenet_tracing.<SubSystem>.detail.moderate         = debug
#    log4j.logger.filenet_tracing.<SubSystem>.detail                  = debug
# For example:
#    log4j.logger.filenet_tracing.api.detail.moderate = debug
# Don't comment out the following line since it includes an appender.
log4j.logger.filenet_tracing = off, FileNetTraceRollingAppender

#=== SubSystem: api
# Uncomment one or more lines to enable tracing.
#log4j.logger.filenet_tracing.api                          = debug
#log4j.logger.filenet_tracing.api.timer                    = debug
# Remove the comment corresponding to the desired detail level
#log4j.logger.filenet_tracing.api.detail.moderate.summary  = debug
#log4j.logger.filenet_tracing.api.detail.moderate          = debug
#log4j.logger.filenet_tracing.api.detail                   = debug

You probably guessed just from the size and amount of detail that the sample configuration file is very flexible, allowing for many logging scenarios. If you want to know more about log4j, you might find it instructive to research aspects of this configuration in the log4j documentation. This article is concerned with just a few variations, all of which are controlled by the few commented lines near the end of the file and repeated in Listing 3. API trace logging includes three verbosity levels: summary, moderate, and detail, each of which is enabled by uncommenting the appropriate line in the configuration file. This article shows examples of the summary and moderate levels for two operations: the domain fetch that you saw in the network trace examples (getObjectsRequest), and an unsuccessful attempt to create a folder in an object store that doesn't exist (executeChangesRequest). This article doesn't show an example of the detail tracing level, because the additional things logged are not particularly interesting for this discussion. It is important to realize that trace logging output is intended primarily as a diagnostic aid for troubleshooting many types of problems. The specific messages and information logged is not guaranteed to stay the same from release to release, and changes are not normally documented. The messages get tweaked quite often.

Listing 3. API tracing verbosity
# Remove the comment corresponding to the desired detail level
#log4j.logger.filenet_tracing.api.detail.moderate.summary  = debug
#log4j.logger.filenet_tracing.api.detail.moderate          = debug
#log4j.logger.filenet_tracing.api.detail                   = debug

API trace logging output appears in the file /p8_api_trace.log. If that location is not convenient, you can easily find all occurrences of that filename in the log4j configuration file and change them to something else. The configuration uses what log4j calls a rolling file appender. That means that log lines continue to accumulate in a file until the file gets to a certain size. At that point, the file is moved aside, and a new file is started. That's very handy when your logging runs for a while. But for iterative development where you are tweaking your code to tune performance, you might like to add the following line to the section where the appender is defined: log4j.appender.FileNetTraceRollingAppender.Append=false. Be sure to make a similar change to the other appender definition sections, where only the appender name needs to be adjusted. When you add that line, log4j discards the contents of the log file and restarts it for each new run of your application. Without it, it's easy to be fooled and puzzle over why the lines at the beginning of the log file don't seem to change.

log4j normally finds its configuration file by searching the Java classpath. There is also a Java property that can be set to point to a specific configuration file. Both mechanisms are easy to use if you are doing API trace logging in a standalone Java application. If you are running inside of a J2EE application server, you might have trouble getting log4j to find your configuration file (due to many variables in the classpath mechanisms of application servers). If that happens, create a JAR file with nothing in it but in the top level of the JAR file (not in a subdirectory). You could call it wjc.jar, for example, but the name is not important, as long as it doesn't collide with some other JAR name. Put wjc.jar with the other JAR files your application uses, typically someplace like WEB-INF/lib/. If the application server finds the other JAR files, it will find wjc.jar. You could use this same technique with your thick client as well, but having inside wjc.jar makes it more difficult to edit.

Sample logging output

The sample configuration file specifies a format for the logging output that includes a date/time stamp, a logging level (always DEBUG in this example scenario), and the thread name. For simplicity, those columns aren't shown in the sample logging output listings. Where long lines have been artificially broken for editorial reasons, you see a backslash at the end of the continued line and white space at the beginning of the continuation line. Where lines have been omitted for brevity, you see the gap as three dots on a line.

  • Summary:
    Listing 4. Summary API tracing
    Configuration for:Config.AutoRefreshEnabled value:null applied
      . . .
    getObjects        request batch-size=1 ObjectReferences \
      . . .
    getObjects        response elapsed=5272 batch-size=1
    executeChanges    request batch-size=1 ObjectReferences [classId=ObjectStore&\
    executeChanges    elapsed=943 exception: \
        com.filenet.api.exception.EngineRuntimeException: \
        Requested item not found. Object store MissingObjectStore not found.
  • Moderate:
    Listing 5. Moderate API tracing
    Configuration for:Config.AutoRefreshEnabled value:null applied
      . . .
    <getObjectsRequest cacheAllowed="true" correlationId="1">
      <objectReference type="GlobalIdentity" classIdentity="Domain" rid="2"/>
      . . .
    <getObjectsResponse elapsed="4224" correlationId="1">
      <value type="Domain" updateSequenceNumber="5" accessAllowed="459267">
        <objectReference type="GlobalIdentity" classIdentity="Domain" \
        identity="{064735FF-3160-45D3-8258-ABA3AAE8F204}" rid="3"/>
        <properties type="Properties">
          <property name="Permissions">
            <value type="UnevaluatedPropertyValue" propertyName="Permissions">
              <parent ref="3"/>
          <property name="FixedContentDevices">
            <value type="UnevaluatedPropertyValue" propertyName="FixedContentDevices">
              <parent ref="3"/>
          <property name="Id">
      . . .
          <property name="ObjectStores">
            <value type="UnevaluatedPropertyValue" propertyName="ObjectStores">
              <parent ref="3"/>
    <executeChangesRequest refresh="false" correlationId="0" updateSequenceNumber="null">
      <pendingAction type="Create" classId="Folder" \
      <objectReference type="GlobalIdentity" classIdentity="ObjectStore" \
        identity="MissingObjectStore" rid="3"/>
      <modifiedProperties type="Properties">
        <property name="Parent">
          <value type="ObjectByPath" classIdentity="Folder" path="/" rid="6">
            <objectStore ref="3"/>
        <property name="FolderName">
    <executeChangesResponse type="EngineRuntimeException" elapsed="845" rid="1">
    com.filenet.api.exception.EngineRuntimeException: E_OBJECT_NOT_FOUND: \
        Requested item not found. Object store MissingObjectStore not found. errorStack={
    	at com.filenet.engine.gcd.GCDHelper.getObjectStoreId(
      . . .

The summary level of API trace logging is useful if you just want to see which RPCs are being processed and how much time they take. If you want to see more details of what's in an RPC, the moderate or detail level is appropriate. RPC are always shown as a request and response pair. The XML in the requests and responses is reasonably close to that seen in the network trace samples, but it does not precisely follow the WSDL. Some approximations and simplifications are used. Because the API trace logging displays the XML in an easy-to-read format, you can readily get a sense for most of the data being carried. For performance tuning, you will mostly be concerned first with reducing the number of RPCs and then with carrying the fewest properties you can while still being able to perform necessary tasks in your application. You should find it straightforward to find both of those things in Listings 4 and 5.

Pros and cons of API trace logging


  • API trace logging can be used with both WSI and EJB transport.
  • API trace logging is not affected by the use of TLS/SSL or a VPN.
  • API trace logging output is somewhat more compact than network trace files. Also, the XML is formatted for easier human consumption.


  • API trace logging has a performance cost. For the summary trace logging level, the performance drag is minimal. For moderate and detail levels, it can be substantial. The RPC timing numbers are somewhat exaggerated for moderate and detail levels.
  • There is a minor configuration hassle factor for API trace logging. For some particularly complex application topologies, it can be vexing to get the configuration file recognized inside a J2EE application server.
  • API trace logging output is only an approximation of what is actually sent across the network. The approximation is good enough for many purposes.
  • There is very little envelope or header information in the API trace logging output. It can be a bit challenging to dig through the information, which means it's not necessarily the best tool for all troubleshooting jobs.
  • Because of its nature as a diagnostic tool, and because the output is often correlated with source code or other artifacts not usually available outside of the support and development environments, some of the API trace logging output can actually increase confusion. For example, when the API is trying to discover things about its environment, it logs many cases of things not being found. In fact, these messages are quite normal. However, it can be difficult to differentiate something like that from a more significant API trace log message.

Using ObjectDumper

When you work on an application with an interactive debugger, you can examine uncountable details about object state and the consequences of various method calls. Sometimes, though, you'd just like to have a utility that would print out a bunch of information about one or more objects. The provided sample class ObjectDumper does this (see Downloadable resources). You can use it as-is, or you can modify it as you see fit. ObjectDumper is written completely in terms of exposed APIs (for Content Manager 4.5.0, but it should work just as well for earlier releases). The code does not contain "secret stuff" or calls to undocumented methods. In some cases, the code relies on toString output for various objects, so remember the usual caveat that the format and content of those is subject to change from release to release. Part of the reason for using toString for some information is that ObjectDumper very carefully avoids doing anything that can change the state of the objects being dumped. If it did not avoid that, it would greatly diminish its value as a diagnostic aid. Because the P8 Content Engine Java and .NET APIs consist mainly of exposed interfaces and non-exposed backing classes, you will see many references to those non-exposed implementation classes. These, too, are subject to change, and you should continue to use only exposed types and methods in your own code, as was done in ObjectDumper.

The code

ObjectDumper includes a small amount of configurability, but it is also structured so that you can subclass it and override methods to change many details of how it works. There is a constructor by which you can tell it which specific OutputStream you would like to use; otherwise, it defaults to writing to System.out. You can also pass in a string tag to be used as the prefix for every line of output. That would be useful as a labeling technique if you were doing multiple object dumps. The default is an empty string.

To dump an object, call one of the generic dump methods. Those dump methods dump information about that object and all of its logical descendents. A depth counter is maintained as the tree of objects is traversed. Lines are indented two spaces for each level of depth. When you look at the source code for dump(Object, int), you see that most of it is a cascade of instanceof tests followed by calls to specific worker methods to handle the dumping of specific types of objects. When those worker methods want to dump further descendent objects, they call back into the generic dump method for additional dispatching. If you want to tweak the dumping of one of those specific types of objects, you could override those worker methods in a subclass. If ObjectDumper does not understand a particular type of object, the generic toString method is used. For example, worker method dumpEngineSet is shown in Listing 6.

Listing 6. dumpEngineSet method
 * Dumping an EngineSet is slightly tricky because we don't know anything about
 * the state of any Iterator or PageIterator being used elsewhere.  In general, 
 * we can't even say if the collection is paged or if we have all of the items
 * already.  Consequently, we just dump information about the first page in the
 * collection.  The PageMark is opaque, so we just rely on the generic toString
 * output in case it reveals anything useful. 
protected void dumpEngineSet(EngineSet engineSet, int depth) throws IOException
    PageIterator pi = engineSet.pageIterator();
    PageMark pm = pi.getPageMark();
    Object[] pageItems = pi.getCurrentPage();
    String summary = "n=" + pageItems.length + " " + pm;
    dump(pageItems, depth);

Perhaps the most complicated case in the class deals with individual Property objects. There are many special cases that the API goes to some trouble to smooth out for you. First of all, properties can represent either single values or collections of values (depending on the metadata definition for that property). In Content Engine jargon, a multi-valued property is sometimes abbreviated as MVP. A property can also be a scalar type, which means a simple type like an integer or a string, or a property can be object-valued. In Content Engine jargon, an object-valued property is sometimes abbreviated as OVP.

API Property objects also have a PropertyState. This is only a reflection of the state of the API object and really has nothing to do with the property as it exists in the repository. The main purpose of PropertyState bookkeeping is to keep track of when an API Property value is unevaluated or a reference. A reference is a property value that has within it information identifying another object, but nothing beyond identity information is currently known (in the API) about that other object. An unevaluated property value is one about which the API currently knows nothing at all beyond the fact that such a property exists. Unevaluated properties are typically MVPs. The API does not even know if the property has a non-null value for this particular instance. These concepts are a bit complicated, but they both arise due to the Content Engine server's guiding principle of doing things as efficiently as possible unless instructed otherwise. You can always fully resolve references and unevaluated property values when you need them. Part of performance tuning is making that happen at the best time. A future article will discuss this in more detail.

A Property object's value can point to another API object, and that object can in turn have properties pointing to other objects. It is not unusual for those pointed-to objects to be shared API object instances. Dumping those each time they occur would not be especially helpful. ObjectDumper internally keeps track of objects it has already seen. When it sees them again, it merely prints a distinctive reference to the earlier occurrence and does not recursively dump the descendents. This is not just a matter of convenience and tidiness. References among API objects can sometimes form cycles, so keeping track of previously seen objects also prevents infinite recursion when cycles are seen.

Sample output

Making small modifications to the HelloDocument program from the first part of this series produced the following output. The code modifications are shown in Listing 7. Add lines near the end of method createAndFileDocument to dump the UpdatingBatch instance before and after sending the updates to the Content Engine server. Because you asked for a refresh of the objects in the UpdatingBatch but did not specify a PropertyFilter for either the document or the RCR, the refresh brings back many properties defined for those objects. Most of the properties are unevaluated or references, though.

Listing 7. Modified code with dump calls
private String createAndFileDocument(Domain dom, ObjectStore os)
    // . . .
    UpdatingBatch ub=UpdatingBatch.createUpdatingBatchInstance(dom,RefreshMode.REFRESH);
    ub.add(doc, null);
    ub.add(rcr, null);
    ObjectDumper od = new ObjectDumper();
    catch (IOException e)
    System.out.println("Doing updates via UpdatingBatch");
    catch (IOException e)
    // . . .

Listing 8 shows a dump of the UpdatingBatch instance before the refresh. As usual, long lines are artificially broken with a backslash, and three dots indicate omitted portions of the dump. You can see that the objects contain relatively few properties, and they are all dirty. In other words, they have had values set by the calling application. ObjectDumper marks the names of dirty properties with an asterisk. There are also pending actions, which is appropriate for objects in an UpdatingBatch.

Listing 8. UpdatingBatch before refresh
[0118cb3a] UpdatingBatch 
  [00c67a88] ArrayList 
    [0096ad7c] BatchItemHandleImpl 
      [0057ae58] DocumentImpl classId=Document&\
        [00775121] PendingAction[2] 
          [016f70a4] Create  Class=com.filenet.api.action.Create \
  Values={classId=Document, objectId={7091F9E9-4982-43BA-88B0-9DFAA80C356D}}
          [014c5b37] Checkin  Class=com.filenet.api.action.Checkin \
  Values={checkinminorversion=false, autoclassify=false}
        [01f8acdc] PropertiesImpl n=2, dirty=true
          [011cc367] PropertyStringImpl *DocumentTitle=My Document Title
          [0160c4b0] PropertyEngineObjectListImpl *ContentElements=((collection))
            [00114025] SubListImpl 
              [013c550f] ContentTransferImpl  \
  Class=com.filenet.apiimpl.core.ContentTransferImpl \
  AccessAllowed=null RecursionLevel=0 UpdateSequenceNumber=null \
  ObjectAddress=( com.filenet.apiimpl.core.DependentIdentity@a347a9da \
  Parent=(null) Index=null PropertyName=null IsNew=true) Connection=(null) \
  SuperClasses=[null] PendingActions=null
                [01f488f1] PropertiesImpl n=3, dirty=true
                  [014a9387] PropertyStringImpl \
                  [011b86c7] PropertyContentImpl \
                  [00d647d8] PropertyStringImpl \
    [002a987d] BatchItemHandleImpl 
      [00813bc1] DynamicReferentialContainmentRelationshipImpl \
        [007a36a2] PendingAction[1] 
          [0198c6f3] Create  Class=com.filenet.api.action.Create \
  Values={defineSecurityParentage=false, autouniquecontainmentname=true, \
  classId=DynamicReferentialContainmentRelationship, \
        [012d8ecd] PropertiesImpl n=3, dirty=true
          [01fa5e5e] PropertyStringImpl *ContainmentName=I Am a Contained Document
          [00497062] PropertyEngineObjectImpl *Tail=classId=Folder&\
          [01716fa0] PropertyEngineObjectImpl *Head=classId=Document&\

Listing 9 shows a dump of the UpdatingBatch instance after the refresh. The pending actions have been cleared out. The many properties returned (66 for the document and 13 for the RCR) are not dirty, because they came from the CE server. Many properties are unevaluated or references. Listing 9 shows a couple of those for illustration, but most dump lines are shortened for brevity and clarity.

Listing 9. UpdatingBatch after refresh
[0118cb3a] UpdatingBatch 
  [0181b3d4] ArrayList 
    [0096ad7c] BatchItemHandleImpl 
      [0057ae58] DocumentImpl classId=Document&\
        [0045378f] PendingAction[0] 
        [014b9a74] PropertiesImpl n=66, dirty=false
          [00893969] PropertyEngineObjectImpl  ReleasedVersion=((UNEVALUATED))  \ \
  PropertyName=ReleasedVersion Value=classId=Document&\
  objectStore={5463CB9C-C05C-4ED6-8DB2-EA931DC026F8}&propertyId=ReleasedVersion \
  IsDirty=false Access=1 State=(UNEVALUATED) Connection=( \
  Class=com.filenet.apiimpl.core.ConnectionImpl \
  URI=http://MyCEServer:9080/wsi/FNCEWS40MTOM/ Parameters={})
          [014b081b] PropertyEngineObjectImpl  VersionSeries=((REFERENCE))  \ \
  PropertyName=VersionSeries Value=classId=VersionSeries&\
  objectStore={5463CB9C-C05C-4ED6-8DB2-EA931DC026F8} \
  IsDirty=false Access=1 State=(REFERENCE) Connection=( \
  Class=com.filenet.apiimpl.core.ConnectionImpl \
  URI=http://MyCEServer:9080/wsi/FNCEWS40MTOM/ Parameters={})
          [00e8606c] PropertyEngineObjectListImpl  Permissions=((UNEVALUATED))  . . .
          [00292cb2] PropertyDateTimeImpl  DateLastModified=Sun Jan 25 21:13:56 PST 2009
          [0135605a] PropertyStringImpl  EntryTemplateLaunchedWorkflowNumber=null
          [0148e798] PropertyBooleanImpl  IsCurrentVersion=true
          [015ccfb1] PropertyEngineObjectImpl  OwnerDocument=null
          [004788d5] PropertyEngineObjectImpl  DocumentLifecyclePolicy=null
          [00688954] PropertyStringImpl  LockOwner=null
          [0110278e] PropertyEngineObjectImpl  SecurityPolicy=null
          [0194e776] PropertyStringImpl  Name=My Document Title
          [00e80740] PropertyEngineObjectImpl  StorageArea=((REFERENCE))  . . .
          [00f2225f] PropertyEngineObjectSetImpl  Annotations=((UNEVALUATED))  . . .
          [006de609] PropertyEngineObjectSetImpl  \
  ParentRelationships=((UNEVALUATED))  . . .
          [01f217ec] PropertyStringImpl  DocumentTitle=My Document Title
          [0100aff5] PropertyBinaryImpl  PublicationInfo=null
          [00200db9] PropertyEngineObjectImpl  SecurityParent=((UNEVALUATED))  . . .
          [015dc37d] PropertyEngineObjectImpl  StoragePolicy=((REFERENCE))  . . .
          [00e7e8eb] PropertyEngineObjectImpl  PublishingSubsidiaryFolder=null
          [016cbd97] PropertyStringImpl  CurrentState=null
          [001321f5] PropertyInteger32Impl  ClassificationStatus=0
          [001a6518] PropertyEngineObjectImpl  ClassDescription=((REFERENCE))  . . .
          [013e4a5a] PropertyEngineObjectSetImpl  \
  WorkflowSubscriptions=((UNEVALUATED))  . . .
          [019050a0] PropertyStringImpl  StorageLocation=null
          [019d3b3a] PropertyFloat64Impl  ContentSize=110.0
          [019b808a] PropertyDateTimeImpl  DateContentLastAccessed=null
          [00140fee] PropertyEngineObjectSetImpl  ParentDocuments=((UNEVALUATED))  . . .
          [0082254d] PropertyDateTimeImpl  DateCreated=Sun Jan 25 21:13:56 PST 2009
          [005f1ae9] PropertyInteger32Impl  ReservationType=32
          [01dfc8a0] PropertyStringImpl  EntryTemplateObjectStoreName=null
          [00ec898a] PropertyEngineObjectSetImpl  AuditedEvents=((UNEVALUATED))  . . .
          [015e0c2b] PropertyInteger32Impl  VersionStatus=1
          [0171194d] PropertyBooleanImpl  IsInExceptionState=false
          [0034151f] PropertyEngineObjectListImpl  ActiveMarkings=((UNEVALUATED))  . . .
          [00114b17] PropertyStringImpl  MimeType=application/octet-stream
          [0159054d] PropertyStringImpl  LastModifier=user1234
          [016b321b] PropertyEngineObjectListImpl  ContentElements=((UNEVALUATED))  . . .
          [0098f192] PropertyEngineObjectImpl  Reservation=((UNEVALUATED))  . . .
          [017748d3] PropertyStringImpl  Creator=user1234
          [004e2f0a] PropertyEngineObjectSetImpl  FoldersFiledIn=((UNEVALUATED))  . . .
          [00c2cf83] PropertyBooleanImpl  IsFrozenVersion=false
          [01c5af2e] PropertyStringImpl  ComponentBindingLabel=null
          [01702c48] PropertyInteger32Impl  LockTimeout=null
          [016b6c55] PropertyInteger32Impl  MajorVersionNumber=1
          [01954f89] PropertyIdImpl  Id={7091F9E9-4982-43BA-88B0-9DFAA80C356D}
          [0198e8b4] PropertyEngineObjectSetImpl  \
  DependentDocuments=((UNEVALUATED))  . . .
          [004b0bbb] PropertyStringListImpl  ContentElementsPresent=((collection))
            [00ef4504] StringListImpl 
              [002f1e75] String application/octet-stream
          [01c5ddd3] PropertyEngineObjectImpl  This=((REFERENCE))  . . .
          [01f47ae8] PropertyInteger32Impl  MinorVersionNumber=0
          [01b11b79] PropertyEngineObjectImpl  SourceDocument=null
          [0082d603] PropertyDateTimeImpl  ContentRetentionDate=null
          [01b09282] PropertyBooleanImpl  IsReserved=false
          [0162ba99] PropertyIdImpl  LockToken=null
          [00c8c7d6] PropertyIdImpl  EntryTemplateId=null
          [01b7b407] PropertyInteger32Impl  CompoundDocumentState=0
          [018c5e67] PropertyBooleanImpl  IsVersioningEnabled=true
          [0089c116] PropertyBooleanImpl  IgnoreRedirect=null
          [01e3bbd7] PropertyEngineObjectSetImpl  Versions=((UNEVALUATED))  . . .
          [00a86d12] PropertyEngineObjectImpl  SecurityFolder=null
          [0190d8e1] PropertyStringImpl
          [008eae04] PropertyEngineObjectSetImpl  Containers=((UNEVALUATED))  . . .
          [0135ae7e] PropertyEngineObjectSetImpl  \
  DestinationDocuments=((UNEVALUATED))  . . .
          [009abce9] PropertyEngineObjectImpl  CurrentVersion=((UNEVALUATED))  . . .
          [0095215b] PropertyIdImpl  IndexationId=null
          [00c10de0] PropertyEngineObjectSetImpl  \
  ChildRelationships=((UNEVALUATED))  . . .
          [0056fc16] PropertyEngineObjectSetImpl  ChildDocuments=((UNEVALUATED))  . . .
    [002a987d] BatchItemHandleImpl 
      [00813bc1] DynamicReferentialContainmentRelationshipImpl \
        [018f9b75] PendingAction[0] 
        [01c85444] PropertiesImpl n=13, dirty=false
          [01144ba2] PropertyEngineObjectImpl  VersionSeries=((REFERENCE))  . . .
          [008de972] PropertyStringImpl  Creator=user1234
          [00d964af] PropertyDateTimeImpl  DateLastModified=Sun Jan 25 21:13:56 PST 2009
          [006127da] PropertyStringImpl  ContainmentName=I Am a Contained Document
          [007f8062] PropertyEngineObjectImpl  ClassDescription=((REFERENCE))  . . .
          [01f8d077] PropertyEngineObjectImpl  Tail=((REFERENCE))  . . .
          [00ee6ad6] PropertyIdImpl  Id={F335B56F-FAEA-42D1-9946-E08565112767}
          [00a826da] PropertyEngineObjectImpl  This=((REFERENCE))  . . .
          [015fc672] PropertyEngineObjectImpl  Head=((REFERENCE))  . . .
          [0178aae1] PropertyDateTimeImpl  DateCreated=Sun Jan 25 21:13:56 PST 2009
          [011abd68] PropertyStringImpl  Name=I Am a Contained Document
          [008932e8] PropertyEngineObjectSetImpl  AuditedEvents=((UNEVALUATED))  . . .
          [00c08593] PropertyStringImpl  LastModifier=user1234

Pros and cons of ObjectDumper


  • You can use ObjectDumper to view the state of objects at arbitrary points in your application. You are not limited to instrumenting RPCs.
  • You can customize it as you see fit, both for the information dumped and for the format of that information. You can do that using subclassing or by directly modifying the ObjectDumper source code.
  • Because you have the source code, you have complete control over what it does. There are no new tools or configuration mechanisms to learn except any that you yourself might invent.


  • You must generally modify the source code of the instrumented application to use ObjectDumper. It's not very useful for instrumenting components for which source code is not available.
  • When you add dump calls to a component, you have to rebuild those components. So, even if you have source code (normally the case for the sorts of things for which you ordinarily use ObjectDumper), there can be a minor hassle factor in rebuilding and redeploying your application.


This article showed you three separate techniques for monitoring data passed in RPCs and the state of P8 Content Engine Java API objects in general. Although every detail of these techniques is not discussed, the article should have adequately shown you the flavor of each so that you can explore further on your own. Each technique has its strengths and weaknesses, but you should have some idea of which you'd like to use and when. Future articles will refer back to these techniques, particularly when discussing performance tuning.

Downloadable resources

Related topics


Sign in or register to add and subscribe to comments.

Zone=Information Management
ArticleTitle=Writing great code with the IBM FileNet P8 APIs, Part 2: Spying on your handiwork