Configuring Server Diagnostics

Although you can set environment variables to enable tracing of activities for all user sessions, it is not recommended to turn tracing on via .ini settings, except in special cases where it is necessary to diagnose startup activities with the VERBOSE, MQL, and/or SQL settings.

And since these types of low-level tracing slow the system down, they should be avoided unless absolutely necessary. None of the other trace types come into play at startup.

See Also
Server Diagnostics
Configuring Server Diagnostics
Studio Customization Toolkit Origin Trace Facility

For most diagnostic purposes, turning tracing on after startup has the following benefits:

  • You have complete control over the order of trace starting, which matters because the first tracing started defines the destination (although you can start multiple traces with a single command).
  • It allows you to limit tracing to be on only when needed—The actions that occur during startup can produce a lot of irrelevant tracing messages, especially for VERBOSE and SQL.
  • Since the server must be taken down and restarted to initiate the trace when using environment variables, it is less invasive to your users.

A preferable method for turning tracing on/off is to start your executable with no tracing defined, setting only MX_TRACE_FILE_PATH to define the directory into which any tracing files will be written. When you get to an operation that you need to diagnose via tracing, check for the tracing types enabled using MQL print trace, and adjust accordingly using trace off and trace type commands. Note that these commands can be issued in a server setting via the administration page emxRunMql.jsp (My Desk > Admin Tools > Run MQL). For 3DSpace users. you can add a wizard to your toolbar that lets you type an MQL/Tcl command and have it processed. Refer to the MQL Concepts for more information.

Each environment variable is described in Environment Variables for Server Diagnostics.

Memory tracing variables are described in Memory Management.

Important: When enabling tracing in the .ini files you must be aware of the following:
  • When enabling tracing for the Live Collaboration server, these variables should be set to a filename because there is no means of viewing stdout (or stderr), since 3DSpace Service activation in java2 runs without a console.
  • Particular care should be taken in the use of SQL and VERBOSE tracing. Both are low level and liable to generate a large amount of output data, which will affect performance.
  • If you turn tracing on with an .ini setting, the tracing will begin only when you restart.

Trace Output

All trace entries have a standard prefix consisting of a fixed-format timestamp (without the date), the tracing TYPE, the thread ID, and a trace message for each line of output. The prefix will always be 23 characters long, followed by a space, as follows:

21:51:39.795 TYPE t@284 <tracing output>

So, the trace message always begins in column 25. For example:

02:06:59.339 MQL  t@354 Start MQLCommand: exec prog printContext

Output columns are as follows:

  • Column 1 through 12 contains the timestamp: hour (0-24), minute, second, millisecond
  • Column 14 through17 contains the trace type: always 4 characters (padded or truncated, such as: "SQL ", "MQL ", "MYTR", "MEMO" (see table below).
  • Column 19 through 23 contains the thread ID: t@ followed by 3 digits
  • Column 25 - tracing message generated by 3DSpace kernel, by the MQL trace type text command, or by Studio Customization Toolkit calls to printTrace().

The output provided for the various traces is summarized in the table below.

Detailed examples can be found in the MQL Concepts.

Trace Type Output
SQL Select, update, insert, delete, rollback and commit commands issued to Oracle. All output is preceded by thread ID.
MEMO Refer to "Error and Log Messages" for a description of the output of Memory Manager.
MQL Program name and arguments (Tcl or JPO), MQL commands issued by those programs (Tcl MQL command or JPO mqlCommand interface), total time for program execution, and execution time for each MQL command. All output is preceded by thread ID. Session ID will also be printed for Program names and commands executed via the mqlCommand interface*.

For deferred programs, "(deferred)" is appended to the MQL output issued at the time of initial invocation. When the deferred execution occurs, the output is marked with start and end markers as well as "(deferred execution)".
* The session ID is a long string, which would make for hard-to-read output if we were to prepend every command with it. The thread ID is usually sufficient. Therefore, we output session id only with certain server calls, and provide the corresponding thread id, which will identify subsequent trace messages associated to that thread, hence that session.
SMTP Open, send requests/responses to/from SMTP server
LDAP Connect and informational requests/responses to/from LDAP server. All output is preceded by thread ID
JPO JPO compilation or invocation
Trigger Event and type (check, override, action) for each trigger fired, and the name of the program that is run. Object type, name, revision, and id, or Relationship name and id are also provided when available.
Workflow Processing data for workflow events.
<other> Whatever the implementor has specified with trace type TYPE text STRING commands or corresponding Studio Customization Toolkit calls.

When using verbose tracing (in MQL or any other kind of tracing) elapsed time of a dispatch is also included in the log. For example: 

since 19:47:14.004, 5.728 secs (1.102 direct 4.626 nested)

where,

since 19:47:14.004

following 'since' is the timestamp from the record starting this dispatch or program execution.

5.728 secs

shows the elapsed seconds since this dispatch or program execution began.

1.102 direct

is the time spent in service dispatch or program execution directly.

4.626 nested

is the time spent in nested calls to other dispatches or program executions.
Note: Service dispatches are reported in VERBOSE trace logs and program execution is reported in MQL trace logs.