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”.
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:
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"
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 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.