I’ve been working with a developer to profile some SQL from a process he’s running. He has no insight into the SQL that the tool is using, primarily to insert data. I thought I’d share some of the details. I still think of this kind of event monitor as a “Statement Event Monitor”.

Setup

I started with the same exact setup from Using an Event Monitor to Capture Statements with Values for Parameter Markers.

Enabling Activity Data Collection

There are several levels at which you can enable data collection. You can do it at the session level. That didn’t work for me, because I’m collecting data from a web-based application (WebSphere Commerce), and I need to just capture whatever it does in a controlled scenario. That means my option was to capture this at the Workload Manager Level. Now I don’t have a license for WLM. But even if you’re not licensed, all of your database activity goes into one of two default classes. The classes in my 10.5 implementation are:

• SYSDEFAULTADMWORKLOAD
• SYSDEFAULTUSERWORKLOAD

All user queries are automatically in that latter “SYSDEFAULTUSERWORKLOAD” if you have no other properties defined.

As always, verify any licensing statements with IBM before counting on them, but my understanding is that you can enable activity data collection on these default classes with out having licensed the WLM feature. To enable the activity data collection I want for my activity statement event monitor, I had to alter that service class like this:

db2 "alter service class sysdefaultsubclass under sysdefaultuserclass collect activity data on all database partitions with details and values"

If you’re actually licensed for and using WLM, you would have to alter the appropriate service class to collect the data you need.

Presumably, there is overhead involved here, so you would not want to leave this enabled beyond the short period that you need to use it. To disable it, use:

db2 "alter service class sysdefaultsubclass under sysdefaultuserclass collect activity data none"

Event Monitor

Once you have enabled the collection of activity data, you need to create an event monitor to actually receive that data. Here, many of the options that you may be familiar with on event monitors are available. My preference for later data analysis is an event monitor that writes to a table, but if you were dealing with a fragile performance situation, that does add additional overhead.

Let’s stop for a minute and talk about when you might want to capture statements with an event monitor and this methodology. In my particular situation, we’re concerned about exactly what SQL is executing, and how long that SQL is taking. The data load process in question is taking longer than we would expect to insert 120,000 rows. I ran this event monitor during specifically defined activity in our non-production environment – with other people asked to stay out of the environment. In a production environment, you are likely not just to impact performance of the main workload with an event monitor with this level of detail, but you’re also likely to generate an incredible amount of data – which may either fill up your available disk space or just be that much harder to get a reasonable analysis out of because there is so much data.

Here’s the syntax I used for this event monitor:

db2 create event monitor act_stmt for activities write to table manualstart

That part actually seemed pretty simple to me.

Not being familiar with this event monitor, I wanted to see what tables it actually created. In my case, I didn’t really care which tablespace the tables ended up in for these test/staging environments, but you could specify that as well. So looking at the tables created, I see:

db2 list tables for all |grep DB2INST1
ACTIVITYMETRICS_ACT_STMT        DB2INST1        T     2013-11-15-13.05.39.368590
ACTIVITYSTMT_ACT_STMT           DB2INST1        T     2013-11-15-13.05.38.306542
ACTIVITYVALS_ACT_STMT           DB2INST1        T     2013-11-15-13.05.38.655985
ACTIVITY_ACT_STMT               DB2INST1        T     2013-11-15-13.05.37.208514

Of course to actually activate it when ready to capture the data, I used:

db2 "set event monitor act_stmt state = 1"

Querying Output

Querying the data takes a bit to figure out how to get what I want. What I came up with finally was this:

        select
                (select substr(stmt_text,1,70) as stmt_text from db2inst1.ACTIVITYSTMT_ACT_STMT as as1 where as1.EXECUTABLE_ID=as.EXECUTABLE_ID fetch first 1 row only),
                count(*) as NUM_EXECS,
                sum(STMT_EXEC_TIME) as SUM_STMT_EXEC_TIME,
                sum(TOTAL_CPU_TIME) as SUM_TOTAL_CPU_TIME,
                sum(LOCK_WAIT_TIME) as SUM_LOCK_WAIT_TIME,
                sum(ROWS_READ) as SUM_ROWS_READ,
                sum(ROWS_MODIFIED) as SUM_ROWS_MODIFIED
        from db2inst1.ACTIVITYSTMT_ACT_STMT as as
        left outer join db2inst1.ACTIVITYMETRICS_ACT_STMT av
                on as.appl_id=av.appl_id
                        and as.uow_id=av.uow_id
                        and as.activity_id=av.activity_id
        group by EXECUTABLE_ID
        order by 3 desc

Note that the substring length of the statement chosen was small to fit on the screen. Once I had looked at statements, I would likely query again to get the full text. The output looks like this:

STMT_TEXT                                                              NUM_EXECS   SUM_STMT_EXEC_TIME   SUM_TOTAL_CPU_TIME   SUM_LOCK_WAIT_TIME   SUM_ROWS_READ        SUM_ROWS_MODIFIED
---------------------------------------------------------------------- ----------- -------------------- -------------------- -------------------- -------------------- --------------------
INSERT INTO XPRICECHGSETTING (STORE, START_DATE, TRAN_TYPE, ITEM, NEW_      120111                14744               692148                    0                 6006               120111
SELECT INSTANCENAME,DBNAME,DBPARTITIONNUM,FACILITY,          (CASE REC          77                 7677              4486013                    0                    0                    0
DELETE FROM xpricechgsetting                                                     1                 1021               386150                    0                    0               120111
select i.INDSCHEMA, i.INDNAME, i.DEFINER, i.TABSCHEMA, i.TABNAME, i.CO           1                   89                37761                    0                31707                13358
SELECT TABNAME, COLNAME FROM SYSCAT.COLUMNS WHERE GENERATED='A' AND TA           2                   73                11406                    0                16454                    0
TRUNCATE TABLE wscomusr.X_GLINK_TEMP IMMEDIATE                                   1                   72                 3840                    0                   17                    0
TRUNCATE TABLE wscomusr.X_ITM_MASTER IMMEDIATE                                   1                   70                 2527                    0                   15                    0
CALL SYSIBM.SQLSTATISTICS (?,?,?,?,?,?)                                          4                   57                19488                    0                   20                    0
CALL SYSIBM.SQLCOLUMNS (?,?,?,?,?)                                               4                   56                26473                    0                    7                    0
CALL SYSIBM.SQLTABLES (?,?,?,?,?)                                                4                   53                 7045                    0                    2                    0
CALL SYSIBM.SQLFOREIGNKEYS (?,?,?,?,?,?,?)                                       4                   45                24777                    0                   15                    0
CALL SYSIBM.SQLPRIMARYKEYS (?,?,?,?)                                             4                   32                 7748                    0                    0                    0
TRUNCATE TABLE wscomusr.X_CATGPENREL_TEMP IMMEDIATE                              1                   24                 2259                    0                   16                    0
...

In this case, I’ve sorted on the execution time in descending order, because that’s the item of most concern to me. The others are interesting to me to be aware of too, and there are many more metrics in the ACTIVTYMETRICS table that might be interesting depending on what you’re looking for.

Here, I learned that the insert statements (the first statement) that this process is running are taking only 15 seconds in the database. So the fact that this overall data load process is running 30-40 minutes is not based on slowness in the database.

A side note – the second statement is one that I’ve already identified as coming from a Tivoli Monitoring implementation that I do not control, and it just keeps popping up in my analyses, both using DBI’s Brother-Panther and manual analyses like this, and it’s really beginning to bug me.