There are some questions about performance issues for which there is no easy answer, and sometimes the best you can do is try to generate an approximate answer then examine the results to eliminate the innocent.
Three such problems – essentially similar – appeared recently on the Oracle Developer Forum, and in this note I’ll supply a mechanism that may be a good enough step in the right direction for at least two of them. The questions were:
- How do I find who’s been using up all the temporary space recently?
- How do I find the execution plans for all the SQL that is called by a procedure?
- What SQL is responsible for generating most redo?
A basic (but incomplete) strategy for attacking these questions is to think of a way of to identify the sql_id and child_number for statements that might be contributing to the problem. If you can think of a suitable attack then you can get all the execution plans (or SQL Monitor reports) for those statements and examine them further.
The strategy is incomplete on two counts – first that you won’t get find the perfect set of statements, you’ll get more than you need but still miss some that are relevant; second that you’ll probably have to run secondary queries to get extra details about statements that look like good culprits for the problem you’re trying to solve.
Who’s been using the temporary space
The way this question was actually posed was more like:
I’ve got a query that started crashing with Oracle error “ORA-01652: unable to extend temp segment by 256 in tablespace TEMP”, but when I check the contents of the temporary tablespace (TEMP) there’s plenty of space available. How do I fix this problem.
This often means your query has changed execution plan and picked a very bad join order with some hash (or merge) joins that have dumped huge amount of data to disc; but it may mean that the space was being taken up by some other activity that doesn’t usually happen when you’re running your query.
So if you find that the SQL Monitor report (or simple call to dbms_xplan.display_cursor) makes you think that your query wasn’t doing anything differently a step that may help is to find all the sql in the library cache that might have been using a lot of temporary space.
For temporary space we can always check v$sql_workarea to identify operations from plans ran as one-pass or multi-pass operations, and we can check their most recent “tempseg size” or maximum tempseg size. Hence:
rem
rem Script: check_full_2a.sql
rem Author: Jonathan Lewis
rem Dated: Aug 2021
rem
rem Columns of interest for temporary space:
rem onepass_executions, multipasses_executions, last_tempseg_size, max_tempseg_size
select
distinct sql_id, child_number
from v$sql_workarea
where onepass_executions != 0
or multipasses_executions != 0
-- or max_tempseg_size > 1e7
/
select
distinct
sql.sql_id, sql.child_number
from
v$sql sql,
v$sql_workarea war
where
( war.onepass_executions != 0
or war.multipasses_executions != 0
)
and sql.sql_id = war.sql_id
and sql.child_number = war.child_number
and sql.last_active_time > sysdate - 15/1440
;
The first query here simply scans through the v$sql_workarea structure (which means it will actually thrash its way through the library cache) looking for operations that spilled to disk or (commented out) have used at least some specified amount of memory.
The second variation joins v$sql_workarea to v$sql so that it can restrict the chosen statements to those that were active some time in the last 15 minutes.
Obviously you will be able to think of other ways of tweaking these statements, and once you’ve got a statement expressing a suitable set of criteria you can embed it into a query that calls dbms_xplan.display_cursor() – as I demontrated about 10 years ago – or dbms_sql_monitor.report_sql_monitor() if you’re suitably licensed.
set linesize 230
set trimspool on
set pagesize 90
set tab off
set long 20000
select
plan_table_output
from (
select
distinct sql_id, child_number
from v$sql_workarea
where onepass_executions != 0
or multipasses_executions != 0
) v,
table(dbms_xplan.display_cursor(v.sql_id, v.child_number, 'memstats'))
;
select
dbms_sql_monitor.report_sql_monitor(
sql_id => v.sql_id,
start_time_filter => sysdate - 15/1440,
type =>'TEXT'
) text_line
from (
select
distinct sql.sql_id
from
v$sql sql,
v$sql_workarea war
where
( war.onepass_executions != 0
or war.multipasses_executions != 0
)
and sql.sql_id = war.sql_id
and sql.child_number = war.child_number
and sql.last_active_time > sysdate - 15/1440
) v
/
A couple of points to note. I’ve included the MEMSTATS format option in the call to dbms_xplan.display_cursor() so that it shows some summary information from v$sql_workarea. However this does have a defect, it doesn’t show space used in temp by materialized “with” subqueries (CTEs) – which is where the call to dbms_sql_monitor.report_sql_monitor() helps because if the execution was captured it will show writes to disc in the “LOAD AS SELECT” operation under the TEMPORARY TABLE TRANSFORMATION operation.
Here’s a sample of output I got from the two queries after forcing a nasty plan to do a big hash join that ultimately produced a small result set.
First the output from the query using package dbms_xplan:
PLAN_TABLE_OUTPUT
------------------------------------------------------------------------
SQL_ID 1cwabt12zq6zb, child number 0
-------------------------------------
with ttemp as ( select /*+ materialize */ * from t1 ) select /*+
no_partial_join(@sel$2 t1b) no_place_group_by(@sel$2) */
t1a.object_type, max(t1a.object_name) from ttemp t1a, ttemp t1b where
t1a.object_id = t1b.object_id group by t1a.object_type order by
t1a.object_type
Plan hash value: 1682228242
-----------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | OMem | 1Mem | O/1/M | Max-Tmp |
-----------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 45 |00:00:16.24 | | | | |
| 1 | TEMP TABLE TRANSFORMATION | | 1 | | 45 |00:00:16.24 | | | | |
| 2 | LOAD AS SELECT (CURSOR DURATION MEMORY)| SYS_TEMP_0FD9D6645_5FF4FE | 1 | | 0 |00:00:02.53 | 2070K| 2070K| | |
| 3 | TABLE ACCESS FULL | T1 | 1 | 1154K| 1154K|00:00:00.55 | | | | |
| 4 | SORT GROUP BY | | 1 | 45 | 45 |00:00:13.72 | 11264 | 11264 | 1/0/0| |
|* 5 | HASH JOIN | | 1 | 18M| 18M|00:00:08.63 | 58M| 12M| | 71M|
| 6 | VIEW | | 1 | 1154K| 1154K|00:00:01.03 | | | | |
| 7 | TABLE ACCESS FULL | SYS_TEMP_0FD9D6645_5FF4FE | 1 | 1154K| 1154K|00:00:01.03 | | | | |
| 8 | VIEW | | 1 | 1154K| 1154K|00:00:00.49 | | | | |
| 9 | TABLE ACCESS FULL | SYS_TEMP_0FD9D6645_5FF4FE | 1 | 1154K| 1154K|00:00:00.43 | | | | |
-----------------------------------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
5 - access("T1A"."OBJECT_ID"="T1B"."OBJECT_ID")
30 rows selected.
Note the absence of any numbers in the Max-Tmp column for operation 2 (highlighted line 18).
Then compare with the results below of the the query using package dbms_sql_monitor:
TEXT_LINE
-----------------------------------------------------------------------
SQL Monitoring Report
SQL Text
------------------------------
with ttemp as ( select /*+ materialize */ * from t1 )
select /*+ no_partial_join(@sel$2 t1b) no_place_group_by(@sel$2) */ t1a.object_type, max(t1a.object_name)
from ttemp t1a, ttemp t1b where t1a.object_id = t1b.object_id
group by t1a.object_type order by t1a.object_type
Global Information
------------------------------
Status : DONE (ALL ROWS)
Instance ID : 1
Session : SYS (10:47180)
SQL ID : 1cwabt12zq6zb
SQL Execution ID : 16777216
Execution Started : 08/05/2021 17:24:56
First Refresh Time : 08/05/2021 17:25:00
Last Refresh Time : 08/05/2021 17:25:12
Duration : 16s
Module/Action : MyModule/MyAction
Service : orclpdb
Program : sqlplus@linux183.localdomain (TNS V1-V3)
Fetch Calls : 4
Global Stats
================================================================================
| Elapsed | Cpu | IO | Fetch | Buffer | Read | Read | Write | Write |
| Time(s) | Time(s) | Waits(s) | Calls | Gets | Reqs | Bytes | Reqs | Bytes |
================================================================================
| 16 | 14 | 2.23 | 4 | 84677 | 986 | 253MB | 866 | 219MB |
================================================================================
SQL Plan Monitoring Details (Plan Hash Value=1682228242)
=====================================================================================================================================================================================================================
| Id | Operation | Name | Rows | Cost | Time | Start | Execs | Rows | Read | Read | Write | Write | Mem | Temp | Activity | Activity Detail |
| | | | (Estim) | | Active(s) | Active | | (Actual) | Reqs | Bytes | Reqs | Bytes | (Max) | (Max) | (%) | (# samples) |
=====================================================================================================================================================================================================================
| 0 | SELECT STATEMENT | | | | 1 | +16 | 1 | 45 | | | | | . | . | | |
| 1 | TEMP TABLE TRANSFORMATION | | | | 1 | +16 | 1 | 45 | | | | | . | . | | |
| 2 | LOAD AS SELECT (CURSOR DURATION MEMORY) | SYS_TEMP_0FD9D6645_5FF4FE | | | 5 | +0 | 1 | 2 | | | 351 | 176MB | . | . | | |
| 3 | TABLE ACCESS FULL | T1 | 1M | 3166 | 1 | +4 | 1 | 1M | | | | | . | . | | |
| 4 | SORT GROUP BY | | 45 | 17727 | 11 | +6 | 1 | 45 | | | | | 10240 | . | | |
| 5 | HASH JOIN | | 18M | 9804 | 13 | +4 | 1 | 18M | 561 | 66MB | 561 | 66MB | 59MB | 71MB | | |
| 6 | VIEW | | 1M | 2966 | 1 | +4 | 1 | 1M | | | | | . | . | | |
| 7 | TABLE ACCESS FULL | SYS_TEMP_0FD9D6645_5FF4FE | 1M | 2966 | 2 | +3 | 1 | 1M | 351 | 176MB | | | . | . | | |
| 8 | VIEW | | 1M | 2966 | 3 | +6 | 1 | 1M | | | | | . | . | | |
| 9 | TABLE ACCESS FULL | SYS_TEMP_0FD9D6645_5FF4FE | 1M | 2966 | 5 | +4 | 1 | 1M | 74 | 12MB | | | . | . | | |
=====================================================================================================================================================================================================================
1 row selected.
In this report you can see that the materialization resulted in 176MB of data being written to temp at operation 2 (highlighted line 43), which is actually more than was written to temp as the hash join spilled over from memory.
There are a number of defects in this call to dbms_sql_monitor – including the need for an extra cost license. Most particularly (a) the plan is captured only if the query runs for more than 6 seconds or has a parallel componet and (b) we’re only passing in the SQL_ID with a time limit, so we could get several executions reported. We could refine the inputs, though, by including the sql_plan_hash_value in our query against v$sql. and we might include an end-time filter.
Whatever we do to minimise the number of plans reported the point will almost certainly come where we have to do eyeball the data to see if we can identify the queries which were almost certainly running and using the temp space we needed.
How do I find the execution plans for all the SQL that is called by a procedure?
To be written
What SQL is responsible for generating most redo?
To be written
Hi Johnathan,
The v$sql_workarea dynamic performance view is great, however it does not have any history. Somewhere from 11g onwards dba_hist_active_sess_history.temp_space_allocated could be more appropiate to identify top TEMP consumers (or v$active_session_history if you are lucky enough) when compared to scanning v$sql_workarea every few minutes.
BR
Pavol Babel
Comment by Pavol Babel — August 5, 2021 @ 6:47 pm BST Aug 5,2021 |
Pavol,
Thanks for the comment.
I really should have included a link back to an article on exactly that topic that I published a couple of years ago: https://jonathanlewis.wordpress.com/2019/12/06/temp-space/
There’s a bit of room for argument on the history aspect – v$sql_workarea is, in effect, a history anyway since it holds a summary of activity over the period that the child cursor was in the library cache, which is probably a good enough guide when you’re looking at recent activity (at least, for certain values of “recent”, like the 15 minutes that I was using in the code samples).
Regards
Jonathan Lewis
Comment by Jonathan Lewis — August 5, 2021 @ 8:48 pm BST Aug 5,2021 |
[…] Finding SQL (Aug 2021): currently includes ideas on finding “who has been using up all the temporary space”. […]
Pingback by Troubleshooting catalogue | Oracle Scratchpad — February 1, 2022 @ 11:31 am GMT Feb 1,2022 |