Logging server requests

For isolating some types of problems, especially problems with queries, logging server requests is helpful. You can enable request-level logging in two ways:

Server requests are logged in the server log file *.srvlog. The -zr server startup option enables request-level logging of operations and sets the type of requests to log (ALL, NONE, or SQL). The -zo option redirects request-level logging information to a file separate from the regular log file and -zs limits the size of this file.

You can enable and disable request-level logging without restarting the Sybase IQ server using the sa_server_option stored procedure. The following commands enable request-level logging of a limited set of requests and redirect the output to the file sqllog.txt:

call sa_server_option('request_level_logging','SQL');
call sa_server_option('request_level_log_file',
                       'sqllog.txt');

The following command disables request-level logging:

call sa_server_option('request_level_log_file','');

To view the current settings for the SQL log file and logging level, execute the following statement:

select property('RequestLogFile'),        property('RequestLogging');

To match .iqmsg log and the -zr SQL log entries using connection information, see “Correlating connection information”.

The request log format has been modified in this version of Sybase IQ to make it more compact and to permit additional information to be recorded. Instead of fixed-format line prefixes, common information is recorded as comma-delimited text. Where possible, times are recorded as “=” (meaning the same as the previous line) or +nnn (meaning nnn milliseconds after the previous line). The end result is that request logs are now about 1/3 the size of logs created by earlier versions.

In this version of Sybase IQ, additional information is recorded in the request log. For queries, the information recorded is isolation level, number of rows fetched, and cursor type. For INSERT, UPDATE, and DELETE statements, the information recorded is number of rows affected and number of triggers fired.

Statements executed within procedures and triggers can be logged optionally.

The short form of query plans can be recorded in the request log. Plans for procedure statements are also recorded, if logging of procedures is enabled.

The following output shows an excerpt from the request log, when the server is started with the -zr all option. In this example, the user connects to the iqdemo database and executes the command sp_iqstatus.

There are several comma separated fields in each line and the first field indicates the time. Periodically, a full timestamp is output in the form:

MMdd hhmmss.sss
0523 095954.807,[,1000000001,sp_iq_mpx_init,16,iq utilities status 1

For lines after this line, for example, “+13,C,1,UID=DBA”, the offset is from the previous line. In this case, “+13” means that about 13 milliseconds have passed since the last line. In some cases, “=” means approximately 0 milliseconds have elapsed since the last line.

Here is the excerpt from the request log:

0523 095954.807,[,1000000001,sp_iq_mpx_init,16,iq
utilities status 1
+2,],1000000001,sp_iq_mpx_init,16
+1,[,1000000001,sp_iq_mpx_init,62,message STRING('IQ
Server ',@@servername,'.') to console
+2,],1000000001,sp_iq_mpx_init,62
taj% pg iqdemo.sqllog
0523 095954.807,[,1000000001,sp_iq_mpx_init,16,iq
utilities status 1
+2,],1000000001,sp_iq_mpx_init,16
+1,[,1000000001,sp_iq_mpx_init,62,message STRING('IQ
Server ',@@servername,'.') to console
+2,],1000000001,sp_iq_mpx_init,62
0523 100510.344,<,1,CONNECT
+13,C,1,UID=DBA
+83,>,1,CONNECT,1
+1,<,1,PREPARE,SELECT @@version, if 'A'<>'a' then 1
else 0 endif, isnull(property('IsIQ'),'NO'),
isnull(connection_property('odbc_distinguish_char_and_
varchar'),'Off'),
isnull(connection_property('odbc_describe_binary_as_va
rbinary'),'Off'), connection_property('charset'),
db_property('charset')
+1,>,1,PREPARE,65536
=,<,1,EXEC,65536
+79,P,1,[S]DUMMY<seq>
=,>,1,EXEC
+1,<,1,DROP_STMT,65536
=,>,1,DROP_STMT
=,<,1,PREPARE,SET TEMPORARY OPTION time_format =
'hh:nn:ss';SET TEMPORARY OPTION timestamp_format =
'yyyy-mm-dd hh:nn:ss.ssssss';SET TEMPORARY OPTION
date_format = 'yyyy-mm-dd';SET TEMPORARY OPTION
date_order = 'ymd';SET TEMPORARY OPTION isolation_level
= 0;
+1,>,1,PREPARE,65537
+1,<,1,EXEC,65537
=,[,1,*batch*,1,set temporary option time_format =
'hh:nn:ss'
+11,],1,*batch*,1
=,[,1,*batch*,1,set temporary option timestamp_format =
'yyyy-mm-dd hh:nn:ss.ssssss'
+11,],1,*batch*,1
+1,[,1,*batch*,1,set temporary option date_format =
'yyyy-mm-dd'
+11,],1,*batch*,1
=,[,1,*batch*,1,set temporary option date_order = 'ymd'+11,],1,*batch*,1
=,[,1,*batch*,1,set temporary option isolation_level = 0
+11,],1,*batch*,1
=,>,1,EXEC

Request log file analysis

The format of the output in the request log file (generated by setting the -zr server startup switch) has changed in Sybase IQ 15.1. The stored procedures sa_get_request_profile and sa_get_request_times can be used to read the -zr log file and summarize the results.

The procedure sa_get_request_profile analyzes the request log to determine the execution times of similar statements and summarizes the results in the global temporary table satmp_request_profile. For example:

call sa_get_request_profile('/sys1/users/jones/iqreqs1_zr.log');
select * from satmp_request_profile;

The procedure sa_get_request_times analyzes the request log to determine statement execution times and summarizes the results in the global temporary table satmp_request_time. For example:

call sa_get_request_times('/sys1/users/jones/iqreqs1_zr.log');
select * from satmp_request_time;

For more information about request-level logging, see the section “Server command-line switches” in Chapter 1, “Running the Database Server” of the Utility Guide, “sa_server_option system procedure” in Chapter 7, “System Procedures”of Reference: Building Blocks, Tables, and Procedures, and “Request logging” in SQL Anywhere Server – SQL Usage > Monitoring and Improving Database Performance > Improving database performance > Other diagnostic tools and techniques.