一条简单的sql语句运行15天的原因分析(r5笔记第17天)
在测试环境中,可能一个测试库中会有几十上百套环境在运行,一般DBA不会去主动干涉测试环境中的一些使用细节,可能问题都是开发测试来反馈给DBA采取做一个被动的处理。今天也算主动了一把,在测试环境中发现了一个大案。 首先通过ash查看了下正在运行的session情况,可以很明显看到有几条sql语句竟然已经执行了15天,没错不是15个小时,是15天。 对于这种情况,很让人有一种立马出手的冲动。不过先来看看问题,已经15天了,也不在这几分钟着急了。
> ksh getash.sh
I SID SER# USERNAME OSUSER STA RPID SPID MACHINE PROGRAM ELAP_SEC TEMP_MB UNDO_MB SQL_ID TSPS SQL
-- ------ ------ ------------ ---------- --- ------- ------ ---------- -------------------- ----------- ------- ------- ------------- ------ -------------------------------------------------
1 3030 8253 xxxx xxxxxxxx ACT 1234 19645 testser JDBC Thin Client 15 16:54:42 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 4353 2389 xxxx xxxxxxxx ACT 1234 7945 testser JDBC Thin Client 15 16:54:42 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 4921 483 xxxx xxxxxxxx ACT 1234 29822 testser JDBC Thin Client 15 16:54:42 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 7375 14169 xxxx xxxxxxxx ACT 1234 4290 testser JDBC Thin Client 15 16:54:39 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 4538 221 xxxx xxxxxxxx ACT 1234 17126 testser JDBC Thin Client 15 16:46:38 dch8sxwt6ujvc /* CL_ProcessController_updateProcessById_2 */ UP
1 957 17975 xxxx xxxxxxxx ACT 16397 18807 testser rman@xxxx (TNS V 00 00:00:11 0004568 STARTED62,
1 2277 47527 xxxx xxxxxxxx ACT 17531 17748 testser rman@xxxx (TNS V 00 00:00:02 0003367 STARTED62,
1 3790 34667 xxxx xxxxxxxx ACT 32656 32658 testser sqlplus@xxxx (TN 00 00:00:01 4k5y59ywjtuhs SELECT /* use_hash(sess,proc,undo,tmp) use_nl(s)*
首先让我好奇的是这么长时间的语句,是不是表里的数据量太多了,执行计划出现了很大的性能问题?之前碰到过几次语句问题导致sql运行了好几天的情况,带着疑问来看了下对应的sql语句,是一个简单的update操作。
SQL_ID dch8sxwt6ujvc, child number 0
-------------------------------------
/* CL_ProcessController_updateProcessById_2 */ UPDATE CL1_PROC_CTRL SET
CL1_PROC_CTRL.PROC_CTRL_ID = :1 , CL1_PROC_CTRL.HEARTBEAT = :2 ,
CL1_PROC_CTRL.STATUS = :3 , CL1_PROC_CTRL.PROC_TYPE = :4 , OPERATOR_ID
= :5 , APPLICATION_ID = :6 , DL_SERVICE_CODE = :7 , DL_UPDATE_STAMP =
:8 , SYS_UPDATE_DATE = SYSDATE WHERE PROC_CTRL_ID = :9
看来核心因素就聚集在表CL1_PROC_CTRL 上了,这是个什么级别的表,是不是数据太多了啊。一查让我大吃一惊,不是数据多,而是只有5条数据。
查看执行计划一看也是无可挑剔的。
-----------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost |
-----------------------------------------------------------------------
| 0 | UPDATE STATEMENT | | | | 1 |
| 1 | UPDATE | CL1_PROC_CTRL | | | |
|* 2 | INDEX UNIQUE SCAN| CL1_PROC_CTRL_PK | 1 | 47 | 1 |
-----------------------------------------------------------------------
好了问题到了这,很多人已经猜出问题所在了,我就继续卖个关子,机会难得,来先看看等待事件吧,这种情况下看等待事件还是一个很有效的方式,直接关联v$session_event来查看。
set linesize 200
col event format a30
col sql_text format a50
set pages 50
select distinct s.sql_id,s.sid,se.event,se.TOTAL_WAITS,sa.sql_text
from v$session s left join v$session_event se
on s.sid=se.sid
left join v$sqlarea sa
on s.sql_id=sa.sql_id
where sa.SQL_TEXT is not null
and sa.sql_id='dch8sxwt6ujvc'
order by se.total_waits desc;
SQL_ID SID EVENT TOTAL_WAITS
------------- ---------- ------------------------------ -----------
dch8sxwt6ujvc 4538 SQL*Net message from client 7371
dch8sxwt6ujvc 4538 SQL*Net message to client 7371
dch8sxwt6ujvc 3030 SQL*Net message from client 3634
dch8sxwt6ujvc 3030 SQL*Net message to client 3634
dch8sxwt6ujvc 7375 SQL*Net message from client 1398
dch8sxwt6ujvc 7375 SQL*Net message to client 1398
dch8sxwt6ujvc 4353 SQL*Net message from client 1386
dch8sxwt6ujvc 4353 SQL*Net message to client 1386
dch8sxwt6ujvc 4921 SQL*Net message to client 1318
dch8sxwt6ujvc 4921 SQL*Net message from client 1318
dch8sxwt6ujvc 4538 log file sync 1111
dch8sxwt6ujvc 3030 log file sync 908
dch8sxwt6ujvc 4538 SQL*Net more data to client 704
dch8sxwt6ujvc 4538 direct path read 661
dch8sxwt6ujvc 7375 log file sync 349
dch8sxwt6ujvc 4353 log file sync 346
dch8sxwt6ujvc 4921 log file sync 329
dch8sxwt6ujvc 4538 db file sequential read 191
dch8sxwt6ujvc 4538 Disk file operations I/O 19
dch8sxwt6ujvc 4353 db file sequential read 5
dch8sxwt6ujvc 3030 db file sequential read 5
dch8sxwt6ujvc 4353 Disk file operations I/O 4
dch8sxwt6ujvc 3030 Disk file operations I/O 4
dch8sxwt6ujvc 4921 Disk file operations I/O 4
dch8sxwt6ujvc 7375 Disk file operations I/O 4
dch8sxwt6ujvc 4921 db file sequential read 3
dch8sxwt6ujvc 7375 db file sequential read 2
dch8sxwt6ujvc 4538 db file scattered read 2
dch8sxwt6ujvc 4921 enq: TX - row lock contention 1
dch8sxwt6ujvc 4538 enq: TX - row lock contention 1
dch8sxwt6ujvc 3030 enq: TX - row lock contention 1
dch8sxwt6ujvc 7375 enq: TX - row lock contention 1
dch8sxwt6ujvc 4353 enq: TX - row lock contention 1
可以从top等待事件中看出,时间都基本在“SQL*Net message from clien”和“SQL*Net message to client",这些等待事件对于这个问题似乎说明不了什么细节的问题,继续往下看,关键在于最后的几个等待事件,是关于”enq: TX - row lock contention“的。这个问题就能说明原因了。 绕了一个圈子,我们来看看v$lock中的明细信息。可以很清晰的看出,等待的时间确实是很长了。
SID_SERIAL ORACLE_USERN OBJECT_NAME LOGON_TIM SEC_WAIT OSUSER MACHINE PROGRAM STATE STATUS LOCK_ MODE_HELD
------------ ------------ ------------------------- --------- --------- ---------- ------------ -------------------- ---------- ---------- ----- ----------
4921,483 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357778 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
3030,8253 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357778 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
4353,2389 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357777 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
7375,14169 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357774 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
4538,221 XXXXXXXX CL1_PROC_CTRL 08-APR-15 1357293 xxxxxxxx xxxxxxxx JDBC Thin Client WAITING ACTIVE DML Row-X (SX)
Blocking Session Details
1519 IS BLOCKING 3030,8253
1519 IS BLOCKING 4353,2389
1519 IS BLOCKING 4538,221
1519 IS BLOCKING 4921,483
1519 IS BLOCKING 7375,14169
可以从blocking session中看出,这个罪魁祸首的session是1519的session. 我们来看看这个session,状态是inactive的,登录时间是半个月之前了。
SID SERIAL# USERNAME OSUSER MACHINE PROCESS TERMINAL TYPE LOGIN_TIME STATUS
---------- ---------- --------------- --------------- -------------------- --------------- --------------- ---------- ------------------- --------
1519 995 XXXXXXX XXXXXXX XXXXXXX 1234 unknown USER 2015-04-08 17:19:08 INACTIVE
看来这个session是由于某种原因没有正常终止,导致剩下的几个session都挂在这个点上了。把这个问题放大,就是15天,从测试的反馈来看似乎这个环境也没有用到,所以没有得到任何反馈。
我还是和对应的team做个简单的沟通为好,然后就开始kill掉这个session.
SQL> alter system kill session '1519,995';
System altered.
kill的过程很快,再次查看v$lock中的等待哪些session等待就正常了,但是查看ash的时候发现这几个session还是存在,在blocking session的内容中,发现出现了一个新的session 380,这个session是今天创建的,看来和我kill的操作也有一定关联。
Blocking Session Details
380 IS BLOCKING 3030,8253
380 IS BLOCKING 4353,2389
380 IS BLOCKING 4538,221
380 IS BLOCKING 4921,483
380 IS BLOCKING 7375,14169
做了确认,kill掉,操作完成之后发现这个问题就修复了。那几个active的session很快就处理了,这个时候结果似乎已经不重要了。
这个案例带给我们的启示就是任何细小的问题都放大都可能造成很严重的影响,有些问题我们关注就会及时处理,有些问题忽略或者疏忽就会不断膨胀,成为一个大麻烦。DBA也需要在这个过程中去取舍,不断调整自己的状态,主动发现问题还相比于得到反馈来说要更加从容。
- Hbase源码系列之regionserver应答数据请求服务设计
- 大数据基础系列之kafkaConsumer010+的多样demo及注意事项
- 大数据基础系列之kafka011生产者缓存超时,幂等性和事务实现
- 大数据基础系列之提交spark应用及依赖管理
- 大数据集群安全系列之kafka使用SSL加密认证
- 基于zookeeper leader选举方式一
- Spark与mongodb整合完整版本
- spark源码系列之累加器实现机制及自定义累加器
- Scala语法基础之隐式转换
- SparkSql的优化器-Catalyst
- Scala语言基础之结合demo和spark讲实现链式计算
- Spark高级操作之json复杂和嵌套数据结构的操作二
- Spark高级操作之json复杂和嵌套数据结构的操作一
- hadoop系列之基础系列
- JavaScript 教程
- JavaScript 编辑工具
- JavaScript 与HTML
- JavaScript 与Java
- JavaScript 数据结构
- JavaScript 基本数据类型
- JavaScript 特殊数据类型
- JavaScript 运算符
- JavaScript typeof 运算符
- JavaScript 表达式
- JavaScript 类型转换
- JavaScript 基本语法
- JavaScript 注释
- Javascript 基本处理流程
- Javascript 选择结构
- Javascript if 语句
- Javascript if 语句的嵌套
- Javascript switch 语句
- Javascript 循环结构
- Javascript 循环结构实例
- Javascript 跳转语句
- Javascript 控制语句总结
- Javascript 函数介绍
- Javascript 函数的定义
- Javascript 函数调用
- Javascript 几种特殊的函数
- JavaScript 内置函数简介
- Javascript eval() 函数
- Javascript isFinite() 函数
- Javascript isNaN() 函数
- parseInt() 与 parseFloat()
- escape() 与 unescape()
- Javascript 字符串介绍
- Javascript length属性
- javascript 字符串函数
- Javascript 日期对象简介
- Javascript 日期对象用途
- Date 对象属性和方法
- Javascript 数组是什么
- Javascript 创建数组
- Javascript 数组赋值与取值
- Javascript 数组属性和方法
- flink教程-基于flink 1.11 使 sql客户端支持执行sql文件
- flink教程-详解flink 1.11 中的JDBC Catalog
- flink教程-flink modules详解之使用hive函数
- 面试iOS 机会在自己手中
- Flink教程-将流式数据写入redis
- Flink教程-keyby 窗口数据倾斜的优化
- Flink源码分析之深度解读流式数据写入hive
- 浙大版《C语言程序设计(第3版)》题目集 习题10-1 判断满足条件的三位数
- 差分标记-HDU1556 Color the ball
- flink cep 案例之机架温度监控报警
- 详解flink 1.11中的新部署模式-Application模式
- 浙大版《C语言程序设计(第3版)》题目集 习题10-2 递归求阶乘和
- hadoop源码解析之RPC分析
- 存储过程和触发器
- hadoop源码学习之namenode启动