执行 grant statement 命令, DB hang

当时执行的sql：grant select on xxx_user.xxx_table to xxx_user;

执行以上grant statement的时候db响应特别慢（hang），发现db出现大量的等待（latch: library cache，cursor: pin S wait on X，library cache lock）。

以下是相关的AWR报告.

	Snap Id	Snap Time	Sessions	Cursors/Session
Begin Snap:	26178	06-Nov-13 18:00:53	683	6.4
End Snap:	26179	06-Nov-13 18:30:54	683	6.4
Elapsed:		30.02 (mins)
DB Time:		24.41 (mins)

Report Summary

Cache Sizes

	Begin	End
Buffer Cache:	37,584M	37,584M	Std Block Size:	8K
Shared Pool Size:	3,296M	3,296M	Log Buffer:	14,256K

Load Profile

	Per Second	Per Transaction
Redo size:	5,139.67	4,518.17
Logical reads:	184.98	162.61
Block changes:	28.13	24.73
Physical reads:	0.42	0.37
Physical writes:	3.24	2.85
User calls:	154.48	135.80
Parses:	40.67	35.75
Hard parses:	0.15	0.13
Sorts:	1.54	1.36
Logons:	0.18	0.16
Executes:	45.74	40.20
Transactions:	1.14

这里看发现硬解析并不高。

% Blocks changed per Read:	15.21	Recursive Call %:	21.58
Rollback per transaction %:	0.00	Rows per Sort:	224.84

Instance Efficiency Percentages (Target 100%)

Buffer Nowait %:	100.00	Redo NoWait %:	100.00
Buffer Hit %:	99.78	In-memory Sort %:	100.00
Library Hit %:	98.42	Soft Parse %:	99.63
Execute to Parse %:	11.08	Latch Hit %:	99.84
Parse CPU to Parse Elapsd %:	11.13	% Non-Parse CPU:	32.12

Shared Pool Statistics

	Begin	End
Memory Usage %:	80.43	66.40
% SQL with executions>1:	99.60	98.25
% Memory for SQL w/exec>1:	92.42	87.32

Top 5 Timed Events

Event	Waits	Time(s)	Avg Wait(ms)	% Total Call Time	Wait Class
latch: library cache	262	928	3,544	63.4	Concurrency
library cache lock	112	275	2,455	18.8	Concurrency
CPU time		144		9.8
cursor: pin S wait on X	3,927	42	11	2.9	Concurrency
cursor: pin S	40,951,979	17	0	1.2	Other

以上TOP 5 Events中，主要都是与Shared Pool相关的latch 竞争。

Time Model Statistics

• Total time in database user-calls (DB Time): 1464.6s
• Statistics including the word "background" measure background process time, and so do not contribute to the DB time statistic
• Ordered by % or DB time desc, Statistic name

Statistic Name	Time (s)	% of DB Time
parse time elapsed	856.54	58.48
sql execute elapsed time	418.45	28.57
DB CPU	143.67	9.81
connection management call elapsed time	108.49	7.41
PL/SQL execution elapsed time	85.23	5.82
hard parse elapsed time	1.17	0.08
hard parse (sharing criteria) elapsed time	0.24	0.02
sequence load elapsed time	0.03	0.00
hard parse (bind mismatch) elapsed time	0.01	0.00
repeated bind elapsed time	0.01	0.00
PL/SQL compilation elapsed time	0.01	0.00
failed parse elapsed time	0.00	0.00
DB time	1,464.62
background elapsed time	21.60
background cpu time	12.89

在这里可以看到SQL的parse time elapsed 占用的时间较大,但hard parse elapsed time占用时间较小，这里可以确定不是由于硬解析造成的latch竞争。

Latch Sleep Breakdown

• ordered by misses desc

Latch Name	Get Requests	Misses	Sleeps	Spin Gets	Sleep1	Sleep2	Sleep3
shared pool	354,362	3,068	184	2,943	0	0	0
kks stats	70,249	2,178	10	2,168	0	0	0
library cache lock	261,435	888	6	882	0	0	0
library cache	130,662	755	262	497	0	0	0
qmn task queue latch	456	130	130	0	0	0	0
session allocation	58,563	47	39	10	0	0	0
cache buffers chains	612,018	21	1	20	0	0	0
process allocation	664	10	10	0	0	0	0
KWQMN job cache list latch	43	4	4	0	0	0	0
user lock	320	2	2	0	0	0	0
slave class create	20	1	1	0	0	0	0

Library Cache Activity

• "Pct Misses" should be very low

Namespace	Get Requests	Pct Miss	Pin Requests	Pct Miss	Reloads	Invali- dations
BODY	157	0.00	767	0.00	0	0
CLUSTER	12	0.00	23	0.00	0	0
SQL AREA	2,910	3.06	91,531	1.75	218	35,792
TABLE/PROCEDURE	563	1.95	10,571	0.29	13	0
TRIGGER	300	0.00	300	0.00	0	0

在这里可以发现SQL AREA中的无效对象较多，被Reloads 的次数也较大。

SGA breakdown difference

• ordered by Pool, Name
• N/A value for Begin MB or End MB indicates the size of that Pool/Name was insignificant, or zero in that snapshot

Pool	Name	Begin MB	End MB	% Diff
java	free memory	16.00	16.00	0.00
large	PX msg pool	1.03	1.03	0.00
large	free memory	14.97	14.97	0.00
shared	CCursor	303.22	213.18	-29.70
shared	KTI-UNDO	48.83	48.83	0.00
shared	PCursor	202.59	178.07	-12.10
shared	db_block_hash_buckets	360.00	360.00	0.00
shared	event statistics per sess	59.71	59.71	0.00
shared	free memory	645.07	1,107.57	71.70
shared	kglsim object batch	56.89	56.89	0.01
shared	library cache	148.08	143.32	-3.21
shared	private strands	91.58	91.58	0.00
shared	sessions	34.70	34.70	0.00
shared	sql area	954.64	613.50	-35.73
streams	Sender info	1.36	1.36	0.00
streams	free memory	31.78	31.78	0.00
	buffer_cache	37,584.00	37,584.00	0.00
	fixed_sga	2.08	2.08	0.00
	log_buffer	13.92	13.92	0.00

以上可以看到shared的 free memory 由645.07m上升到1,107.57m。

总结下来，可以确定可能是由于过度的软解析造成Shared Pools的相关latch竞争，因为grant命令改变了对象的权限信息，导致大量的sql进行了软解析。

Oracle Database 10g Enterprise Edition Release 10.2.0.5.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options

SQL> set lines 120
SQL> select session_id,sql_id,session_type,session_state,event
  2    from v$active_session_history
  3   where sample_time >=
  4         to_date('2013-11-06 18:02:00', 'yyyy-mm-dd hh24:mi:ss')
  5     and sample_time <=
  6         to_date('2013-11-06 18:09:00', 'yyyy-mm-dd hh24:mi:ss')
  7     and event is not null
  8     and event in ('latch: library cache',
  9                   'cursor: pin S wait on X',
10                   'library cache lock');

SESSION_ID SQL_ID        SESSION_TY SESSION EVENT
---------- ------------- ---------- ------- ----------------------------------------------------------
  5843     ff9yk9p2xgqqj     FOREGROUND     WAITING     latch: library cache         
  5864     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  5877     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6017     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6188     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6238     2fry4cd25dnbx     FOREGROUND     WAITING     latch: library cache         
  6501     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  5843     ff9yk9p2xgqqj     FOREGROUND     WAITING     latch: library cache         
  5864     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  5877     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6017     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6188     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6238     2fry4cd25dnbx     FOREGROUND     WAITING     latch: library cache         
  6501     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  5843     ff9yk9p2xgqqj     FOREGROUND     WAITING     latch: library cache         
  5864     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  5877     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6188     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6238     2fry4cd25dnbx     FOREGROUND     WAITING     latch: library cache         
  5843     ff9yk9p2xgqqj     FOREGROUND     WAITING     latch: library cache         
  5864     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  5877     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6188     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6238     2fry4cd25dnbx     FOREGROUND     WAITING     latch: library cache         
  5843     ff9yk9p2xgqqj     FOREGROUND     WAITING     latch: library cache         
  5864     2fry4cd25dnbx     FOREGROUND     WAITING     cursor: pin S wait on X         
  6238     2fry4cd25dnbx     FOREGROUND     WAITING     latch: library cache         
  6238     2fry4cd25dnbx     FOREGROUND     WAITING     latch: library cache         
  5823     cpj497kjx0dya     FOREGROUND     WAITING     latch: library cache         
  5843     cpj497kjx0dya     FOREGROUND     WAITING     library cache lock     5851     17875
  5864     2fry4cd25dnbx     FOREGROUND     WAITING     latch: library cache         
  5877     2fry4cd25dnbx     FOREGROUND     WAITING     library cache lock     5851     17875
  6017                                        FOREGROUND     WAITING     latch: library cache         
  6047     cpj497kjx0dya     FOREGROUND     WAITING     library cache lock     5851     17875
  6061                                        FOREGROUND     WAITING     latch: library cache         
  6110     ff9yk9p2xgqqj     FOREGROUND     WAITING     library cache lock     5851     17875    
  6261     cdmx52fnhqc8v     FOREGROUND     WAITING     library cache lock     5851     17875
  6293     cpj497kjx0dya     FOREGROUND     WAITING     latch: library cache         
  6349     6uhqu7cj1mkhm     FOREGROUND     WAITING     library cache lock     5851     17875
  6360     b99w0dykagkhc     FOREGROUND     WAITING     latch: library cache         
  6375     b99w0dykagkhc     FOREGROUND     WAITING     latch: library cache         
  6421     cpj497kjx0dya     FOREGROUND     WAITING     library cache lock     5851     17875
  6471     cpj497kjx0dya     FOREGROUND     WAITING     library cache lock     5851     17875
  6530                                        FOREGROUND     WAITING     latch: library cache         
  6533     bus6ugbbxm8n0     FOREGROUND     WAITING     library cache lock     5851     17875
  5823     cpj497kjx0dya     FOREGROUND     WAITING     latch: library cache         
  5843     cpj497kjx0dya     FOREGROUND     WAITING     library cache lock     5851     17875
  5877     2fry4cd25dnbx     FOREGROUND     WAITING     library cache lock     5851     17875
  6047     cpj497kjx0dya     FOREGROUND     WAITING     library cache lock     5851     17875
  6061                                        FOREGROUND     WAITING     latch: library cache         
  6110     ff9yk9p2xgqqj     FOREGROUND     WAITING     library cache lock     5851     17875
     
      

select sql_id, sql_text
  from v$sqlarea
where sql_id = 'ff9yk9p2xgqqj'
union all
select sql_id, sql_text
  from v$sqlarea
where sql_id = '2fry4cd25dnbx'
union all
select sql_id, sql_text from v$sqlarea where sql_id = '1wpryzh4nhudp';
sql_id                                    sql_text
---------------------------------------------------------------------
ff9yk9p2xgqqj     INSERT INTO bb_INFO (........) VALUES(:B9 ,:B8 ,:B7 ,:B6 ,1,:B5 , :B4 ,:B3 ,:B2 ,:B1 )
2fry4cd25dnbx     select ......   from bb_login t, bb_info t2 where t.uin = t2.uin and t2.uin = :1
1wpryzh4nhudp     select ......  from bb_info  where uin = :1 

运行以上sql查询sql text ,都是和grant 相关对象的select 语句,PROCEDURE 程序。

sys@ACCDB0> select owner, object_name, last_ddl_time
  2    from dba_objects
  3   where object_name = upper('user_certification_info');

OWNER                          OBJECT_NAME                    LAST_DDL_TIME
------------------------------ ------------------------------ -------------------
bb00                          bb_INFO        2013-11-06 18:03:12
bb02                         bb_INFO        2013-11-06 18:07:04
bb04                          bb_INFO        2013-11-06 18:08:28

也可以看出当对objects执行grant命令后，其实是对此objects执行了DDL。

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/26390465/viewspace-1777471/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/26390465/viewspace-1777471/