ORACLE 11G 性能诊断优化之ASH实战分析详解

ORACLE 11G 性能诊断优化之ASH实战分析详解

 转载

wx5caecf2ed06452021-08-09 22:45:31博主文章分类：Oracle©著作权

文章标签sql等待事件htmlsql语句数据文章分类Oracle数据库阅读数130

1、ASH （Active SessionHistory）

ASH以V$SESSION为基础，每秒采样一次，记录活动会话等待的事件。不活动的会话不会采样，采样工作由新引入的后台进程MMNL来完成。

 

v$active_session_history视图提供了在实例级别抽取会话活动信息。活动会话每分钟会被抽样一次且被存储在sga中的循环缓冲区中.任何被连接到数据库且正等待一个不属于空闲等待事件的会话会被考虑是一个活动的会话。每个会话抽样都是一组行数据且通过v$active_session_history视图来返回每个被抽样活动会话的行数据，返回最新被抽样会话的第一行数据。因为活动会话抽样是存储在sga中的循环缓冲区中，系统活动越大的，活动时间越少会话的可以被存储在循环缓冲区中。这意味着在这期间被抽样的每个会话会出现在v$视图中或者会话活动的时间会在v$视图中被显示，这完全依赖于数据库活动情况。

 

ASH buffers 的最小值为1MB，最大值不超过30MB.内存中记录数据。期望值是记录一小时的内容，所以说ASH 内存记录数据始终是有限的

             

         一般在线上实时诊断数据库性能问题，特别是负载高w出来上了100后，cpu 100%，这个时候用ash实时出日志报告，就能很大程度上准确定位问题所在。

 

 

 

 

2、ASH的主要要素点

在执行SQL> @?/rdbms/admin/ashrpt.sql命令后，会让有如下参数需要手动填写：

（1）日志报告类型

Enter value for report_type: text 

-- 选择生成的ASH 报告类型，是text 还是html

 

（2）日志报告起始时间

Enter value for begin_time: 08/31/1620:00:00

-- 输入ASH 开始的时间，时间格式上面的示例有说明，比如我这里是2016年8月31日晚上20:00:00开始。

 

（3）日志报告结束时间

Enter value for duration:7200

-- 输入ASH 结束时间，默认是SYSDATE - begin_time，一般输入的分析统计的总时间，一般默认是秒，比如这里7200就是2个小时，拿出2个小时的ash分析日志来。

 

（4）报告文件名

Enter value for report_name: /home/oracle/ash_20160831_3.html 

-- 输入ASH 报告的名称，可以指定生成的目录，默认情况是当前登陆sqlplus的目录。 这里的扩展最好加上，如果不加扩展名，扩展名会变成lst. 不影响数据，但是会影响阅读效率。

3、ASH操作实战记录

 

SQL> @?/rdbms/admin/ashrpt.sql

 

Current Instance

~~~~~~~~~~~~~~~~

 

   DB Id    DB Name  Inst Num Instance

----------- ------------ -------- ------------

 3391761643 POWERDES                 1 powerdes

 

 

Specify the Report Type

~~~~~~~~~~~~~~~~~~~~~~~

Enter 'html' for an HTML report， or 'text' for plain text

Defaults to 'html'

Enter value for report_type: html

 

Type Specified:  html

 

 

Instances in this Workload Repository schema

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

 

   DB Id     Inst Num DB Name            Instance     Host

------------ -------- ------------ ------------ ------------

* 3391761643     1 POWERDES      powerdes  pldb1

* 3391761643     1 POWERDES      powerdes  localhost.lo

                                                        caldomain

 

 

Defaults to current database

 

Using database id: 3391761643

 

Enter instance numbers. Enter 'ALL' for all instances in a

RAC cluster or explicitly specify list of instances (e.g.， 1，2，3).

Defaults to current instance.

 

Using instance number(s): 1

 

 

 

 

 

 

 

 

ASH Samples in this Workload Repository schema

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

 

Oldest ASH sample available:  23-Aug-16 08:00:17   [  12265 mins in the past]

Latest ASH sample available:  31-Aug-16 20:25:19   [          0 mins in the past]

 

 

Specify the timeframe to generate the ASH report

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Enter begin time for report:

 

--    Valid input formats:

--       To specify absolute begin time:

--         [MM/DD[/YY]] HH24:MI[:SS]

--         Examples: 02/23/03 14:30:15

--                    02/23 14:30:15

--                    14:30:15

--                    14:30

--       To specify relative begin time: (start with '-' sign)

--         -[HH24:]MI

--         Examples: -1:15  (SYSDATE - 1 Hr 15 Mins)

--                    -25    (SYSDATE - 25 Mins)

 

Defaults to -15 mins

Enter value for begin_time: 08/31/16 20:00:00

Report begin time specified: 08/31/16 20:00:00

 

Enter duration in minutes starting from begin time:

Defaults to SYSDATE - begin_time

Press Enter to analyze till current time

Enter value for duration: 7200

Using 31-Aug-16 20:00:00 as report begin time

Using 31-Aug-16 20:26:30 as report end time

 

 

Specify Slot Width (using ashrpti.sql) for 'Activity Over Time' section

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

………  # 这里信息太多，省过不贴了。

 

 

# 这里填写好生成的报表文件名字，然后回车

Enter value for report_name: ash_20160831_3.html

 

Using the report name ash_20160831_3.html

 

Summary of All User Input

-------------------------

Format            : HTML

DB Id               : 3391761643

Inst num       : 1

Begin time     : 31-Aug-16 20:00:00

End time       : 31-Aug-16 20:26:30

Slot width     : Default

Report targets : 0

Report name    : ash_20160831_3.html  

<p />

End of Report

</body></html>

Report written to ash_20160831_3.html                                                                                                                                                                                

SQL>

 

 

 

 

4、ASH日志报告详解

4.1 ASH报告

使用ash报告，在生成ash报告之后，可以重新检索哪些标识为短暂性能问题的信息。

ash报告的内容分成了以下几个部分：

top events

load profile

top sql

top pl/sql

top java

top sessions

to objects/files/latches

activity over time

 

41.png

 

4.2 Top Evnets

顶级等待事件部分描述了被抽样会话活动中由用户，后台等产生的顶级等待事件，使用这些信息可以识别是哪些等待事件造成了短暂的性能问题.顶级等待事件包含以下部分:

（1）Top User Events顶级用户事件

这部分信息显示了在抽样会话活动中占很高百分比的用户进程等待事件。

 

（2）Top Background Events顶级后台事件

这部分信息显示了在抽样会话活动中占很高百分比的后台进程等待事件。

 

（3）Top Event P1/P2/P3 Values顶级等待事件参数P1/P2/P3

这部分信息显示了在抽样会话活动中占很高百分比的等待事件的参数值它通过总的等待时间(%Event)百分比进行排序后被显示.对于每一个等待事件p1，p2，p3的值与等待事件参数parameter 1，parameter 2，parameter 3这三个列相关联.

 

案例如下图42.png所示：

 

 

4.3 Load Profile

load profile部分描述了在抽样的会话活动中的负载分析.使用这部分信息可以识别造成短暂性能问题的服务，客户或sql命令类型.负载概要部分包含以下部分信息:

 

（1）top service/module

这部分信息显示了在抽样会话活动中占很高百分比的服务和模块信息

 

（2）top client ids

这部分信息显示了在抽样会话活动中占很高百分比的客户端的id信息它是数据库会话中应用程序的特定标识符

 

（3）top sql command types

这部分信息显示了在抽样会话活动中占很高百分比的sql命令类型比如select或update

 

（4）top phases of execution

这部分信息显示了在抽样会话活动中占很高百分比的执行步骤比如sql，pl/sql和java的编译和执行操作.

 

案例如下图43.png所示：

 

 

 

 

4.4 Top Sql

顶级sql部分描述了抽样会话活动中的顶级sql语句，使用这部分信息可以识别出造成短暂性能问题的高负载sql语句

顶级sql部分包含以下信息:

top sql with top events

top sql with top row sources

top sql using literals

top parsing module/action

complete list of sql text

 

（1）top sql with top events

这部分信息显示了在抽样会话活动中占总的等待事件很高百分比的sql语句.

 

（2）top sql with top row sources

这部分信息显示了在抽样会话活动中占很高百分比的sql语句和它们的详细执行计划信息.通过这部分信息可以识别出哪部分的sql执行消耗了大量的sql执行时间

 

（3）top sql using literals

这部分信息显示了在抽样会话活动中占很高百分比的使用literal值的sql语句.可以重新检查这部分sql语句看是否能使用绑定变量来代替literal值.

 

（4）top parsing module/action

这部分信息显示了在抽样会话活动中当执行解析sql语句时占很高百分比的模块和操作

 

（5）complete list of sql text

这部分信息显示了顶级sql语句的完整的文本内容

 

（6）top pl/sql

这部分信息显示了在抽样会话活动中占很高百分比的pl/sql过程.

 

（7）top java

这部分信息显示了在抽样会话活动中占很高百分比的java程序

 

 

4.5 top sessions

这部分信息描述了会话正在等待的一个特定等待事件。使用这部分信息来识别在抽样会话活动中占很高百分比的会话它们可能是造成短暂性能问题的原因.top sessions部分包含以下信息:

 

（1）top sessions

这部分信息显示了在抽样会话活动中占很高百分比的等待会话

 

（2）top blocking sessions

这部分信息显示了在抽样会话活动中占很高百分比的阻塞会话

 

（3）top sessions running pqs

这部分信息显示了哪些在抽样会话活动中占很高百分比的正处于等待的并行查询

 

 

4.6、top objects/files/latches

这部分信息显示了通常最消耗数据库资源的信息括以下部分:

 

（1）top db objects

这部分信息显示了在抽样会话活动中占所有引用对象很高百分比的数据库对象(比如表和索引)

 

（2）top db files

这部分信息显示了在抽样会话活动中占访问量很高百分比的数据库文件

 

（3）top latches

这部分信息显示了在抽样会话活动中占很高百分比的闩锁信息

闩锁是一种简单低级别串行化机制用来保护sga中的共享数据结构.比如闩锁保护当前访问数据库和缓冲区缓存中数据块结构的用户列表.当维护或查找这些结构时服务器或后台进程请求持有闩锁的时间是非常短暂的.闩锁的实现依赖于操作系统特别是一个进程等待获取一个闩锁多长时间.

 

（4）Activity over time

这一部分是ash报告信息最丰富的一部分.这部分信息对于长时间周期的ash报告来说因为在分析期间它提供了关于活动和工作负载概要深层次的详细信息.activity over time会被分成10个时段.每个时段的大小基于分析所持续的时间.第一个和最后一个时段是奇怪.所有内部时段是相等的大小它们可以相互比较.例如，如果分析时间持续10分钟那么所有的时段将会是每个一分钟.然后如果分析时间持续9分30秒，那么外部的时段可能是每个15秒内部的时段可能每个1分钟

 

特定时段中每个时段包含的信息如下:

列                       描述

slot time(持续时间)      时段的持续时间

solt count               在时段中抽样会话的数量

event                    在时段中顶级的三个等待事件

event count              ash抽样等待的等待事件的数量

%event                   ash抽样等待的等待事件在整个分析期间所占的百分比

 

当比较内部时段时，通过识别异常的event count和slot count列执行一个倾斜分析.event count列的异常指示了在抽样会话中等待的等待事件数量增加了.slot count列的异常指示活动的会自豪感增加了，因为ash数据只从活动会话中进持抽样说明数据库的

负载增加了.通常来说当活动会话抽样的数理和与这些会话相关的等待事件增加时那么这个时段可能会造成短暂性能问题，如下44.png所示：

 

 

5、分析ASH日志报告

把生成的ash_20160831_3.html拷贝出来，在浏览器打开，可以看到问题在cursor. Mutex S上面，如下所示：

11.png

 

---------------------------------------------------自己生成----------------------------------------------------------------------------------------

ASH Report For WXH/wxh

 

DB Name	DB Id	Instance	Inst num	Release	RAC	Host
WXH	142723844	wxh	1	11.2.0.1.0	NO	PANACEABJ-003

 

 

CPUs	SGA Size	Buffer Cache	Shared Pool	ASH Buffer Size
4	3,058M (100%)	1,376M (45.0%)	400M (13.1%)	8.0M (0.3%)

 

 

	Sample Time	Data Source
Analysis Begin Time:	02-9ÔÂ -18 20:54:45	V$ACTIVE_SESSION_HISTORY
Analysis End Time:	02-9ÔÂ -18 21:09:51	V$ACTIVE_SESSION_HISTORY
Elapsed Time:	15.1 (mins)
Sample Count:	3
Average Active Sessions:	0.00
Avg. Active Session per CPU:	0.00
Report Target:	None specified

 

ASH Report

•  Top Events
•  Load Profile
•  Top SQL
•  Top PL/SQL
•  Top Java
•  Top Call Types
•  Top Sessions
•  Top Objects/Files/Latches
•  Activity Over Time

 Back to Top

---

 

Top Events

•  Top User Events
•  Top Background Events
•  Top Event P1/P2/P3 Values

 Back to Top

 

Top User Events

Event	Event Class	% Event	Avg Active Sessions
CPU + Wait for CPU	CPU	33.33	0.00

 Back to Top Events 
 Back to Top

 

Top Background Events

Event	Event Class	% Activity	Avg Active Sessions
CPU + Wait for CPU	CPU	33.33	0.00
os thread startup	Concurrency	33.33	0.00

 Back to Top Events 
 Back to Top

 

Top Event P1/P2/P3 Values

No data exists for this section of the report.

 Back to Top Events 
 Back to Top

 

 

Load Profile

•  Top Service/Module
•  Top Client IDs
•  Top SQL Command Types
•  Top Phases of Execution

 Back to Top

 

Top Service/Module

Service	Module	% Activity	Action	% Action
SYS$BACKGROUND	KTSJ	33.33	KTSJ Slave	33.33
	UNNAMED	33.33	UNNAMED	33.33
SYS$USERS	UNNAMED	33.33	UNNAMED	33.33

 Back to Load Profile 
 Back to Top

 

Top Client IDs

No data exists for this section of the report.

 Back to Load Profile 
 Back to Top

 

Top SQL Command Types

• 'Distinct SQLIDs' is the count of the distinct number of SQLIDs with the given SQL Command Type found over all the ASH samples in the analysis period

SQL Command Type	Distinct SQLIDs	% Activity	Avg Active Sessions
UPDATE	1	33.33	0.00

 Back to Load Profile 
 Back to Top

 

Top Phases of Execution

Phase of Execution	% Activity	Avg Active Sessions
SQL Execution	33.33	0.00

 Back to Load Profile 
 Back to Top

 

 

Top SQL

•  Top SQL with Top Events
•  Top SQL with Top Row Sources
•  Top SQL using literals
•  Top Parsing Module/Action
•  Complete List of SQL Text

 Back to Top

 

Top SQL with Top Events

SQL ID	Planhash	Sampled # of Executions	% Activity	Event	% Event	Top Row Source	% RwSrc	SQL Text
davq1msn9b8kd	685674527	1	33.33	CPU + Wait for CPU	33.33	UPDATE	33.33	UPDATE MGMT_POLICY_ASSOC_EVAL_...

 Back to Top SQL 
 Back to Top

 

Top SQL with Top Row Sources

SQL ID	PlanHash	Sampled # of Executions	% Activity	Row Source	% RwSrc	Top Event	% Event	SQL Text
davq1msn9b8kd	685674527	1	33.33	UPDATE	33.33	CPU + Wait for CPU	33.33	UPDATE MGMT_POLICY_ASSOC_EVAL_...

 Back to Top SQL 
 Back to Top

 

Top SQL using literals

No data exists for this section of the report.

 Back to Top SQL 
 Back to Top

 

Top Parsing Module/Action

No data exists for this section of the report.

 Back to Top SQL 
 Back to Top

 

 

Complete List of SQL Text

 

SQL Id	SQL Text
davq1msn9b8kd	UPDATE MGMT_POLICY_ASSOC_EVAL_DETAILS SET CRIT_COUNTER = NVL(:B9 , CRIT_COUNTER), WARN_COUNTER = NVL(:B8 , WARN_COUNTER), INFO_COUNTER = NVL(:B7 , INFO_COUNTER), LAST_ERROR_MESSAGE = :B6 , LAST_EVALUATION_DATE = :B5 WHERE TARGET_GUID = :B4 AND POLICY_GUID = :B3 AND COLL_NAME = :B2 AND RESULT_KEY_VALUE = :B1

 Back to Top SQL 
 Back to Top

 

 

Top PL/SQL Procedures

• 'PL/SQL entry subprogram' represents the application's top-level entry-point(procedure, function, trigger, package initialization or RPC call) into PL/SQL.
• 'PL/SQL current subprogram' is the pl/sql subprogram being executed at the point of sampling . If the value is 'SQL', it represents the percentage of time spent executing SQL for the particular plsql entry subprogram

PLSQL Entry Subprogram	% Activity	PLSQL Current Subprogram	% Current
SYSMAN.EMD_MAINTENANCE.EXECUTE_EM_DBMS_JOB_PROCS	33.33	SQL	33.33

 Back to Top

 

 

Top Java Workload

No data exists for this section of the report.

 Back to Top

 

 

Top Call Types

No data exists for this section of the report.

 Back to Top

 

 

Top Sessions

•  Top Sessions
•  Top Blocking Sessions
•  Top Sessions running PQs

 Back to Top

 

Top Sessions

• '# Samples Active' shows the number of ASH samples in which the session was found waiting for that particular event. The percentage shown in this column is calculated with respect to wall clock time and not total database activity.
• 'XIDs' shows the number of distinct transaction IDs sampled in ASH when the session was waiting for that particular event
• For sessions running Parallel Queries, this section will NOT aggregate the PQ slave activity into the session issuing the PQ. Refer to the 'Top Sessions running PQs' section for such statistics.

Sid, Serial#	% Activity	Event	% Event	User	Program	# Samples Active	XIDs
7, 87	33.33	CPU + Wait for CPU	33.33	SYS	ORACLE.EXE (J000)	1/906 [ 0%]	1
132, 10	33.33	CPU + Wait for CPU	33.33	SYS	ORACLE.EXE (W000)	1/906 [ 0%]	0
191, 5	33.33	os thread startup	33.33	SYS	ORACLE.EXE (CJQ0)	1/906 [ 0%]	0

 Back to Top Sessions 
 Back to Top

 

Top Blocking Sessions

No data exists for this section of the report.

 Back to Top Sessions 
 Back to Top

 

Top Sessions running PQs

No data exists for this section of the report.

 Back to Top Sessions 
 Back to Top

 

 

Top Objects/Files/Latches

•  Top DB Objects
•  Top DB Files
•  Top Latches

 Back to Top

 

Top DB Objects

No data exists for this section of the report.

 Back to Top Objects/Files/Latches 
 Back to Top

 

Top DB Files

No data exists for this section of the report.

 Back to Top Objects/Files/Latches 
 Back to Top

 

Top Latches

No data exists for this section of the report.

 Back to Top Objects/Files/Latches 
 Back to Top

 

 

Activity Over Time

• Analysis period is divided into smaller time slots
• Top 3 events are reported in each of those slots
• 'Slot Count' shows the number of ASH samples in that slot
• 'Event Count' shows the number of ASH samples waiting for that event in that slot
• '% Event' is 'Event Count' over all ASH samples in the analysis period

Slot Time (Duration)	Slot Count	Event	Event Count	% Event
21:00:00 (2.0 min)	2	CPU + Wait for CPU	1	33.33
		os thread startup	1	33.33
21:02:00 (2.0 min)	1	CPU + Wait for CPU	1	33.33

 Back to Top

 

End of Report