Reporting Bad SQL Code in DB2 - Page 3

Finding Top Sessions

To find the slow-running SQL, we need to collect and analyze all SQL statements coming into the database, for a period of high system utilization. Previously presented "top" UNIX system commands can be used to identify a period for collecting SQL statements. After the system returns to low CPU utilization, we will stop collecting SQL statistics.

Listing applications connected to the database:

 db2 => list application global
 
Auth Id  Application    Appl.      Application Id                 DB       # of
         Name           Handle                                    Name    Agents
-------- -------------- ---------- ------------------------------ -------- -----
DB2INST1  db2bp          401        *N0.db2inst1.030520135855     ARTSIT   87   
PAYMENT1  DWH_CGN.EXE    355        776B6599.0DEA.030520135255    ARTSIT   41   
PAYMENT1  DWH_CGN.EXE    366        776B6599.0DED.030520135450    ARTIST   131  
PAYMENT9  java           377        82500A51.F327.030520061537    ARTIST   11   
PAYMENT9  java           345        43264E31.E222.020110034533    ARTIST   7   

We assume that the problem is coming from users PAYMENT1 and PAYMENT9. The maximum number of agents (131) has been allocated for PAYMENT1 user connection and it makes sense to expect that this is hogging the connection.

First, we need to create the statements monitor switches and to store their definition in the database catalog. On our system, statement collecting is only reasonable on node 1 and node 2, since node 0 (catalog) has no user objects.

db2 => connect to artist 
 
   Database Connection Information
 
 Database server        = DB2/SUN 7.2.5
 SQL authorization ID   = DB2INST1
 Local database alias   = ARTSIT

Enabling statement information collecting at database manager level:

db2 => update monitor switches using statement on
DB20000I  The UPDATE MONITOR SWITCHES command completed successfully.

Creating SQL event monitor for capturing the SQL statements for the user PAYMENT1:

db2 => create event monitor SQLNODE1_PAY1 for statements where AUTH_ID='PAYMENT1' write to 
file '/home/db2inst1/pay1_1' NONBLOCKED REPLACE ON NODE 1 LOCAL
DB20000I  The SQL command completed successfully.
db2 => create event monitor SQLNODE2_PAY1 for statements where AUTH_ID='PAYMENT1' write to 
file '/home/db2inst1/pay1_2' NONBLOCKED REPLACE ON NODE 2 LOCAL
DB20000I  The SQL command completed successfully.

Creating the SQL event monitor for capturing the SQL statements for the user PAYMENT9:

db2 => create event monitor SQLNODE1_PAY9 for statements where AUTH_ID='PAYMENT9' write to 
file '/home/db2inst1/pay9_1' NONBLOCKED REPLACE ON NODE 1 LOCAL
DB20000I  The SQL command completed successfully.
db2 => create event monitor SQLNODE2_PAY9 for statements where AUTH_ID='PAYMENT9' write to 
file '/home/db2inst1/pay9_2' NONBLOCKED REPLACE ON NODE 2 LOCAL
DB20000I  The SQL command completed successfully.

Activate the SQL event monitors for the user PAYMENT1:

db2 => set event monitor SQLNODE1_PAY1 state=1
DB20000I  The SQL command completed successfully.
db2 => set event monitor SQLNODE1_PAY1 state=1
DB20000I  The SQL command completed successfully.

Activate the SQL event monitors for user PAYMENT9:

db2 => set event monitor SQLNODE1_PAY9 state=1
DB20000I  The SQL command completed successfully.
db2 => set event monitor SQLNODE2_PAY9 state=1
DB20000I  The SQL command completed successfully.

Checking status for the SQL event monitor switch:

db2 => get monitor switches
 
            Monitor Recording Switches
 
Switch list for node 0
Buffer Pool Activity Information  (BUFFERPOOL) = OFF
Lock Information                        (LOCK) = OFF
Sorting Information                     (SORT) = OFF
SQL Statement Information          (STATEMENT) = ON  05-22-2003 10:12:49.890612
Table Activity Information             (TABLE) = OFF
Unit of Work Information                 (UOW) = OFF

db2 => select EVMONNAME,TARGET,NODENUM,MONSCOPE from syscat.eventmonitors
 
EVMONNAME          TARGET               NODENUM MONSCOPE
------------------ -------------------- ------- --------
SQLNODE1_PAY1      /home/db2inst1/pay1_1      1 L       
SQLNODE1_PAY9      /home/db2inst1/pay9_1      1 L       
SQLNODE2_PAY1      /home/db2inst1/pay1_2      2 L       
SQLNODE2_PAY9      /home/db2inst1/pay9_2      2 L       

Reporting Bad SQL Code

After the application activity has been finished, monitoring activity can be turned off. Stopping SQL event monitoring will empty all database buffers, and force writing all of the collected information to a file.

Stopping the SQL collection for users PAYMENT1 and PAYMENT9:

db2 => set event monitor SQLNODE1_PAY1 state=0
DB20000I  The SQL command completed successfully.
db2 => set event monitor SQLNODE1_PAY1 state=0
DB20000I  The SQL command completed successfully.
db2 => set event monitor SQLNODE1_PAY9 state=0
DB20000I  The SQL command completed successfully.
db2 => set event monitor SQLNODE2_PAY9 state=0
DB20000I  The SQL command completed successfully

The generated file is a non-readable binary file. We will use the standard DB2 system command db2evmon to format trace file to the readable format.

>> db2evmon -path /home/db2inst1/pay1_1 > sql_payment1_node1.txt
Reading /tmp/00000000.evt ...
>> db2evmon -path /home/db2inst1/pay1_2 > sql_payment1_node2.txt
Reading /tmp/00000000.evt ...
>> db2evmon -path /home/db2inst1/pay9_1 > sql_payment9_node1.txt
Reading /tmp/00000000.evt ...
Reading /tmp/00000001.evt ...
Reading /tmp/00000002.evt ...
Reading /tmp/00000003.evt ...
>> db2evmon -path /home/db2inst1/pay1_1 > sql_payment9_node2.txt
Reading /tmp/00000000.evt ...
Reading /tmp/00000001.evt ...
Reading /tmp/00000002.evt ...

sql_payment1_nodex.txt and sql_payment9_nodex.txt contains all of the executed SQL commands from users PAYMENT1 and PAYMENT9.

Checking and comparing content, in one of the event trace files, we find the query with highest CPU utilization:

  Statement Event ...
  Appl Handle: 377
  Appl Id: 82500A51.F327.030520061537
  Appl Seq number: 0001
  Creator  : PAYMENT9
  Package  : SQLLF000
  Cursor   : SQLCUR4
  Cursor was blocking: FALSE
  Text     : select u1.status, u2.status_old, max(u16.user_enrity_rel) user_entity,           
  max(u16.user_entitiy_lang) user_entitiy_lang, u11.customer_group , max(u14. customer_group)    
  customer_group,......
  -------------------------------------------
  Start Time: 05-20-2003 14:34:36.111156
  Stop Time:  05-20-2003 16:23:39.507116
  Exec Time:  594.477708 seconds   
  Number of Agents created: 11
  User CPU:   427.400000 seconds  
  System CPU: 161.260000 seconds
  Fetch Count: 0
  Sorts: 23
  Total sort time: 13.340000
  Sort overflows: 4
  Rows read: 1342544411
  Rows written: 0
  Internal rows deleted: 0
  Internal rows updated: 0
  Internal rows inserted: 0

The SQL statement under the Text field is our database killer. This statement has the highest CPU utilization and it is coming from user PAYMENT9.

Conclusion

The demonstrated procedure can be further extended with advanced reporting techniques.

All of the collected information is an ideal source for loading into a database for further analysis. Once it is in the database, we will be able to produce reports related to SQL statement execution since many performance problems are closely related to SQL statement execution.

» See All Articles by Columnist Marin Komadina