Technical Blog Post
Abstract
Profiling sql statements using db2trc
Body
Troubleshooting an SQL statement that is slow or running in a non-optimal way can be a challenging task.
Usually there is some cardinality underestimation within the query compiler estimates that could lead to a poor execution plan choice.
Tools like db2caem : https://www.ibm.com/support/knowledgecenter/en/SSEPGG_10.5.0/com.ibm.db2.luw.admin.cmd.doc/doc/r0057282.html
are great to identify underestimations in an execution plan.
However the data provided by db2caem has some limitations.
"First of all, it requires the statement to actually complete. In some cases, performance can be so bad that even after hours or running, a statement doesn't complete. In this case, db2caem won't have the data we need."
This information is no longer correct, information gathered by a db2caem in progress can be obtained using the method described in the article Using db2caem to diagnose queries which do not complete or are resource intensive
Another downside is that you cannot execution db2caem on an already in progress statement, i.e. some statements don't run slow all the time,the execution time might depend on external factors, like parameter marker values.
In cases like this, it is difficult to gain transparency as to where the statement is actually spending time.
In DB2, an execution plan is made up of a graph of low level plan operators, otherwise known as "lolepops". These can represent a TBSCAN , IXSCAN, NLJOIN, HSJOIN, UNION etc... operator.
These operators are seen when running an explain on a statement ( db2expln or db2exfmt ),when a statement is executing, it spends its time in those operators.
For instance a Nested loop join with a large number of rows on the outer leg might be spending a lot of time in the NLJOIN lolepop.
Some statements have hundreds of these operators, so troubleshooting a query plan performance is not straightforward just from visual inspection of the plan alone.
If there was some runtime knowledge of where processing time is being spent then that task could become much easier.
This can be achieved by making use of a little known db2trc suboption. "-rds"
The option is documented in the Knowledge Center at this location.
Let's now take a small example. Running db2trc with no options should be done with extreme caution in production environments.
Gigabytes worth of trace information can be produced in a matter of minutes,which also means that performance can severely be impacted by db2trc.
So it is always advisable to limit the db2trc to trace only what you need.
In this case the input uses the application handle of the application currently running a slow SQL statement.
( assuming that slow means at least X number of minutes, sufficient to identify an application handle and to take a quick db2trc ).
We also add the "SQLRI" flag, this is the component that will produce the trace points we need, there is no need to fill the trace buffer with components that are not required.
db2trc on -l 128M -t -Madd SQLRI -apphdl <application handle>
< let this run for at least a few seconds>
db2trc dmp trc.dmp
db2trc off
db2trc flw -t -rds trc.dmp trc.flw
Note that the -t option is used both in the collection and the formatting in order to obtain timestamps.
The resulting trc.flw file will look similar to this :
8 0.000101568 | | sqlrihsjnBuildPD entry [opNumber: 266, lolepop: 4] [eduid 38403
9 0.000101880 | | | sqlri_hsjnProcessBuildTuple entry [eduid 38403 eduname db2agent]
10 0.000102287 | | | | sqlri_hsjnAddBuildTuple entry [eduid 38403 eduname db2agent]
11 0.000102849 | | | | sqlri_hsjnAddBuildTuple exit
12 0.000103089 | | | sqlri_hsjnProcessBuildTuple exit
13 0.000103287 | | sqlrihsjnBuildPD exit [opNumber: 266, lolepop: 4] [rc = 4]
14 0.000104306 | sqlriFetch exit [rc = 0x80040001 = -2147221503 = SQLD_NOREC]
15 0.000104511 sqlriNljnNonPiped exit [opNumber: 270, lolepop: 6]
16 0.000104810 sqlriNljnNonPiped entry [opNumber: 254, lolepop: 7] [eduid 38403
17 0.000105142 | sqlriFetch entry [eduid 38403 eduname db2agent]
18 0.000106537 | sqlriFetch exit [rc = 0x80040001 = -2147221503 = SQLD_NOREC]
19 0.000106736 sqlriNljnNonPiped exit [opNumber: 254, lolepop: 7]
20 0.000106974 sqlrita entry [opNumber: 242, lolepop: 8] [eduid 38403 eduname db2agent]
21 0.000107316 | sqlriFetch entry [eduid 38403 eduname db2agent]
22 0.000110947 | sqlriFetch exit
23 0.000111148 sqlrita exit [opNumber: 242, lolepop: 8]
the -rds option has produced the "lolepop" information for us. Interpreting this from the trace alone is not that straightforward, but I attached a ( perl ) tool to this blog which parses this and produces a report:
$ ./db2prof --file trc.flw
Start processing db2trc ..
Operator Count Cumulative (s) Per Operator (s) %
Thread id = 8388920_38403_0
8 59928 0.279630914 0.279630914 2.48
6 59928 0.690958987 0.106035371 0.94
52 59928 0.019025154 0.019025154 0.17
50 59928 0.016324934 0.016324934 0.14
4 59928 0.131950418 0.131950418 1.17
7 119855 10.242792851 10.226468167 90.68
so using this information I can tell that 90% of time is spent in operator 7
If I have the db2exfmt output for the statement then that points me to the "hot" operator and I can start finding explanations or solutions for this.
But this approach is somewhat static.
I added functionality to the tool to automatically collect information based on an input application handle.
Usage :
$ ./db2prof --help
Usage:
db2prof -arguments
Arguments:
--help print Options and Arguments
--apphdl <apphdl> Create profile for this application handle
--file <filename> Use an already collected trace as input.
Note : options --file and --apphdl are mutually exclusive
--time <number of seconds>
Then I use an ugly cartesian product to illustrate a poorly running / hanging sql statement :
select count_big(*) from staff s1, staff s2, staff s3, staff s4, staff s5, staff s6;
I obtain the application handle before running the sql :
$ db2 "values MON_GET_APPLICATION_HANDLE()"
1
--------------------
31
and then run the sql in that same session
then in another window, I release the profiling tool on the application handle and this produces the following output :
$ ./db2prof -apphdl 31
Database = SAMV105 , C-AnchID = 786, C-StmtUID = 1
Environment id = 1, Variation id = 1
Trace is turned on
Obtaining a masked db2trc ...
Trace is stopped
Trace has been dumped to file "trc_temp.dmp"
Trace is turned off
Checking if the statement didn't change during tracing...
Collecting db2expln info from the package cache
DB2 Universal Database Version 10.5, 5622-044 (c) Copyright IBM Corp. 1991, 2012
Licensed Material - Program Property of IBM
IBM DB2 Universal Database SQL and XQUERY Explain Tool
Output is available in "expln.out".
Total number of trace records : 1074323
Trace truncated : NO
Trace wrapped : YES
Number of trace records formatted : 1074323 (pid: 28639248 tid 2382 node: 0)
Formatting db2trc..
Start processing db2trc..
Operator Count Cumulative (s) Per Operator (s) %
Thread id = 28639248_2382_0
6 6 0.000004663 0.000004663 0.00
11 210 0.000043074 0.000043074 0.02
4 7352 0.007897461 0.004655432 1.90
3 7147 0.233554180 0.011057333 4.51
12 7140 0.001554969 0.001554969 0.63
2 250189 0.162247533 0.224250137 91.55
5 210 0.000228939 0.000136177 0.06
Operators
6 Nested Loop Join
2 Aggregation Completion
3 Nested Loop Join
5 Nested Loop Join
9 Access Table Name = BENNYV.STAFF ID = 2,15
8 Access Table Name = BENNYV.STAFF ID = 2,15
7 Nested Loop Join
1 Return Data to Application
4 Nested Loop Join
I used the package cache anchor/userid values to obtain the data from db2expln. Some more parsing gives me a short explanation of the operator.
It saves the output in expln.out so afterwards I can get a more full view of the query plan. But with this information I can immediately see that operator 2 is where most time is spent.
The tool is not perfect yet and might have some flaws, but it should give an indication of time spent at the plan operator level, without too much impact
( the trace it uses is short and masked ).
The tool will work in partitioned environments but only for the logical partitions running on the host where the command was executed.
Future development will depend on uptake and usefulness.
UID
ibm13285891