About the Coretime Log Analysis Tool

Coretime output may be used to:

Reveal Studio Customization Toolkit calls, MQL commands, and/or programs which don't complete.
Expose transactions which are started and are not explicitly committed or aborted.
Detect operations suspect of causing performance problems (such as long running program objects).

Coretime is installed in the ENOVIA_INSTALL/bin/ARCH directory and can be run from a command line as follows:

coretime [-method] [-time] [-noclones] [-session SESSIONID] ENOVIA.LOG

where:

-method orders the output alphabetically by Studio Customization Toolkit method.
-time orders the output by longest running to shortest running. Calls that don't complete (-1 milliseconds) are listed at the end of the output.
-session SESSIONID extracts all log entries for the specified session and is only valid for logs generated with MX_VERBOSE_PARAM_TRACE. Include -noclones to omit clones of the specified session. Clones are 3DSpace sessions generated by calls to com.matrixone.servlet.FrameworkServlet.getFrameContext() by the JSP/Web server, and are identified by the string ":mx."
ENOVIA.LOG is the name of the log file to analyze, optionally including the path. If no path is specified, the file is assumed to be in the current directory.

Coretime parses an ENOVIA.LOG file and calculates the milliseconds spent in each recognizable module. The recognizable modules are:

dispatches to the kernel (verbose tracing entries containing "dispatch for")
user programs (MQL tracing entries containing "Start Program:")
user calls to MQLCommand (MQL tracing entries containing "Start MQLCommand:")
user checkpoints generated via MQL trace commands or Studio Customization Toolkit printTrace method calls whose text begins with "Start checkpoint:" and which have a matching trace message whose text begins with "End checkpoint:" Note that these message delimiters are case sensitive, and may be used by implementors wherever they choose.

In the case of Program, MQLCommand and Checkpoint, the message from the start marker will be included in the timing summary.

Coretime is a tool that aids in the analysis of verbose and MQL traces, although it is not required, since these traces are human readable text, as documented here as well as in the Programming Guide, "Program Object Coding Strategies" chapter.

Sample Coretime Output

13:07:45.590    t@20:     4101 milliseconds: ADK:   
invokeClass.bosInterface

13:07:50.701    t@26:       10 milliseconds: MQL:   print policy "Part 
Quality Plan" select property[state_Active].value dump;

13:07:51.081    t@20:       10 milliseconds: ADK:   
invokeClass.bosInterface

13:07:51.081    t@20:         9 milliseconds: PGM:    emxMailUtil

The table below explains the fields in the output.


Field	Value (example)	Meaning
1: Timestamp	13:07:45.590	Start time of the operation
2: Thread	t@20	Thread ID on which the operation executed.
3: Time	10 milliseconds -1 milliseconds -2 milliseconds	Elapsed time between "stateless dispatch for" and "dispatch complete" or "dispatch exception". If coretime detects a trace entry did not complete, its time will be reported as "-1 milliseconds." This is the time taken to start the transaction, but not complete it. A time of "-2 millliseconds" indicates a "long runner". Refer to "Memory Use" for details.
4: Output provided by	Studio Customization Toolkit MQL CHKPT PGM	Verbose trace output MQL trace output implementor checkpoint Launch of program via Studio Customization Toolkit or MQL
5: method, command, or program	invokeClass.bosInterface	Operation is a result of this method, command or program. Studio Customization Toolkit calls that end in exceptions include: EXCEPTION! For transactions that successfully complete or abort are followed by a transaction lifetime calculation, in milliseconds.

When coretime reports that a call did not complete (that is, elapsed time of -1 milliseconds:), you can then use the original trace file to troubleshoot. For example, for the following coretime output:

14:03:08.116    t@17:         -1 milliseconds:  
expandSelect.bosBusinessObject

Search original trace log for the timestamp (14:03:08.116), and then follow activity on that thread to find the expandSelect call with it's parameters:

14:03:08.116 VERB t@017 stateless dispatch for expandSelect.bosBusinessObject

14:03:08.116 VERB t@017 allocate context for session DwHyGBRDflOxOsO2HcYdA5Epv2kunV6ObF0UBzxc2B0uD4pDqh8T!167699317!1127221
234180:mx112722498309124663705:(__emxCustomExpand.java:1010)

14:03:08.126 VERB t@017   input params: id=53367.54932.31998.58101, relPattern=Approving Organization, typePattern=*, objectSelect 
length=1, relSelect length=0,getTo=0, getFrom=1, recurse=1, objWhereClause=, relWhere=(attribute[Organization Type] == 
"Franchise")

The session id indicates the expandSelect originated from the JSP page emxCustomExpand.jsp. The expandSelect was being executed on the business object with ID 53367.54932.31998.58101. You should look at this object to determine what information you are really looking for and then improve the expandSelect by applying additional criteria to the parameters, such as including a typePattern.

For transactions that do not have explicit commit or abort calls, Coretime prepends a comment stating this. For example:

####### following start.bosContext has no commit or abort 
####### session 
KqRZs0FZy66mv9fk5RRE9n3:mx11528214996531004958:(_testengchgECRDiscoverObjects.java:966)
19:59:31.494    t@265:        0 milliseconds: ADK:  start.bosContext

The session ID tells us that the missing transaction commit/abort is from JSP page testengchgECRDiscoverObjects.jsp.