Where can I find a description of the request-level log

[reimer_pods]

Today we were trying to find the source of a problem at a client's site. Activating request-logging for some time gave us at least some hints. But we had some trouble interpreting the contents of the request log.

Can anyone point me to a description of the request log contents?

<snippet>
=,<,96,OPEN,131109
+10,>,96,OPEN,131110
+90,<,96,CLOSE,131110
=,I,96,0,1,0,NOSCROLL*+READONLY+HOLD
=,>,96,CLOSE
=,<,96,DROP_STMT,131109
=,>,96,DROP_STMT
=,<,96,PREPARE,SELECT cast(NULL AS CHAR(128)) AS TABLE_CAT,SYSUSERPERMS.user_name AS     TABLE_SCHEM,SYSTABLE.table_name AS TABLE_NAME,COLUMN_NAME,cast((select count(*) from SYS.SYSCOLUMN other where table_id = SYSTABLE.table_id and column_id <= SYSCOLUMN.column_id and pkey = 'Y') AS smallint) AS KEY_SEQ,SYSTABLE.table_name AS PK_NAME FROM SYS.SYSCOLUMN JOIN SYS.SYSTABLE JOIN SYS.SYSUSERPERMS WHERE user_name = 'sirius' AND table_name = 'ARTIKEL' AND pkey = 'Y' ORDER BY 1,2,3,5
+1,>,96,PREPARE,131111
+18,<,96,EXEC,131111
=,W,96,111,Anweisung kann nicht ausgeführt werden
=,>,96,EXEC
=,<,96,OPEN,131111
+3,>,96,OPEN,131112
=,<,96,CLOSE,131112
=,I,96,0,1,0,NOSCROLL*+READONLY+HOLD
+1,>,96,CLOSE
=,<,96,DROP_STMT,131111
=,>,96,DROP_STMT
=,<,96,CLOSE,65570
=,I,96,0,546,0,NOSCROLL*+READONLY+HOLD
=,>,96,CLOSE
+8,<,96,DROP_STMT,65569
=,>,96,DROP_STMT
=,<,96,PREPARE,select connection_property('TransactionStartTime')
=,>,96,PREPARE,65577
+1,<,96,EXEC,65577
=,W,96,111,Anweisung kann nicht ausgeführt werden
=,>,96,EXEC
=,<,96,OPEN,65577
</snippet>

[MarkCulp]

Before I answer your question directly, I will mention that there are a number of tools available that you can use to analyze your request log file:

• tracetime.pl - located in your SA install samples directory - in SA 12 it is in samples/sqlanywhere/performancetracetime/tracetime.pl

• sa_get_request_profile - a procedure that will determine execution times of similar statements

• sa_get_request_times - a procedure that will determine execution times of each statement

As for documentation on the format, there appears to be no good source (and we need to do something about this!). If you know PERL you can read through the tracetime.pl script and figure out the details, but here are the general rules:

Each line is a comma delimited set of fields:

• timestamp - this will be one of

  • an absolute time in "MMDD HHMMSS.sss" format, or
  • '=' if the time is exactly the same as the previous line
  • +n to indicate 'n' milliseconds after the previous line

• logging event type - one of:

  • '<' - start of a new request (sent to the server)
  • '>' - end of request
  • '>.' - connection dropped
  • 'C' - new connection
  • 'H' - hostvar information
  • 'E' - error
  • 'W' - warning
  • 'P' - plan
  • 'I' - info
  • 'X' - extra data/info
  • '[' - procedure call begin
  • ']' - procedure call end

• connection id

• request type (if a start/end of a request) or procedure name (if a proc call)

• various other details depending on the log event type and request type - e.g. SQL text, statement id, or cursor id

[reimer_pods]

@Mark: Thanks for your helpfull explanation. We would have liked to see the SQL statements with their host variables in chronological order, but for some unknown reason the SQL was missing. However, I was not able to reproduce that on my PC.