执行 grant statement 命令, DB hang.

hellbebe 发表于 2013-11-19 14:19:35

本帖最后由 hellbebe 于 2013-11-20 09:41 编辑

当时执行的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进行了软解析。

请各位大师，刘大指正。谢谢

Maclean Liu(刘相兵 发表于 2013-11-19 14:29:56

1、任何问题请至少给出版本信息
2、请上传完整的AWR 和当时的ASH报告

hellbebe 发表于 2013-11-19 14:39:48

Maclean Liu(刘相兵发表于 2013-11-19 14:29 static/image/common/back.gif
1、任何问题请至少给出版本信息
2、请上传完整的AWR 和当时的ASH报告

上传了，谢谢！

Maclean Liu(刘相兵 发表于 2013-11-19 15:12:39

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有较多的 Invali- dations ，需要明确这些 Invali- dations是否与grant有关

Maclean Liu(刘相兵 发表于 2013-11-19 15:13:25

收集如下信息并上传：
oradebug setmypid
oradebug unlimit;
alter session set events 'immediate trace name systemstate level 266';
alter session set events 'immediate trace name library_cache level 11';
alter session set events 'immediate trace name cursordump level 16';
oradebug tracefile_name;

还有需要ASH

hellbebe 发表于 2013-11-20 09:42:34

Maclean Liu(刘相兵发表于 2013-11-19 15:13 static/image/common/back.gif
收集如下信息并上传：
oradebug setmypid
oradebug unlimit;

上传了ash。
oradebug setmypid
oradebug unlimit;
alter session set events 'immediate trace name systemstate level 266';
alter session set events 'immediate trace name library_cache level 11';
alter session set events 'immediate trace name cursordump level 16';
oradebug tracefile_name;
现在设置这些还可以吗？

hellbebe 发表于 2013-11-20 09:43:35

Maclean Liu(刘相兵发表于 2013-11-19 15:12 static/image/common/back.gif
Library Cache Activity
"Pct Misses" should be very low
Namespace Get Requests Pct Miss Pin Requests    ...

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
   5864 2fry4cd25dnbx FOREGROUND WAITING latch: library cache
   5877 2fry4cd25dnbx FOREGROUND WAITING library cache lock
   6017             FOREGROUND WAITING latch: library cache
   6047 cpj497kjx0dya FOREGROUND WAITING library cache lock
   6061             FOREGROUND WAITING latch: library cache
   6110 ff9yk9p2xgqqj FOREGROUND WAITING library cache lock
   6126 2fry4cd25dnbx FOREGROUND WAITING latch: library cache
   6179 b99w0dykagkhc FOREGROUND WAITING latch: library cache
   6188 2fry4cd25dnbx FOREGROUND WAITING latch: library cache
   6238 2fry4cd25dnbx FOREGROUND WAITING latch: library cache
   6261 cdmx52fnhqc8v FOREGROUND WAITING library cache lock
   6293 cpj497kjx0dya FOREGROUND WAITING latch: library cache
   6349 6uhqu7cj1mkhm FOREGROUND WAITING library cache lock
   6360 b99w0dykagkhc FOREGROUND WAITING latch: library cache
   6375 b99w0dykagkhc FOREGROUND WAITING latch: library cache
   6421 cpj497kjx0dya FOREGROUND WAITING library cache lock
   6471 cpj497kjx0dya FOREGROUND WAITING library cache lock
   6530             FOREGROUND WAITING latch: library cache
   6533 bus6ugbbxm8n0 FOREGROUND WAITING library cache lock
   5823 cpj497kjx0dya FOREGROUND WAITING latch: library cache
   5843 cpj497kjx0dya FOREGROUND WAITING library cache lock
   5877 2fry4cd25dnbx FOREGROUND WAITING library cache lock
   6047 cpj497kjx0dya FOREGROUND WAITING library cache lock
   6061             FOREGROUND WAITING latch: library cache
   6110 ff9yk9p2xgqqj FOREGROUND WAITING library cache lock
   6126 2fry4cd25dnbx FOREGROUND WAITING latch: library cache
   6179 b99w0dykagkhc FOREGROUND WAITING latch: library cache
   6238 2fry4cd25dnbx FOREGROUND WAITING latch: library cache
   6261 cdmx52fnhqc8v FOREGROUND WAITING library cache lock
   6293 cpj497kjx0dya FOREGROUND WAITING latch: library cache
   6349 6uhqu7cj1mkhm FOREGROUND WAITING library cache lock
   6375 b99w0dykagkhc FOREGROUND WAITING latch: library cache
.....................



SQL>select * from v$sqlarea where sql_id in ('1wpryzh4nhudp','cpj497kjx0dya','bus6ugbbxm8n0','gkjabmxaxa4p0');
------------------------------------------------------------------------

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

Maclean Liu(刘相兵 发表于 2013-11-20 10:27:24

Top Blocking Sessions

Blocking session activity percentages are calculated with respect to waits on enqueues, latches and "buffer busy" only
'% Activity' represents the load on the database caused by a particular blocking session
'# Samples Active' shows the number of ASH samples in which the blocking session was found active.
'XIDs' shows the number of distinct transaction IDs sampled in ASH when the blocking session was found active.
Blocking Sid % Activity Event Caused % Event User Program # Samples Active XIDs
5851,17875 19.21 library cache lock 19.21 SYS plsqldev.exe 112/480 [ 23%] 1

SQL Command Type Distinct SQLIDs % Activity Avg Active Sessions
SELECT 21 36.51 1.12
INSERT 9 15.19 0.46
PL/SQL EXECUTE 7 12.94 0.40
GRANT 6 7.49 0.23
UPDATE 5 2.93 0.09

看起来确实是 grant引起的，但需要追踪一下为了grant 也被阻塞了

hellbebe 发表于 2013-11-20 10:41:00

Maclean Liu(刘相兵发表于 2013-11-20 10:27 static/image/common/back.gif
Top Blocking Sessions

Blocking session activity percentages are calculated with respect to waits on ...

谢谢刘大！另外请教一下，您是如何通过ash确认是grant导致，因为当时是我执行grant，如果是别的dba执行，我就没招了，哈！

可以这样猜测吗？与此次grant相关的存储过程/sql正在执行(应该持有shared cursor 的library cache lock/pin，还持有与shared cursor相关的objects 对象的lock/pin)，此时执行grant需要修改shred cursor的权限列表导致。

hellbebe 发表于 2013-11-20 10:57:38

hellbebe 发表于 2013-11-20 10:41 static/image/common/back.gif
谢谢刘大！另外请教一下，您是如何通过ash确认是grant导致，因为当时是我执行grant，如果是别的dba执行， ...

通过blocking_session？

hellbebe 发表于 2013-11-20 11:00:25

另外为什么会出现执行grant导致竞争呢？是因为并发量大吗？

hellbebe 发表于 2013-11-20 16:46:52

没有人回复了？

Maclean Liu(刘相兵 发表于 2013-11-20 21:03:35

如果您的环境中恰好无法利用dbms_shared_pool.purge存储过程，我们也可以采用一些折中的方法来清除游标缓存；譬如通过一个无关紧要的grant/revoke操作,但这样也会造成所有该授权/撤职对象相关SQL的执行计划失效:
SQL> alter system flush shared_pool;

系统已更改。

SQL> select /* cache_me */  count(*)  from youyus;

  COUNT(*)
----------
      9

SQL> select sql_id,
  2       address,
  3       hash_value,
  4       executions,
  5       loads,
  6       version_count,
  7       invalidations,
  8       parse_calls,
  9       plan_hash_value
10 from v$sqlarea
11 where sql_text like '%cache_me%'
12    and sql_text not like '%v$sqlarea%';

SQL_ID       ADDRESS  HASH_VALUE EXECUTIONS    LOADS VERSION_COUNT INVALIDATIONS PARSE_CALLS PLAN_HASH_VALUE
------------- -------- ---------- ---------- ---------- ------------- ------------- ----------- ---------------
25asu5a76nqmn 2F540EA0 2389334644       1       1          1          0          1    2542806819

SQL> select address,operation,to_char(timestamp,'HH24:MI:SS') from v$sql_plan where plan_hash_value= 2542806819;

ADDRESS  OPERATION                                                 TO_CHAR(
-------- ------------------------------------------------------------ --------
2F540EA0 SELECT STATEMENT                                           13:39:28
2F540EA0 SORT                                                       13:39:28
2F540EA0 TABLE ACCESS                                              13:39:28

SQL> revoke select on youyus from scott;

撤销成功。

SQL> select sql_id,
  2       address,
  3       hash_value,
  4       executions,
  5       loads,
  6       version_count,
  7       invalidations,
  8       parse_calls,
  9       plan_hash_value
10 from v$sqlarea
11 where sql_text like '%cache_me%'
12    and sql_text not like '%v$sqlarea%';

SQL_ID       ADDRESS  HASH_VALUE EXECUTIONS    LOADS VERSION_COUNT INVALIDATIONS PARSE_CALLS PLAN_HASH_VALUE
------------- -------- ---------- ---------- ---------- ------------- ------------- ----------- ---------------
25asu5a76nqmn 2F540EA0 2389334644       1       1          1          1          1    2542806819

/*授权/撤销会造成执行计划invalid，此处 INVALIDATIONS上升到1*/

SQL> select /* cache_me */  count(*)  from youyus;

  COUNT(*)
----------
      9
/*重新执行SQL，将引发一次硬解析*/
SQL> select address,operation,to_char(timestamp,'HH24:MI:SS') from v$sql_plan where plan_hash_value= 2542806819;

ADDRESS  OPERATION                                                 TO_CHAR(
-------- ------------------------------------------------------------ --------
2F540EA0 SELECT STATEMENT                                           13:40:23
2F540EA0 SORT                                                       13:40:23
2F540EA0 TABLE ACCESS                                              13:40:23

/*执行计划的时间戳发生了变化，达到了重新解析游标的目的*/

FYI

http://www.askmaclean.com/archives/oracle%E4%B8%AD%E6%B8%85%E9%99%A4%E6%B8%B8%E6%A0%87%E7%BC%93%E5%AD%98%E7%9A%84%E5%87%A0%E7%A7%8D%E6%96%B9%E6%B3%95.html

hellbebe 发表于 2013-11-21 10:16:26

明白了，谢了刘大

hellbebe 发表于 2013-11-21 10:43:31

Maclean Liu(刘相兵发表于 2013-11-20 21:03 static/image/common/back.gif
如果您的环境中恰好无法利用dbms_shared_pool.purge存储过程，我们也可以采用一些折中的方法来清除游标缓存 ...

如果是这样，那应该是硬解析才对呀，可是在awr中看并没有过多的硬解析。

Maclean Liu(刘相兵 发表于 2013-11-21 11:40:22

hang的特定是什么都变慢了，而不是什么都变快了，变慢的的效应之一是次数减少

页: [1]

Oracle数据库数据恢复、性能优化's Archiver

执行 grant statement 命令, DB hang.