Troubleshooting Parallel Execution with Active Session History
转自 http://www.tyson1.com/professional/parallel/px_ash.htm
Active Session History (ASH) is one of the most powerful debugging tools available to the DBA or developer. It is a data dictionary view called SYS.DBA_HIST_ACTIVE_SESS_HISTORY. There is no corresponding ALL_ or USER_ view. The ASH view is populated every second with a sampling of data from the v$session view joined to other v$views. Since this is a sampling, not all of the rows from v$session are copied to the ASH. However, most performance problems go on for minutes or even hours. These are going to have a lot of rows in ASH.
The ASH view does not contain all of the columns from the v$session view. For instance, the osuser column is missing. This can make it difficult to identify the “person of interest” associated with a performance problem. However, the machine name is copied into the ASH. This machine name is either a PC name or a server name. If your company can tell you who is assigned a PC with a given name, then you can translate the machine name into a person’s name.
The ASH view also has columns that are not in v$session, such as pga_allocated and temp_space_allocated. These are enormously useful, as we shall see.
The ASH view is part of the workload repository, so every row gets a snap_id even though the view is populated continuously every second instead of just during the AWR snapshots. The ASH view has the same retention period as the workload repository, so the data in it is only going to go back a week or two, or whatever your AWR retention period is.
Since the ASH view contains samples of the v$session view every second, the underlying table will get very large for an active database. I don’t think that there are any indexes on these tables. Accordingly, queries on ASH can be challenging, and there are a few tricks involved. These queries can easily take 5 minutes to run with one process, so using a parallel processing hint is almost essential. And then when the query completes, it can easily return thousands of rows, so you need to know how to aggregate the results into useful information.
Use of the Active Session History view will described below and illustrated with examples. These examples will take spikes in resource utilization from our queries that use the workload repository views to monitor the database. The ASH view is the link that enables us to go from observing a performance problem to finding the solution.
Following is the description of the active session history view:
SQL> describe sys.dba_hist_active_sess_history Name Null? Type ----------------------------- -------- ----------------- SNAP_ID NOT NULL NUMBER DBID NOT NULL NUMBER INSTANCE_NUMBER NOT NULL NUMBER SAMPLE_ID NOT NULL NUMBER SAMPLE_TIME NOT NULL TIMESTAMP(3) SESSION_ID NOT NULL NUMBER SESSION_SERIAL# NUMBER SESSION_TYPE VARCHAR2(10) FLAGS NUMBER USER_ID NUMBER SQL_ID VARCHAR2(13) SQL_CHILD_NUMBER NUMBER SQL_OPCODE NUMBER FORCE_MATCHING_SIGNATURE NUMBER TOP_LEVEL_SQL_ID VARCHAR2(13) TOP_LEVEL_SQL_OPCODE NUMBER SQL_PLAN_HASH_VALUE NUMBER SQL_PLAN_LINE_ID NUMBER SQL_PLAN_OPERATION VARCHAR2(64) SQL_PLAN_OPTIONS VARCHAR2(64) SQL_EXEC_ID NUMBER SQL_EXEC_START DATE PLSQL_ENTRY_OBJECT_ID NUMBER PLSQL_ENTRY_SUBPROGRAM_ID NUMBER PLSQL_OBJECT_ID NUMBER PLSQL_SUBPROGRAM_ID NUMBER QC_INSTANCE_ID NUMBER QC_SESSION_ID NUMBER QC_SESSION_SERIAL# NUMBER EVENT VARCHAR2(64) EVENT_ID NUMBER SEQ# NUMBER P1TEXT VARCHAR2(64) P1 NUMBER P2TEXT VARCHAR2(64) P2 NUMBER P3TEXT VARCHAR2(64) P3 NUMBER WAIT_CLASS VARCHAR2(64) WAIT_CLASS_ID NUMBER WAIT_TIME NUMBER SESSION_STATE VARCHAR2(7) TIME_WAITED NUMBER BLOCKING_SESSION_STATUS VARCHAR2(11) BLOCKING_SESSION NUMBER BLOCKING_SESSION_SERIAL# NUMBER BLOCKING_INST_ID NUMBER BLOCKING_HANGCHAIN_INFO VARCHAR2(1) CURRENT_OBJ# NUMBER CURRENT_FILE# NUMBER CURRENT_BLOCK# NUMBER CURRENT_ROW# NUMBER CONSUMER_GROUP_ID NUMBER XID RAW(8) REMOTE_INSTANCE# NUMBER IN_CONNECTION_MGMT VARCHAR2(1) IN_PARSE VARCHAR2(1) IN_HARD_PARSE VARCHAR2(1) IN_SQL_EXECUTION VARCHAR2(1) IN_PLSQL_EXECUTION VARCHAR2(1) IN_PLSQL_RPC VARCHAR2(1) IN_PLSQL_COMPILATION VARCHAR2(1) IN_JAVA_EXECUTION VARCHAR2(1) IN_BIND VARCHAR2(1) IN_CURSOR_CLOSE VARCHAR2(1) SERVICE_HASH NUMBER PROGRAM VARCHAR2(64) MODULE VARCHAR2(48) ACTION VARCHAR2(32) CLIENT_ID VARCHAR2(64) ECID VARCHAR2(64)
The execution plan of a query run on the ASH view will reveal the underlying tables.
EXPLAIN PLAN FOR SELECT * FROM SYS.DBA_HIST_ACTIVE_SESS_HISTORY;
SQL> SELECT * FROM TABLE( dbms_xplan.display( NULL, NULL, 'typical', NULL ));
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
Plan hash value: 1921269144
-----------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop |
-----------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 781 | 205K| 18 (6)| 00:00:01 | | |
|* 1 | FIXED TABLE FIXED INDEX| X$XPLTON (ind:1) | 1 | 47 | 0 (0)| 00:00:01 | | |
|* 2 | FIXED TABLE FIXED INDEX| X$XPLTOO (ind:1) | 1 | 47 | 0 (0)| 00:00:01 | | |
|* 3 | HASH JOIN | | 781 | 205K| 18 (6)| 00:00:01 | | |
| 4 | TABLE ACCESS FULL | WRH$_EVENT_NAME | 995 | 66665 | 5 (0)| 00:00:01 | | |
|* 5 | HASH JOIN RIGHT OUTER | | 781 | 154K| 13 (8)| 00:00:01 | | |
|* 6 | TABLE ACCESS FULL | WRM$_SNAPSHOT | 45 | 720 | 3 (0)| 00:00:01 | | |
| 7 | PARTITION RANGE ALL | | 781 | 141K| 9 (0)| 00:00:01 | 1 | 3 |
| 8 | TABLE ACCESS FULL | WRH$_ACTIVE_SESSION_HISTORY | 781 | 141K| 9 (0)| 00:00:01 | 1 | 3 |
-----------------------------------------------------------------------------------------------------------------------
The WRH$_ACTIVE_SESSION_HISTORY table is the main table for the ASH view. It is a big table, and there are no indexes on it as far as I can tell. A query on the ASH view can easily take over 5 minutes in a database that has a lot of sessions to sample (this one doesn't). So, queries on the ASH view need to use parallel processes if they are going to run in a reasonable amount of time.
When using the PARALLEL hint in a query that reads the ASH view, do not specify a table name or degree. These will either be ignored, or prevent the PARALLEL hint from being used. The underlying tables in the ASH view are hidden data dictionary tables, and these apparently don't work the same as user tables as far as the PARALLEL hint is concerned. Just specify the PARALLEL hint and you will get the default degree of parallelism, which is equal to the product of the database parameters cpu_count times parallel_threads_per_cpu. This is the number of parallel processes that you will get for each set of senders and receivers. Since you will get both senders and receivers in the execution plan of any query on the ASH view, the total number of parallel process that your ASH query will get is two times the default degree of parallelism.
explain plan for SELECT /*+ PARALLEL */ * FROM SYS.DBA_HIST_ACTIVE_SESS_HISTORY;
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------
Plan hash value: 391332229
-----------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | Pstart| Pstop | TQ |IN-OUT| PQ Distrib |
-----------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 781 | 205K| 11 (10)| 00:00:01 | | | | | |
|* 1 | FIXED TABLE FIXED INDEX | X$XPLTON (ind:1) | 1 | 47 | 0 (0)| 00:00:01 | | | | | |
|* 2 | FIXED TABLE FIXED INDEX | X$XPLTOO (ind:1) | 1 | 47 | 0 (0)| 00:00:01 | | | | | |
| 3 | PX COORDINATOR | | | | | | | | | | |
| 4 | PX SEND QC (RANDOM) | :TQ10002 | 781 | 205K| 11 (10)| 00:00:01 | | | Q1,02 | P->S | QC (RAND) |
|* 5 | HASH JOIN | | 781 | 205K| 11 (10)| 00:00:01 | | | Q1,02 | PCWP | |
| 6 | PX RECEIVE | | 995 | 66665 | 3 (0)| 00:00:01 | | | Q1,02 | PCWP | |
| 7 | PX SEND BROADCAST | :TQ10000 | 995 | 66665 | 3 (0)| 00:00:01 | | | Q1,00 | P->P | BROADCAST |
| 8 | PX BLOCK ITERATOR | | 995 | 66665 | 3 (0)| 00:00:01 | | | Q1,00 | PCWC | |
| 9 | TABLE ACCESS FULL | WRH$_EVENT_NAME | 995 | 66665 | 3 (0)| 00:00:01 | | | Q1,00 | PCWP | |
|* 10 | HASH JOIN RIGHT OUTER| | 781 | 154K| 8 (13)| 00:00:01 | | | Q1,02 | PCWP | |
| 11 | PX RECEIVE | | 45 | 720 | 2 (0)| 00:00:01 | | | Q1,02 | PCWP | |
| 12 | PX SEND BROADCAST | :TQ10001 | 45 | 720 | 2 (0)| 00:00:01 | | | Q1,01 | P->P | BROADCAST |
| 13 | PX BLOCK ITERATOR | | 45 | 720 | 2 (0)| 00:00:01 | | | Q1,01 | PCWC | |
|* 14 | TABLE ACCESS FULL| WRM$_SNAPSHOT | 45 | 720 | 2 (0)| 00:00:01 | | | Q1,01 | PCWP | |
| 15 | PX BLOCK ITERATOR | | 781 | 141K| 5 (0)| 00:00:01 | 1 | 3 | Q1,02 | PCWC | |
| 16 | TABLE ACCESS FULL | WRH$_ACTIVE_SESSION_HISTORY | 781 | 141K| 5 (0)| 00:00:01 | 1 | 3 | Q1,02 | PCWP | |
-----------------------------------------------------------------------------------------------------------------------------------------------------
Parallel Process Spikes
Below is the output of the query that retrieves the parallel operation metrics from the sys.dba_hist_sysstat view. As you can see, there is a spike in the parallel operations between 8:00 AM and 11:00 AM.
INTERVAL_HOUR NOT_DG TOTAL_DG DG_SERIAL DG_1_TO_25 DG_25_TO_50 DG_50_TO_75 DG_75_TO_99 -------------- ---------- ---------- ---------- ---------- ----------- ----------- ----------- 25-SEP-2012 00 159 0 0 0 0 0 0 25-SEP-2012 01 166 107 68 7 18 10 4 25-SEP-2012 02 238 7 0 2 4 1 0 25-SEP-2012 03 357 60 26 29 2 1 2 25-SEP-2012 04 36 0 0 0 0 0 0 25-SEP-2012 05 116 18 7 6 0 5 0 25-SEP-2012 06 230 6 2 1 3 0 0 25-SEP-2012 07 325 6 1 1 1 1 2 25-SEP-2012 08 24717 0 0 0 0 0 0 25-SEP-2012 09 104902 0 0 0 0 0 0 25-SEP-2012 10 56475 0 0 0 0 0 0 25-SEP-2012 11 175 0 0 0 0 0 0 25-SEP-2012 12 178 0 0 0 0 0 0 25-SEP-2012 13 198 0 0 0 0 0 0 25-SEP-2012 14 217 1 1 0 0 0 0 25-SEP-2012 15 232 0 0 0 0 0 0 25-SEP-2012 16 224 0 0 0 0 0 0 25-SEP-2012 17 72 0 0 0 0 0 0 25-SEP-2012 18 11 0 0 0 0 0 0 25-SEP-2012 19 7 0 0 0 0 0 0 25-SEP-2012 20 3 0 0 0 0 0 0 25-SEP-2012 21 6 0 0 0 0 0 0 25-SEP-2012 22 30 0 0 0 0 0 0 25-SEP-2012 23 1 0 0 0 0 0 0
Despite the spike in parallel operations, there were no requests for parallel operations that were downgraded. Let’s query the Active Session History and see what these parallel operations were.
The following query counts the number of parallel sessions grouped by user_id, program, module, machine, and sql_id. The parallel sessions are identified the same way that they were in the v$session view: the program name as the format oracle_owner@db_server_name, and then they have a parallel process ID in parentheses.
column program format A25 column machine format A10 column module format A25 column user_id format 9999999 column count format 99999
SELECT * FROM (
SELECT /*+ PARALLEL */
count(*) AS count,
user_id, program, module, machine, sql_id
FROM SYS.DBA_HIST_ACTIVE_SESS_HISTORY
WHERE sample_time > TO_DATE('25-SEP-2012 08:00:00','DD-MON-YYYY HH24:MI:SS')
AND sample_time < TO_DATE('25-SEP-2012 11:10:00','DD-MON-YYYY HH24:MI:SS')
AND program LIKE 'oracle@%'
GROUP BY user_id, program, module, machine, sql_id
ORDER BY count(*) desc
)
WHERE rownum <= 20
/
COUNT USER_ID PROGRAM MODULE MACHINE SQL_ID
------ -------- ------------------------- ------------------------- ---------- -------------
160 0 oracle@db_server(J001) DBMS_SCHEDULER db_server 8szmwam7fysa3
109 327 oracle@db_server(P009) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
108 327 oracle@db_server(P012) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
92 0 oracle@db_server(J002) DBMS_SCHEDULER db_server c6ksc6kfhjjc6
92 327 oracle@db_server(P000) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
90 327 oracle@db_server(P008) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
89 327 oracle@db_server(P006) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
89 327 oracle@db_server(P004) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
85 327 oracle@db_server(P010) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
83 327 oracle@db_server(P011) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
82 0 oracle@db_server(J001) DBMS_SCHEDULER db_server 9q7k9nbpvk8pv
81 327 oracle@db_server(P001) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
80 57 oracle@db_server(P033) osuser@server2 (TNS V1-V3) server2 0tahuczhvjmm3
80 327 oracle@db_server(P005) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
79 327 oracle@db_server(P014) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
74 327 oracle@db_server(P007) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
70 327 oracle@db_server(P015) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
69 327 oracle@db_server(P013) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
65 327 oracle@db_server(P003) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
64 57 oracle@db_server(P032) osuser@server2 (TNS V1-V3) server2 0tahuczhvjmm3
If you have RAC, then you may need more than one server name in the filter predicate. You may will need one for each instance.
Notice the parallel process hint in the SQL statement. Querying the Active Session History view in serial mode can take 5 minutes or more. With 64 parallel processes, it takes 20 to 25 seconds to run this query in my database. Your performance in your database will vary, but you are likely to need the parallel hint in this query. The table name in the hint is the underlying table that the view is defined on.
The ASH view has other columns in it that you may want to investigate, so feel free to add them to the SELECT clause. The above output has been limited to fit on a page.
The user_id is the number from the user_id column of the sys.dba_users view. You may be tempted to join the sys.dba_hist_active_sess_history view to the sys.dba_users view on user_id, but the performance can be even worse than querying the Active Session History view by itself. These views are defined on multiple tables with complex operations. Joining them can cause unpredictable performance, so I always query on the ASH view by itself.
The user_id value of 0 corresponds to the SYS account, so we ignore those sessions. The parallel sessions for user_id 327 may have different process numbers, but they all have the same sql_id, avb14fdyuwdhy. Use the following query to get the SQL statement:
SELECT * FROM sys.dba_hist_sqltext WHERE sql_id = '8szmwam7fysa3';
The result was an UPDATE statement that did not use a primary or unique key. In fact, it was doing an index skip scan on the primary key index because the first column of the index was not in the filter predicates. The SQL statement was tuned by adding the first column of the primary key to the where clause, although a range predicate had to be used.
When a query or DML statement affects a single row in a table by use of a unique scan on a primary or unique key index, then parallel processing will not be used even if it is enabled on the index that the constraint is defined on. In other words, the Oracle optimizer will not use parallel processing for single row transactions even if it is available. It isn’t faster or more efficient to do so. Because of the overhead involved in allocating parallel processes, unique DML statements do not benefit from them, and the optimizer knows that.
On the other hand, an index range scan can benefit from parallel processes, so the optimizer will use them if the index scan is not unique. This may or may not be desirable. Typically, I will enable parallel processing on indexes if they are large enough, but not if they are small.
Wait Events
At the same time that we had a spike in parallel processes, there was a spike in the wait event “library cache: mutex X”. The following output from my daily report has the hours listed horizontally instead of vertically:
Wait events in seconds: Metric Name H00 H01 H02 H03 H04 H05 H06 H07 H08 H09 H10 H11 H12 H13 H14 H15 library cache: mutex X 20 30 14 15 2 7 14 16 95740682110 6 9 7 7 7
Once again, between the hours of 8:00 AM and 11:00 AM, there was a spike. Lets query the Active Session History on wait event and see what we get.
SELECT * FROM (
SELECT /*+ PARALLEL */
count(*) AS count,
user_id, program, module, machine, sql_id
FROM SYS.DBA_HIST_ACTIVE_SESS_HISTORY
WHERE sample_time > TO_DATE('25-SEP-2012 08:00:00','DD-MON-YYYY HH24:MI:SS')
AND sample_time < TO_DATE('25-SEP-2012 11:10:00','DD-MON-YYYY HH24:MI:SS')
AND event = 'library cache: mutex X'
GROUP BY user_id, program, module, machine, sql_id
ORDER BY count(*) DESC
)
WHERE rownum <= 20
/
COUNT USER_ID PROGRAM MODULE MACHINE SQL_ID
------ -------- ------------------------- ------------------------- ---------- -------------
73 327 oracle@db_server(P009) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
61 327 oracle@db_server(P012) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
60 327 oracle@db_server(P004) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
56 327 oracle@db_server(P008) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
53 327 oracle@db_server(P011) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
51 327 oracle@db_server(P005) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
46 327 oracle@db_server(P014) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
43 327 oracle@db_server(P003) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
43 327 oracle@db_server(P006) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
42 327 oracle@db_server(P010) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
42 327 oracle@db_server(P007) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
36 327 oracle@db_server(P001) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
36 327 oracle@db_server(P012) osuser@server2 (TNS V1-V3) server2 66hqjnsynh3b5
33 327 oracle@db_server(P013) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
32 327 oracle@db_server(P015) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
32 327 oracle@db_server(P003) osuser@server2 (TNS V1-V3) server2 66hqjnsynh3b5
31 327 oracle@db_server(P000) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
30 327 oracle@db_server(P011) osuser@server2 (TNS V1-V3) server2 66hqjnsynh3b5
30 327 oracle@db_server(P014) osuser@server2 (TNS V1-V3) server2 66hqjnsynh3b5
30 327 oracle@db_server(P002) osuser@server2 (TNS V1-V3) server2 avb14fdyuwdhy
The top ten results all have the same sql_id as the UPDATE statement that caused our parallel process spike. You will often see a performance problem affect multiple metrics.
Temp Tablespace Spikes
The following output from my daily report shows a spike in writes to the TEMP tablespace.
Temp tablespace metrics: Metric Name H00 H01 H02 H03 H04 H05 H06 H07 H08 H09 H10 H11 H12 H13 H14 H15 tempstatxs_phyblkwrt 22 121 25 16 4 13 17 16 23 5 66 76 26 1 26 2 v$sort_segment-used_extents 5 1 0 0 0 0 0 0 0 12 0 3 0 0 0 0 Values are in Gigabytes
Remember that the value for "physical blocks written" is a cumulative metric, and "used extents" is a snapshot taken on the hour. Between 1:00 AM and 2:00 AM, there were 121 Gigabytes of data written to the TEMP tablespace, but the snapshot values that bracket this interval are 1 and 0. This is because the data is continuously written to, and then deleted from, the TEMP tablespace. The extents did not pile up at the snapshot times. This is normal behavior for the TEMP tablespace.
However, the spike of 121 Gigabytes of data written indicates that there are SQL statement that have multi-pass joins (See Cost-Based Oracle Fundamentals by Jonathan Lewis, Chapter 12, "Hash Joins"). We can use the ASH view to find these SQL statements.
SELECT * FROM (
SELECT /*+ PARALLEL */
count(*) AS count,
user_id, program, module, machine, sql_id
FROM SYS.DBA_HIST_ACTIVE_SESS_HISTORY
WHERE sample_time > TO_DATE( '09-OCT-2012 08:00:00', 'DD-MON-YYYY HH24:MI:SS' )
AND sample_time < TO_DATE( '09-OCT-2012 11:10:00', 'DD-MON-YYYY HH24:MI:SS' )
AND temp_space_allocated > 1024*1024*1024
GROUP BY user_id, program, module, machine, sql_id
ORDER BY count(*) DESC
)
WHERE rownum <= 20
/
COUNT USER_ID PROGRAM MODULE MACHINE SQL_ID
------ -------- --------------------------- ------------------------- -------- -------------
140 401 oracle@db_server (P005) user1@server2 (TNS V1-V3) server2 00gzy11w5tvtw
54 401 oracle@db_server (P037) user1@server2 (TNS V1-V3) server2 00gzy11w5tvtw
27 53 user2@server3 (TNS V1-V3) user2@server3 (TNS V1-V3) server3 1xrbpuk849qq3
7 53 user2@server3 (TNS V1-V3) user2@server3 (TNS V1-V3) server3 czujsw3fhp3hx
4 293 sqlplus@server3 (TNS V1-V3) SQL*Plus server3 96t76t3utp5z6
The condition in the WHERE clause that filtered on temp_space_allocated used one Gigabyte for the literal. You may want to change this to something more representative for your database.
The top two sessions are parallel processes for the same sql_id, 00gzy11w5tvtw. Since these sessions make up a good majority of the sessions counted for in this condition, this sql statement is the prime suspect. You can find out just how much of the temp tablespace that these sessions used by looking at individual rows from the ASH view.
column temp_space_allocated format 999,999,999,999
SELECT /*+ PARALLEL */
sql_id,
TO_CHAR(sample_time,'DD-MON-YYYY HH24:MI:SS') AS sample_time,
temp_space_allocated
FROM SYS.DBA_HIST_ACTIVE_SESS_HISTORY
WHERE sample_time > TO_DATE( '09-OCT-2012 08:00:00', 'DD-MON-YYYY HH24:MI:SS' )
AND sample_time < TO_DATE( '09-OCT-2012 11:10:00', 'DD-MON-YYYY HH24:MI:SS' )
AND sql_id = '00gzy11w5tvtw'
ORDER BY sample_time;
SQL_ID SAMPLE_TIME TEMP_SPACE_ALLOCATED ------------- -------------------- -------------------- 00gzy11w5tvtw 09-OCT-2012 10:12:48 13,849,591,808 00gzy11w5tvtw 09-OCT-2012 10:12:58 14,166,261,760 00gzy11w5tvtw 09-OCT-2012 10:12:58 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:13:08 14,469,300,224 00gzy11w5tvtw 09-OCT-2012 10:13:18 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:13:28 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:13:38 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:13:48 15,703,474,176 00gzy11w5tvtw 09-OCT-2012 10:13:48 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:13:58 16,027,484,160 00gzy11w5tvtw 09-OCT-2012 10:14:08 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:14:18 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:14:18 16,667,115,520 00gzy11w5tvtw 09-OCT-2012 10:14:28 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:14:38 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:14:48 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:14:58 17,996,709,888 00gzy11w5tvtw 09-OCT-2012 10:15:08 12,156,141,568 00gzy11w5tvtw 09-OCT-2012 10:15:18 18,660,458,496 00gzy11w5tvtw 09-OCT-2012 10:15:59 18,662,555,648 00gzy11w5tvtw 09-OCT-2012 10:16:09 18,662,555,648 00gzy11w5tvtw 09-OCT-2012 10:16:19 18,662,555,648 00gzy11w5tvtw 09-OCT-2012 10:16:29 18,662,555,648 00gzy11w5tvtw 09-OCT-2012 10:16:39 18,662,555,648
Notice that the value tracked by the ASH view, temp_space_allocated, is a snapshot value. It goes up and down, and peaks at over 18 Gigabytes. It may have written more than 18 Gig of data to the temp tablespace, but no more that 18 Gig of space was allocated at any one time. The metric from the v$tempstatxs view, phyblkwrt (physical blocks written) was a cumulative value. This illustrates the fact that similar metrics in different v$ view are not necessarily the same. Nevertheless, we can still find the offending query and try to tune it.
SELECT * FROM sys.dba_hist_sqltext WHERE sql_id = '00gzy11w5tvtw';
The offending user can found from the sys.dba_users view:
SELECT user_id, username FROM sys.dba_users WHERE user_id = 401;
If you have users who share the same username with other users and applications, then it can be difficult to identify the “person of interest” responsible for the offending query. If, on the other hand, your company follows good security practices and has dedicated accounts for each person and each application, then your job of helping the users is much easier.
PGA Spikes
The following row from my daily report has a spike in PGA use.
PGA in Gigabytes: Metric Name H00 H01 H02 H03 H04 H05 H06 H07 H08 H09 H10 H11 H12 H13 H14 H15 total PGA allocated 19 1 3 3 5 2 5 9 10 8 8 11 11 3 2 1
The statistic “total PGA allocated” is a snapshot value taken every time the AWR takes a snapshot of the v$ views. Hence, we only know the value at the snapshot times, and not between them.
After PGA is used, the PGA memory remains “allocated” for a while in case another session needs PGA memory. However, after a certain amount of time, which is not documented, the PGA memory will be released if it is not reused.
Since the spike of 19 Gigabytes in “total PGA allocated” is below the value of the parameter pga_aggregate_target, which is 50 Gig, we are not hitting the resource limit with this memory spike. The database is not going to experience performance problems as a whole. Tuning this spike may indicate a condition known as “compulsive tuning disorder,” which is a state of continued tuning when there aren’t any more real performance problems.
Although the database as a whole may not suffer from this PGA spike, the SQL statement that caused it could use some help, and I am supposed to spend part of my time on “proactive tuning.” I also needed an example of how to tune a PGA spike, and I’ve already fixed all the real performance problems. So, we will use the ASH to find the SQL statement responsible for this spike.
SELECT * FROM (
SELECT /*+ PARALLEL */
count(*) AS count,
user_id, program, module, machine, sql_id
FROM SYS.DBA_HIST_ACTIVE_SESS_HISTORY
WHERE sample_time > TO_DATE( '09-OCT-2012 08:00:00', 'DD-MON-YYYY HH24:MI:SS' )
AND sample_time < TO_DATE( '09-OCT-2012 11:10:00', 'DD-MON-YYYY HH24:MI:SS' )
AND pga_allocated > 1024*1024*1024
GROUP BY user_id, program, module, machine, sql_id
ORDER BY count(*) DESC
)
WHERE rownum <= 20
/
COUNT USER_ID PROGRAM MODULE MACHINE SQL_ID
------ -------- --------------------------- ------------------------- -------- -------------
33 293 sqlplus@pzm3017 (TNS V1-V3) SQL*Plus pzm3017 3uhcz0dc55z6c
This query counts all the recorded sessions in the ASH view that have pga_allocated greater than one Gigabyte. To find the actual pga_allocated of the SQL statement, we can query the ASH once again.
column pga_allocated format 999,999,999,999
SELECT /*+ PARALLEL */
sql_id,
TO_CHAR(sample_time,'DD-MON-YYYY HH24:MI:SS') AS sample_time,
pga_allocated
FROM SYS.DBA_HIST_ACTIVE_SESS_HISTORY
WHERE sample_time > TO_DATE('29-SEP-2012 00:00:00','DD-MON-YYYY HH24:MI:SS')
AND sample_time < TO_DATE('29-SEP-2012 01:10:00','DD-MON-YYYY HH24:MI:SS')
AND sql_id = '3uhcz0dc55z6c'
ORDER BY sample_time;
SQL_ID SAMPLE_TIME PGA_ALLOCATED
------------- -------------------- ----------------
3uhcz0dc55z6c 29-SEP-2012 00:13:45 95,633,408
3uhcz0dc55z6c 29-SEP-2012 00:13:55 95,633,408
3uhcz0dc55z6c 29-SEP-2012 00:14:05 95,633,408
3uhcz0dc55z6c 29-SEP-2012 00:14:15 95,633,408
3uhcz0dc55z6c 29-SEP-2012 00:14:25 407,453,696
3uhcz0dc55z6c 29-SEP-2012 00:14:35 642,924,544
3uhcz0dc55z6c 29-SEP-2012 00:14:45 828,194,816
3uhcz0dc55z6c 29-SEP-2012 00:14:55 918,700,032
3uhcz0dc55z6c 29-SEP-2012 00:15:06 1,038,237,696
3uhcz0dc55z6c 29-SEP-2012 00:15:16 1,131,692,032
3uhcz0dc55z6c 29-SEP-2012 00:15:26 1,224,163,328
3uhcz0dc55z6c 29-SEP-2012 00:15:36 1,315,454,976
3uhcz0dc55z6c 29-SEP-2012 00:15:46 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:15:56 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:16:06 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:16:16 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:16:26 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:16:36 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:16:46 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:16:56 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:17:06 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:17:16 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:17:26 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:17:36 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:17:46 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:17:56 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:18:06 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:18:16 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:18:26 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:18:36 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:18:46 1,381,056,512
3uhcz0dc55z6c 29-SEP-2012 00:18:56 49,299,456
3uhcz0dc55z6c 29-SEP-2012 00:19:06 49,299,456
3uhcz0dc55z6c 29-SEP-2012 00:19:16 49,561,600
3uhcz0dc55z6c 29-SEP-2012 00:19:26 49,561,600
3uhcz0dc55z6c 29-SEP-2012 00:19:36 45,301,760
3uhcz0dc55z6c 29-SEP-2012 00:19:46 49,561,600
The value of pga_allocated can go up and down for a SQL statement. For this SQL, the pga_allocated does not go much higher than one Gigabyte. Other SQL statement must have contributed to the “Total PGA Allocated” spike of 19 Gig, but they never had more than 1 Gig of PGA, so they were not in our ASH query results. Lowering the filter condition to less than 1 Gig would find these other SQL statements, but there would be a lot of them with less than 1 Gig of PGA each. Tuning all of them would take a lot of time for little return on performance improvement. This does not satisfy my compulsive tuning disorder, so I will look for performance problems elsewhere.
浙公网安备 33010602011771号