近期遇到一客户反映业务系统出现卡顿;使用的是oracle rac,应用是WINDOWS上的程序;遇到这种问题常规的处理思路无非就是查找卡顿时间点数据库的运行情况,找到程序执行对应的SQL是否出现缓慢等来进行处理。
本次问题诡异之处在于数据库角度来看没有执行速度大于1S的SQL,使用10046 trace跟踪指定客户机上的应用程序,在应用程序上手动进行业务操作,此时trace日志来看SQL执行没有速度慢的,应用程序表现无响应(持续几十秒到10几分钟)。
后面使用应用程序debug模式,把应用程序执行业务流程继续细化到每一步函数调用等,对应的在数据库做10046 trace,生成每一步函数调用的trace信息。开发人员从对应的SQL中发现了应用慢时业务涉及的一张表有CLOB字段,此CLOB字段中的内容大小不一相关较大,少的几K多的几十MB,数据库端执行速度快,但是返回数据多时客户端程序即慢、无响应。
处理方法:开发人员也不了解此列作用,通过RENAM此列,并新建同名的空列的方式,临时处理了此问题(即备份、清空了此列数据)。 后续在找到原因后再看10046 trace中相应的信息,发现对应SQL执行时有相应LOB读取,但是SQL执行速度较快就被忽略了。回想起几年前也有客户在自己电脑上使用PLSQL DEV工具查询一张大表,点显示全部数据过一会电脑就卡死机了,当时让打开任务管理器然后让再次执行PLSQL DEV中语句,可以观察到WINDOWS 内存使用率直线上升,CPU使用率也开始上涨直到卡住;
经验教训:后面搜索个人的历史文档发现之前遇到过PLSQL DEV查大表时客户端卡住、LOB字段对应的’SQL*Net message from client’ 等类似问题还收藏了相应的MOS文档,但是遗憾的是没有第一时间往这方面考虑排查;也需要反思一下我们通常的ORACLE数据库问题分析时一般都是看SQL执行时间效率,客户端主机性能、中间的网络层都会被考虑;但是很少分析返回几行数据每行数据量多少,返回数据行数多、数据量大时客户端程序可能处理不过来;以后遇到客户端反应慢时要考虑到此问题。
附相应的10046 trace及MOS上一篇关于此种情况LOB相关的文档:
“Direct path read” Wait Event During LOB Access (文档 ID 2287482.1) High ‘SQL*Net message from client’ when querying LOB tables (文档 ID 1590389.1)
问题10046 TRACE文件的信息:
SQL ID: 19bq18qskngd1 Plan Hash: 3456281917
SELECT ………………
FROM
ABC_MERGE E WHERE E.ABC_KEY IN (:0,:1)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 3 0.00 0.00 0 8 0 2
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.00 0.00 0 8 0 2
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 90
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
2 2 2 INLIST ITERATOR (cr=8 pr=0 pw=0 time=88 us)
2 2 2 TABLE ACCESS BY INDEX ROWID ABC_MERGE (cr=8 pr=0 pw=0 time=134 us cost=6 size=1264 card=2)
2 2 2 INDEX UNIQUE SCAN PK_ABC_MERGE (cr=6 pr=0 pw=0 time=93 us cost=4 size=0 card=2)(object id 92717)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message from client 5 66.64 66.79
SQL*Net message to client 4 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 1 2 1
Fetch 5 0.00 0.00 0 20 0 37
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 13 0.00 0.00 0 21 2 38
Misses in library cache during parse: 0
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message from client 1579 66.64 68.32 ===>>
SQL*Net message to client 1579 0.00 0.00
Disk file operations I/O 22 0.00 0.00
direct path read 3255 0.00 0.32 ===>>
gc cr block 2-way 1 0.00 0.00
log file sync 1 0.00 0.00