IBM - WAS、DB2、TCPDUMP查找长时间运行SQL

最新推荐文章于 2023-08-21 11:01:52 发布

MyGaoRen

最新推荐文章于 2023-08-21 11:01:52 发布

阅读量1.2k

点赞数

分类专栏： IBM DB2 SQL 文章标签： db2 ibm was sql tcpdump

本文链接：https://blog.csdn.net/MyGaoRen/article/details/107406135

版权

IBM 同时被 3 个专栏收录

9 篇文章 1 订阅

订阅专栏

DB2

7 篇文章 0 订阅

订阅专栏

SQL

2 篇文章 0 订阅

订阅专栏

WAS动态监控长时间SQL事务
DB2 客户端JDBC DRIVE跟踪开启
DB2服务器端快照SNAPSHOT查找执行时长SQL
DB2服务器端监控视图及表函数查找执行时长SQL
DB2服务器端按连接动态跟踪开启
TCPDUMP收集SQL语句

WAS动态监控长时间SQL事务

注意：仅支持WAS 8.5.5.12及之后版本

临时开启长事务监控，如下案例，在数据源名称为” DefaultApp Datasource”上开启jdbc时间监控，超过18000毫秒（18秒）输出信息。

ds = AdminControl.completeObjectName('name=DefaultApp Datasource,*')

AdminControl.invoke(ds, "enableJDBCTiming","18000")

关闭临时长事务监控，超过18000毫秒（18秒），输出执行SQL

AdminControl.invoke(ds, "disableJDBCTiming")

日志输出信息，包括执行的SQL语句

[4/7/17 9:04:38:618 CDT] 000000a0 WSJdbcTiming W TRAS9910W: The 7555828d transaction on the

000000a0 thread has been running for 1044 ms, which exceeds the time set for emitting the trace on a

running thread. The following stack trace shows what this thread is currently doing:java.lang.Throwable

at com.ibm.ws.rsadapter.spi.WSJdbcTiming.<init>(WSJdbcTiming.java:39)

at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.beginTransactionIfNecessary(WSJdbcConnection.java:872)

at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.createStatement(WSJdbcConnection.java:1729)

at com.ibm.ws.rsadapter.jdbc.WSJdbcConnection.createStatement(WSJdbcConnection.java:1707)

at suite.r90.base.jdbc41.test.JDBC41TestServlet.init(JDBC41TestServlet.java:136)

at javax.servlet.GenericServlet.init(GenericServlet.java:244)

at com.ibm.ws.webcontainer.servlet.ServletWrapper.init(ServletWrapper.java:342)

at com.ibm.ws.webcontainer.servlet.ServletWrapperImpl.init(ServletWrapperImpl.java:168)

at com.ibm.ws.webcontainer.servlet.ServletWrapper.load(ServletWrapper.java:1385)

at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1029)

at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:4144)

at com.ibm.ws.webcontainer.webapp.WebAppImpl.handleRequest(WebAppImpl.java:2208)

at com.ibm.ws.webcontainer.webapp.WebGroup.handleRequest(WebGroup.java:304)

at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:1030)

at com.ibm.ws.webcontainer.WSWebContainer.handleRequest(WSWebContainer.java:1817)

at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:382)

at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:465)

at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:532)

at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.processRequest(HttpInboundLink.java:318)

at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.ready(HttpInboundLink.java:289)

at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:214)

at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:113)

at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:175)

at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)

at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)

at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:138)

at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:204)

at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:775)

at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:905)

at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1892)

The following list gives the total run time of the transaction, all SQL statements that ran during the

transaction, and the run time for each of the SQL statements:

1044 ms JEEName:jdbc41testApp | jdbc41test.war | JDBC41TestServlet

814.845 ms jdbc/TestDataSource | executeUpdate | drop table JDBC_FAT_v41_COLORS

213.501 ms jdbc/TestDataSource | executeUpdate | create table JDBC_FAT_v41_COLORS (id int not null primary key, color

varchar(30))

方法完成时间 Time for method completion (814.845ms).

JNDI名称JNDI name of the Data Source on which the SQL statement was executed (jdbc/TestDataSource).

执行CRUD方法JDBC specification method that is called by application (executeUpdate).

执行SQL语句SQL statement that is executed (drop table JDBC_FAT_v41_COLORS).

数据源中设置长事务监控属性，重启后自动生效，不用每次设置。

ds = AdminConfig.getid( '/Cell:MyCell/Node:MyNode/Server:server1/JDBCProvider:Derby JDBC Provider/DataSource:DefaultApp Datasource/')

propertySet = AdminConfig.showAttribute(ds, 'propertySet')

AdminConfig.create('J2EEResourceProperty', propertySet, [['name','JDBCTimingThreshold'], ['value','180000'],['description','Log a stacktrace and list of JDBC operations that are performed if a transaction runs for more than the specified number of milliseconds']])

此参数需要重效。

WAS强制清理数据源连接池

有写场景下需要处理无效连接，需要手动清理WAS连接池，

清除 server2 的数据库连接池

set ds [$AdminControl queryNames type=DataSource,name=myDS,process=server2,*]

$AdminControl invoke $ds purgePoolContents

清除所有池

set mbeans [$AdminControl queryNames type=DataSource,*]

foreach mbean $mbeans {

>$AdminControl invoke $mbean purgePoolContents

}

DB2 客户端JDBC DRIVE跟踪开启

在加载DB2 JDBC DRIVE时指定参数，可以指定是否开启动态跟踪，

注意：JCC release 3.72 and 4.22 之后版本提供此功能。其次开启可能影响性能

部分参数如下：

db2.jcc.tracePolling=true
db2.jcc.tracePollingInterval=60
db2.jcc.traceDirectory=/tmp
db2.jcc.traceLevel=0
db2.jcc.traceOption=1
db2.jcc.traceFileCount=5
db2.jcc.traceFileAppend=false

以下几个参数决定如何动态开启跟踪：

tracePolling:是否开启动态开启 Enables JDBC trace to be dynamically enabled/disabled.

tracePollingInterval: 配置检查周期，检查traceLevel参数是否修改Check the driver configuration file every xx seconds to see if the traceLevel parameter has changed

traceLevel:为0关闭跟踪，为1开启跟踪

traceLevel 对应变量DB2 JDBC trace constants

Trace Constant	Integer Value
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_NONE	0
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_CONNECTION_CALLS	1
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_STATEMENT_CALLS	2
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_RESULT_SET_CALLS	4
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_DRIVER_CONFIGURATION	16
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_CONNECTS	32
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_DRDA_FLOWS	64
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_RESULT_SET_META_DATA	128
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_PARAMETER_META_DATA	256
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_DIAGNOSTICS	512
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_SQLJ	1024
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_XA_CALLS**	2048
com.ibm.db2.jcc.DB2BaseDataSource.TRACE_ALL	-1

缺省JDBC Drive会从 CLASSPATH环境变量指定目录中，查找DB2JccConfiguration.properties文件内容，或者指定参数db2.jcc.propertiesFile设置查找指定文件。

命令行使用方法样例如下：

java -Ddb2.jcc.propertiesFile=jcc.properties JccTraceExample

WAS数据源中配置方法如下：

1) Set the trace properties for JDBC in WebSphere Application Server

In the administration console, go to
Resources > JDBC Provider > Data Sources > (Data source name) > Additional Properties > Custom Properties
Set: traceLevel to -1 (-1 means full trace, TRACE_ALL)

2) Start the trace, by enabling WebSphere diagnostic trace

In the administration console, go to
Troubleshooting > Logs and Trace > (select the server) > Diagnostic Trace

Trace Specification:

v6 or later: *=info:WAS.j2c=all:RRA=all:WAS.database=all:Transaction=all
v5: RRA=all=enabled:WAS.database=all=enabled:J2C=all=enabled

DB2服务器端快照SNAPSHOT查找执行时长SQL

DB2根据动态 SQL 语句快照，找到排序多、溢出多的 SQL 语句

收集动态SQL快照语句如下

db2 get snapshot for dynamic SQL on DBNAME

收集数据，一条语句执行了一次，执行时间花费了 7.6 秒，Rows Read=1099018, Rows Written= 99011。排序发生了一次，溢出一次。注意：此应用仅执行一次，如果执行多次，花费时间就是多次执行的合计值。

Number of executions               = 1
Number of compilations             = 1
Worst preparation time (ms)        = 134
Best preparation time (ms)         = 134
Internal rows deleted              = 0
Internal rows inserted             = 0
Rows read                          = 1099018
Internal rows updated              = 0
Rows written                       = 99011
Statement sorts                    = 1
Statement sort overflows           = 1
Total sort time                    = 204
Buffer pool data logical reads     = 30561
Buffer pool data physical reads    = 2367
Buffer pool temporary data logical reads   = 1792
Buffer pool temporary data physical reads = 1
Buffer pool index logical reads    = 35
Buffer pool index physical reads   = 27
Buffer pool temporary index logical reads = 0
Buffer pool temporary index physical reads = 0
Buffer pool xda logical reads      = 0
Buffer pool xda physical reads     = 0
Buffer pool temporary xda logical reads    = 0
Buffer pool temporary xda physical reads   = 0
Total execution time (sec.microsec)= 7.612814
Total user cpu time (sec.microsec) = 0.938412
Total system cpu time (sec.microsec)= 0.000000
Total statistic fabrication time (milliseconds) = 0
Total synchronous runstats time (milliseconds) = 0
Statement text                     = SELECT dept_id, name FROM db2inst1.employee
WHERE dept_id < 100 ORDER BY dept_id

注意：收集前，请开启SNAPSHOT监控

db2 update monitor switches using BUFFERPOOL on LOCK on SORT on STATEMENT on TIMESTAMP on TABLE on UOW on

关闭SNAPSHOT监控命令

db2 update monitor switches using BUFFERPOOL off LOCK off SORT off STATEMENT off TIMESTAMP off TABLE off UOW off

查看快照监控状态

db2 get monitor switches

DB2服务器端监控视图及表函数查找执行时长SQL

可以使用DB2 9.7及之后新增的监控视图，查找信息

监控视图APPLICATIONS ，检索应用连接显示执行状态、时长及SQL

select APPLICATION_HANDLE, APPLICATION_NAME, ELAPSED_TIME_SEC, ACTIVITY_STATE, QUERY_COST_ESTIMATE, STMT_TEXT from sysibmadm.mon_current_sql

以下是输出结果

31452 db2bp 0 EXECUTING 1 select APPLICATION_HANDLE, APPLICATION_NAME, ELAPSED_TIME_SEC, ACTIVITY_STATE, QUERY_COST_ESTIMATE, STMT_TEXT from sysibmadm.mon_current_sql
31233 db2jcc_application 26 IDLE 39825 SELECT T1.TOTALTAX, T1.LOCKED, T1.TOTALTAXSHIPPING, T1.STATUS, T1.FIELD2, T1.TIMEPLACED, T1.FIELD3, T1.CURRENCY, T1.SEQUENCE, T1.TOTALADJUSTMENT, T1.ORMORDER, T1.SHIPASCOMPLETE, T1.PROVIDERORDERNUM, T1.TOTALPRODUCT, T1.DESCRIPTION, T1.MEMBER_ID, T1.ORGENTITY_ID, T1.FIELD1, T1.STOREENT_ID, T1.ORDCHNLTYP_ID, T1.ADDRESS_ID, T1.LASTUPDATE, T1.ORDERS_ID, T1.COMMENTS, T1.NOTIFICATIONID, T1.TYPE, T1.EDITOR_ID, T1.OPTCOUNTER, T1.SOURCEID, T1.EXPIREDATE, T1.BUSCHN_ID, T1.BLOCKED, T1.TOTALSHIPPING, T1.TRANSFERSTATUS, T1.OPSYSTEM_ID, T1.BUYERPO_ID FROM ORDERS T1 WHERE (T1.STATUS = ?)

监控视图APPLICATIONS ，检索应用连接的状态、地址等信息

select substr(A.AUTHID,1,10) as AUTH_ID, substr(A.APPL_NAME,1,20) as app_name, A.AGENT_ID as APP_HANDLE, substr(A.APPL_ID,1,25) as APPLICATION_ID, substr(A.APPL_STATUS,1,15) as status, A.STATUS_CHANGE_TIME, second(current timestamp-A.STATUS_CHANGE_TIME) as SEC_IN_STATUS, substr(A.CLIENT_NNAME,1,15) as CLIENT_NNAME from SYSIBMADM.APPLICATIONS A with ur

以下是输出结果

AUTH_ID    APP_NAME             APP_HANDLE           APPLICATION_ID               STATUS          STATUS_CHANGE_TIME         SEC_IN_STATUS CLIENT_NNAME
---------- -------------------- -------------------- ---------------------------- --------------- -------------------------- ------------- ---------------
DB2INST1   db2bp                               55809 *LOCAL.db2inst1.130307034    UOWEXEC         2013-03-06-23.38.21.759104             0 sigma-dev-db01
WSCOMUSR   db2jcc_application                  55789 100.159.65.4.57849.130307030 UOWWAIT         2013-03-06-23.30.00.212507            21 sigma-dev-app01
WSCOMUSR   db2stmm                             55335 *LOCAL.DB2.130306094532      UOWWAIT         2013-03-06-23.36.55.997962            25 sigma-dev-app01
WSCOMUSR   db2jcc_application                  55334 100.159.65.4.55535.130306094 UOWWAIT         2013-03-06-23.35.00.155727            21 sigma-dev-app01
WSCOMUSR   db2jcc_application                  55347 100.159.65.4.55612.130306094 UOWWAIT         2013-03-06-23.30.00.209638            21 sigma-dev-app01
WSCOMUSR   db2jcc_application                  55662 100.159.65.4.57212.130306220 UOWWAIT         2013-03-06-23.30.00.210223            21 sigma-dev-app01
WSCOMUSR   db2jcc_application                  55458 100.159.65.4.56161.130306140 UOWWAIT         2013-03-06-23.35.53.351758            28 sigma-dev-app01
WSCOMUSR   db2fw0                              55339 *LOCAL.DB2.130306094536      UOWWAIT         2013-03-06-04.45.32.972073            48 sigma-dev-app01
WSCOMUSR   db2jcc_application                  55661 100.159.65.4.57211.130306220 UOWWAIT         2013-03-06-23.30.00.206092            21 sigma-dev-app01
WSCOMUSR   db2lused                            55338 *LOCAL.DB2.130306094535      UOWWAIT         2013-03-06-23.30.58.412692            23 sigma-dev-app01
WSCOMUSR   db2wlmd                             55337 *LOCAL.DB2.130306094534      CONNECTED       2013-03-06-04.45.32.830828            48 sigma-dev-app01
WSCOMUSR   db2jcc_application                  55343 100.159.65.4.55607.130306094 UOWWAIT         2013-03-06-23.35.00.162591            21 sigma-dev-app01
WSCOMUSR   db2taskd                            55336 *LOCAL.DB2.130306094533      UOWWAIT         2013-03-06-23.35.55.966370            25 sigma-dev-app01
WSCOMUSR   db2jcc_application                  55737 100.159.65.4.57593.130307010 UOWWAIT         2013-03-06-23.30.00.208060            21 sigma-dev-app01

监控表函数 mon_get_pkg_cache_stmt，执行时间最长的SQL，仅显示前五名

select stmt_exec_time, num_executions, stmt_textfrom table(mon_get_pkg_cache_stmt(null,null,null,-2)) as s order by stmt_exec_time desc fetch first 5 rows only

监控表函数 mon_get_pkg_cache_stmt，消耗CPU时间最长的SQL，仅显示前五名

select stmt_exec_time, num_executions,(total_cpu_time / 1000) as cpu_time,stmt_textfrom table(mon_get_pkg_cache_stmt(null,null,null,-2)) as s order by cpu_time desc fetch first 5 rows only

监控表函数 mon_get_pkg_cache_stmt，消耗IO最长的SQL，仅显示前五名

select stmt_exec_time, num_executions,(pool_read_time + pool_write_time+direct_read_time + direct_write_time) as io_timefrom table(mon_get_pkg_cache_stmt(null,null,null,-2)) as t order by io_time desc fetch first 5 rows only

DB2服务器端按连接动态跟踪开启

如果能确定DB2端数据库连接ID，可以开启动态跟踪，收集详细信息，如下命令开启及关闭。

db2 connect to sample
APPID=`db2 -x "select application_id() from sysibm.sysdummy1"`
db2trc on -f db2trc.dmp -appid $APPID
db2 "select * from sysibmadm.snaplock"
db2trc off

注意：生产环境谨慎使用，对性能有影响

收集完成后，需要对跟踪输出文件格式化，使用如下命令

db2trc flw db2trc.dmp db2trc.flw

db2trc fmt db2trc.dmp db2trc.fmt

TCPDUMP收集SQL语句

如果客户环境有类似天旦这样的系统，可以从网络包文捕获相关SQL语句。如果通信采用SSL加密，就有难度，理论通过SSL加密证书可以解密

使用tcpdump

tcpdump -i eth0 -s 0 -l -w out.log port 50000

以下是相关参数

-i 网卡设备
-w 写入管道,将抓包数据输出到文件中而不是标准输出,
- dst 抓取
port 端口号
-l 将标准输出转换为缓冲行形式
-s snaplen表示从一个包中截取的字节数。0表示包不截断，抓完整的数据包。默认的话 tcpdump 只显示部分数据包,默认68字节
-x 把协议头和包内容都原原本本的显示出来,会以16进制和ASCII两种方式同时输出
-nn 指定将每个监听到的数据包中的域名转换成IP、端口从应用名称转换成端口号后显示
-r：从给定的数据包文件中读取数据。使用"-"表示从标准输入中读取
-tttt 使时间戳格式更加可读
-c 在收到指定的包的数目后，tcpdump就会停止
-q：快速打印输出

使用tcpdump以ASCII格式打印出所有的分组并且读取文件

tcpdump -A -r out.log

以下是找到的SELECT语句

以下是SQL查询结果也可以看到

以下是wireshark工具分析结果

以下是tcpdump收集mysql的相关sql的脚本，仅供参考

tcpdump -i eth0 -s 0 -l -w out.log port 3306 | strings | perl -e '
#!/bin/bash
while(<>) { chomp; next if /^[^ ]+[ ]*$/;
if(/^(SELECT|UPDATE|DELETE|INSERT|SET|COMMIT|ROLLBACK|CREATE|DROP|ALTER|CALL)/i) {
if (defined $q) { print "$q/n" ; }
$q=$_;
} else {
$_ =~ s/^[ /t]+//; $q.=" $_" ;
}
}'