How to interpret a custom server trace

ID  ELAPSED_SEC    DELTA_MSEC   APPL   SYSCALL KERNEL INTERRUPT
456 100.472410880  606.073856  CA_LIB: [46988] CS_1 ENTRY  CA_Get_Element_Count ext_voice_sp 0x...
456 100.472451584    0.040704  CA_LIB: [46988] CS_1 PARMS  CA_Get_Element_Count data 0x20008858
                               CA_LIB: [46988] CS_1 PARMS  CA_Get_Element_Count length 6560
                               CA_LIB: [46988] CS_1 PARMS  CA_Get_Element_Count sampling_rate 8000 ...
       CA_LIB: [46988] CS_1 PARMS  CA_Get_Element_Count FORMAT_ULAW ORDE...
456 100.472532992    0.081408  CA_LIB: [46988] CS_1 RETURN CA_Get_Element_Count RC 5 CA_NO_ERROR...
456 100.472701440    0.168448  CA_LIB: [46988] CS_1 ENTRY  CA_Import_Voice      int_sp 0x2FF222A...
456 100.472739584    0.038144  CA_LIB: [46988] CS_1 PARMS  CA_Import_Voice      int_sp data 0x2...
                               CA_LIB: [46988] CS_1 PARMS  CA_Import_Voice      total_elements 5
                               CA_LIB: [46988] CS_1 PARMS  CA_Import_Voice      UNCOMPRESSED_VOI...
                               CA_LIB: [46988] CS_1 PARMS  CA_Import_Voice      ext_sp data 0x2...
                               CA_LIB: [46988] CS_1 PARMS  CA_Import_Voice      length 6560
                               CA_LIB: [46988] CS_1 PARMS  CA_Import_Voice      sampling_rate 8000 ...
                               CA_LIB: [46988] CS_1 PARMS  CA_Import_Voice      FORMAT_ULAW ORDE...
456 100.504947584    0.030208  CA_LIB: [46988] CS_1 RETURN CA_Import_Voice      RC 5  CA_NO_ERRO...

 The trace in Figure 1 was formatted using the Blueworx Voice Response print_trace command. The basic format of the trace is the same as a trace formatted using the AIX trcrpt command.

• The first column (ID) is the trace event ID.
  • Trace event IDs are explained in more detail in the section named Defining Trace Events of AIX: Version 4: Writing a Device Driver.
  • Blueworx Voice Response uses seven trace event IDs depending on what is being traced. See the section on Blueworx Voice Response usage of AIX trace event IDs in the Blueworx Voice Response for AIX: Problem Determination information.
  • This custom server trace uses trace event ID 0x456. When you know the trace event ID used in your trace, you can use AIX selective trace. For information on AIX tracing, see AIX: Problem Solving Guide and Reference.
• The second column (ELAPSED_SEC) is the elapsed time (in seconds) since the trace started.
• The third column (DELTA_MSEC) is the number of milliseconds since the previous trace event.
• The fourth column (APPL) is set to CA_LIB by Blueworx Voice Response to identify a line in the formatted trace report that is part of custom server tracing. This allows you to use the AIX command grep to filter just custom server trace information from a formatted trace report.
• The fifth column contains the ID of the process making the custom server library call. If you know the process ID of the custom server that you want to debug, you can use grep to further filter the trace report.
  Note: The titles of the fifth and subsequent columns SYSCALL, KERNEL and INTERRUPT don't apply to Blueworx Voice Response custom server traces and should be ignored.
• The sixth column contains the name of the custom server (in this example, the name is CS_1). While the custom server is starting up or shutting down, its name is not available, so the trace shows ?????? instead of the name.
• The seventh column describes the trace entry. It starts with one of the following keywords:

  ENTRY

  Entry to a custom server library call from a custom server. This includes the name of the custom server library call (for example CA_Get_Element_Count()), and all scalar parameters. If more than one line is needed to format scalar parameters, the second and subsequent lines are prefixed “Entry”.

  Scalar parameters include integer, and short parameters, plus the addresses of any structures passed to the custom server library. These are traced first so that if for example an invalid pointer is passed to the custom server library, the trace will contain the pointer in error before it is dereferenced and causes a core dump.

  In the example you can see the address of the EXT_VOICE_ST which is being passed to CA_Get_Element_Count(), and later the addresses of the INT_VOICE_ST and EXT_VOICE_ST which are being passed to CA_Import_Voice(). You can already see that the same EXT_VOICE_ST is being passed to both CA_Get_Element_Count() and CA_Import_Voice(). If the addresses were different this might indicate that the custom server was passing the wrong parameter to one of the subroutines.

  PARMS

  Parameters passed to a custom server library call from a custom server.

  The PARMS section includes the values of non-scalar input parameters on entry to the custom server library. Structures are decoded member by member.

  If more than one line is required to decode the parameters for a custom server library call, second and subsequent lines omit the trace event ID, elapsed seconds, and delta milliseconds fields. The string CA_LIB: which identifies this as part of a custom server library trace, the process id, the string PARMS and the custom server library function name are still present.

  RETURN

  Return from a custom server library call to the custom server. This includes the name of the custom server library call (CA_Get_Element_Count()) the return value of the function (RC 5), and the value of the globals CA_errno and errno on exit from the custom server library. CA_errno (CA_NO_ERROR in the example) is decoded into one of the values of the CA_ERRNO_ENUM enumeration which is defined in CA_header.h.

  Note: The value of errno is not cleared on entry to the custom server library. Its value may therefore be non-zero across a series of custom server library calls.