October 2011 Edition

Using Request Logging To Monitor Application Concurrency

Request logging has been available in SQL Anywhere since version 8.0. It has been enhanced over the years with more functionality which was designed to help diagnose database performance problems. Although the information gathered with 'request logging' doesn't log as much information as 'database tracing' (introduced in version 10), it provides a quick and simple way to gather enough information for concurrency analysis without service interruption. This is particularly important for systems running 24/7 when we don't want to affect the end users and wish to minimize the performance impact on the system.

With request logging, a database administrator can identify all SQL requests that are being sent to the database, their duration with query plan information, as well as blocking information which is required to help diagnose performance issues.

It is particularly important to monitor for blocking patterns after application upgrades. With changes in the executed SQL code or changes to the database schema there is always a chance that there is an increase in contention for database resources. This is when request logging may become helpful, while minimizing the impact on the system’s performance.

Below is an example that demonstrates how to identify blocking requests, using the request logging feature with SQL Anywhere 12.0.1.

Turn request logging on

In order to start request-level logging, a user needs to connect to the running database server and execute:

CALL dbo.sa_server_option('RequestLogFile',<request.log>);
CALL dbo.sa_server_option('RequestLogging',<options>);

or start the server with -zr <options> -zo <request.log> switches,

where:

<request.log> - file where request logging information is stored

and <options>:

PLAN - enables logging of execution plans (short form).

HOSTVARS - enables logging of host variable values.

PROCEDURES - enables logging of statements executed from within procedures.

TRIGGERS - enables logging of statements executed from within triggers.

OTHER - enables logging of additional request types not included by SQL, such as FETCH and PREFETCH. .

BLOCKS - enables logging of details showing when a connection is blocked and unblocked

REPLACE - at the start of logging, the existing request log is replaced.

ALL logs all supported information.

NO or NONE turns off logging to the request log.

e.g. outputs logging information to c:\req.txt, with sql+plan+blocks+replace’ options:

call dbo.sa_server_option('RequestLogFile','c:\req.txt');
call dbo.sa_server_option('RequestLogging','sql+procedures+blocks+replace');

Note: Since the request-level log records all SQL statements that were executed, be aware that <request.log> file may contain sensitive data (passwords etc.)

Test your Application

When testing on a production system, turn the logging on as shown as above and leave it running for some time (e.g. 15 or 30 minutes ). Monitor the request.log file growth as it may rapidly increase in size on busy systems.

In our example we are going to simulate blocking with the following using SQL Anywhere 12 installed:

Open cmd Window and start the server:

dbsrv12 -n blocktest "%sqlany12%\demo.db"

Create a test table and test procedures:

"%sqlany12%\bin32\dbisql" -c uid=dba;pwd=sql;servername=blocktest

and run:

-- create test table
CREATE TABLE mytab(
pk INT PRIMARY KEY DEFAULT AUTOINCREMENT,
i2 INT NOT NULL
);

-- insert a random number between 1 and 100 into i2
INSERT INTO mytab(i2)
SELECT cast(rand() * 100 as int);
COMMIT;

-- create block_test1 procedure which will update mytab and wait 3 seconds before it commits
CREATE PROCEDURE block_test1()
begin
declare i int;
SET i = 0;
WHILE i <= 10 LOOP
UPDATE mytab SET i2 = cast(rand() * 100 as int);
WAITFOR DELAY '00:00:03';
COMMIT;
SET i = i + 1;
END LOOP;
end;

-- create block_test2 procedure which will update mytab and wait 2 seconds before it commits
CREATE PROCEDURE block_test2()
begin
declare i int;
SET i = 0;
WHILE i <= 10 LOOP
UPDATE mytab SET i2 = cast(rand() * 100 as int);
WAITFOR DELAY '00:00:02';
COMMIT;
SET i = i + 1;
END LOOP;
END;

From the same dbisql Windows, start request logging by executing:

CALL dbo.sa_server_option('RequestLogFile','c:\req.txt');
CALL dbo.sa_server_option('RequestLogging','sql+procedures+plan+blocks+replace');
bsrv12 -n blocktest "%sqlany12%\demo.db"

Now, open 2 additional dbisql windows, and then from the first window run:

CALL block_test1();

then, without waiting for completion , from the second window run:

CALL block_test2();

Let both of them to finish and close both of them.

Go back to the first dbisql Window and stop request logging by executing:

CALL dbo.sa_server_option('RequestLogging','off');

Analyzing blocked statements

Using the same dbisql Window, load the request-level log data into temporary tables using a system stored procedure:

CALL dbo.sa_get_request_times('c:\req.txt');

To see which connections were blocked and for how long, execute:

SELECT *, DATEDIFF(ms,block_time,unblock_time) as dur_ms
FROM dbo.satmp_request_block

Then, see which actual SQL requests where blocked with e.g:

SELECT req_id,conn_id,millisecs,stmt_id,stmt, proc_name, proc_line,start_time
FROM satmp_request_time t
WHERE EXISTS(SELECT * FROM satmp_request_block WHERE req_id=t.req_id)

And, finally for a particular blocked statement (req_id: 130) see which statements were executing at the same time to cause the blocking. Looking at 4000 ms timeframe you can see that as soon as conn_id=4 executed ‘commit work’ conn_id=2 started processing again.

SELECT req_id,conn_id,millisecs,stmt,proc_name,proc_line,plan,start_time
FROM satmp_request_time
WHERE start_time BETWEEN '2011-09-30 14:00:30.343'
AND dateadd(ms,4000,'2011-09-30 14:00:30.343')