Reading and decoding instrumentation files for WebSphere Lombardi Edition (WLE), and IBM Business Process Manager (BPM) products

Answer

Instrumentation .dat files are compacted binary files that can be read only after they are decoded. This level of tracing is used to debug performance-related issues.

Instrumentation log files show every command that is issued on the Process Server and how long each command takes to run. Analysis should be completed in conjunction with thread dumps and log files. Thread dumps show the threads and the full Java™ stacks of the running components. Log files indicate any errors that might occur during this time. Instrumentation logging helps show where a process is taking time. With the three types of information, you can cross-reference for performance. For example, you have a coach and it takes 20 seconds to run. This coach has multiple activities including reading from an external data source, calling a web service, processing an uploaded file, verifying form data, and sending the data to the Process Server. Collecting instrumentation log files during this time shows each step and how long, in milliseconds, each step takes to run. Thread dumps tell you which thread is running and the full stack of the code path.
 
Note: Instrumentation logging is an expensive operation. You will see a performance decrease when you run logging operations. Thus, run logging operations during an analysis period only. These log files are very large. A small five minute sample might yield a 5 MB file, which expands to 25 MB. The more activity you have, the larger the file. 
 
Notes on cluster configurations 
This process only collects data for the node on which you are running the instrumentation data. If you can turn off other nodes, usually just the Event Manager, you can shift load to one server to do testing. Or, you can access one server directly and bypass the load balancer to perform the tests. The more isolated the environment, the better.
 
How do I start instrumentation logging?
Complete the following steps: 

1. Log into the Process Admin Console as a user in the tw_admins group, such as tw_admin or admin.
   
   For example:
   http://server_name:port_number/ProcessAdmin 
   
   Note: The SECJ0305I might display if this step is run without the base internal users. The user also needs to be a member of the 'AUDITOR' and 'OPERATOR' roles in the WebSphere Application Server configuration. By default, the tw_admin and the specified administrator at install have these rights, for example, admin or bpmadmin.
   
   
2. Under Monitoring, click Instrumentation.   
   
   
3. Click Start Logging to collect data. Note where it stores the file. For example, in IBM Business Process Manager Version 7.5, the file might be stored in the following directory:
   C:\IBM\BPM\v7.5\profiles\ProcCtr01\logs\inst001.dat 
   
   
4. Click Stop Logging. 
   
   
5. Retrieve the file for processing. 

 
How do I to decode the instrumentation .dat files? 
Use the following command to extract the data: 
java -Xmx1024M -cp svrcoreclnt.jar  com.lombardisoftware.instrumentation.log.tools.NonXMLDump inst001.dat >  inst001.txt 
 
Notes: 

• The svrcoreclnt.jar file needs to be in a path that Java can execute. You can copy this file to a separate directory to your desktop to run. The location of  the Java archive (JAR) file is: [install_dir]\Lombardi\lib 
  
  
• 1024MB heap will be sufficient for almost all cases.
  
  
• inst001.dat is the instrumentation file.
  
  
• inst001.txt is a decoded file in the plain text format. 

Reading the decoded file 
The decoded file is a plain text file. Most text editors do not allow you to edit very large files (greater than 25MB). Using a command-line tool, like grep, enables you to quickly search through the entire file. Grep is available in most Linux distributions and there is a free client for Windows as well. 


The instrumentation log files are important because they tell you exactly how long it took for something to run. The following command finds all threads that took longer than 1000 milliseconds (1 second) to complete, which are the threads that you should examine first.
 
grep -E "(THREAD|period [0-9]{4,}ms)" inst001.txt 

Example Sample output and recommendations: 
>> THREAD Thread-47 << 
>> THREAD WebContainer : 2 << 
03:17:10.356 period 1156ms 'Resume Workflow Engine' { 
03:17:10.418    period 1031ms 'Do Job'  
Worker=com.lombardisoftware.component.javaconnector.worker.JavaConnectorWorker { 
03:17:10.418       period 1031ms 'Java Execution' { 
>> THREAD WebContainer : 13 << 
>> THREAD WebContainer : 16 << 

The time is nested. 1156ms 'Resume Workflow Engine' is running a coach and it took 1.2 seconds. Within here, you see that it took 1.0 seconds to execute Java. After this function, there might be another function that took 400 milliseconds.


 'Heartbeat Get Data'
In a process server, this is the metadata that is sent back to a process center. Increase the value of the <repository-server-interval> value in a 100custom.xml file. This value is in seconds and it is the time an online process server reports back to a process center on metadata for instances and tasks. Set this value to 300 or greater (5 minutes).

Sample override XML:
<properties>
    <server>
       <repository-server-interval merge="mergeReplace">300</repository-server-interval>
    </server>
</properties>


'EJB Calls'Method=
SarchAPIFacadeCore.findSearchableBusinessDataAliasesForProcessIn  
This method finds variables that are exposed as searchable. There are multiple solutions:

• Delete closed instances to reduce overhead of searching
• Limit the number of exposed variables for business search - See Section 2.2.2 "Use searchable business variables judiciously" in the Business Process Management Deployment Guide Using IBM Business Process Manager V8.5 IBM Redbooks publication.
• Enable the accelerator tables (pivot tables). For more information, see Process search optimization in the product documentation. This function is available in Version 8.0.1 and later and on 7.5.1.x with APAR JR42012
• Regularly run database indexes and runstats on the LSW_TASK and LSW_BPD_INSTANCE_VARIABLES tables.

'Snapshot read access' id=Snapshot.<id>

• Delete snapshots from your environment that are no longer needed. Apply all required fixes for your version before deleting snapshots.
• For Process Center, there is a setting to delete unnamed snapshots. See the <unnamed-snapshot-cleanup-config> section in the Deleting unnamed snapshots from a Process Center server, automated method topic within the product documentation.
• See the documentation on deleting snapshots.
• Regularly tune database and run stats, LSW_SNAPSHOT and LSW_PO_VERIONS, which affect the reading of snapshots.

AuthorizationAPIFacadeCore.canExecuteTasksActions
This issue is resolved with JR44341

'Load Execution Context'
This is reading task execution data. These are the variables saved in the application design.

• Reduce number and size of variables in tasks and business process definitions (BPD) as much a possible. This approach will decrease the amount of data that has to be de-serialized.
• Keep database indexes and run stats current on LSW_TASK* tables
• Improve database performance for the BLOB colums, such as LSW_TASK_EXECUTION_CONTEXT.execution_context

'Tasks Executed' Task Type=ExecuteSystemLaneActivityTask {

• Review settings of the event manager. <bpd-queue-capacity> and related threads might need to be increased.
• Examine the system lane activities. Some of these might be calling outside systems or do heavy processing of data. This activity might be expected based on your application design.

com.lombardisoftware.component.javaconnector.worker.JavaConnecor
This code is calling a function in a managed asset using the Java connector from the system data toolkit. The methods with this Java™ archive (JAR) should be reviewed for performance.


EJB Calls Method=PersistenceServicesCore.findAll
period xxxxms 'findAll' type=Contribution
period xxxxms Load delta snapshot'
This issue is resolved with APAR JR44583



Example Grep commands
grep.exe -E "(THREAD|period [0-9]{4,}ms)" inst001.txt    - This command finds all calls that are greater than 1 second.

grep.exe"  %1 %2 > %2FindItem.txt - These commands find %1 in file %2 and stores the result in a new text file. - grep.exe "1031ms 'Java Execution'" inst001.txt

grep.exe" -A %1 %2 %3 > %3FindXLines.txt - These commands find a block text after a specific search string and stores it in a text file - grep.exe -A "1031ms 'Java Execution' 300 inst001.txt