Posted by The other day as my PC popped up its usual “Hey, you really should look at buying a bigger disk” 
message, I was motivated to see if I could clear down some of the space utilization on the myriad of databases on my machine. On the majority them I encountered no issue doing that, but on one of them, the query to DBA_FREE_SPACE revealed an odd performance issue:
SQL> set timing on
SQL> select tablespace_name,
2 sum(bytes) tot_free,
3 count(*) chunks
4 from dba_free_space
5 group by tablespace_name ;
TABLESPACE_NAME TOT_FREE CHUNKS
-------------------- ---------- ----------
SYSTEM 3866624 2
DEMO 103809024 1
SYSAUX 103677952 1
UNDOTBS1 2698706944 270
ASKTOM 122945536 102
USERS 198705152 38
7 rows selected.
Elapsed: 00:04:51.22
Nearly 5 minutes just to query DBA_FREE_SPACE! I created a brand new session and re-ran the query to see if there was some sort of I/O issue on my machine, because after all, the poor thing get slammed every day with all sorts of things, not least of which is my kids demanding to use its GPU for gaming!
SQL> select
2 event
3 ,total_waits
4 ,total_timeouts
5 ,secs
6 ,rpad(to_char(100 * ratio_to_report(secs) over (), 'FM000.00') || '%',8) pct
7 ,max_wait
8 from (
9 select
10 event
11 ,total_waits
12 ,total_timeouts
13 ,time_waited/100 secs
14 ,max_wait
15 from v$session_event
16 where sid = sys_context('USERENV','SID')
17 and event not like 'SQL*Net%'
18 );
EVENT TOTAL_WAITS TOTAL_TIMEOUTS SECS PCT MAX_WAIT
-------------------------------------------- ----------- -------------- ---------- -------------- ----------
Disk file operations I/O 5 0 0 00.00% 0
log file sync 1 0 0 00.00% 0
db file sequential read 244352 0 271.48 100.00% 1
events in waitclass Other 64 1 0 00.00% 0
You can see the time was all lost in ‘db file sequential read’ waits, but the maximum wait for these I/O’s was fine – it was just the volume of them. 244 thousand! And if you check back on the number of chunks for each tablespace, it would seem odd that I’d need to do that many reads to find that relatively small number of chunks. None of the databases on my PC are that large in size.
So just like the advice we give to people on AskTOM, I ran the query with the GATHER_PLAN_STATISTICS hint to see where all this time and I/O’s were coming from. I also did a fresh DBMS_STATS.GATHER_DICTIONARY_STATS just in case.
SQL> set serverout off
SQL> select /*+ gather_plan_statistics */ tablespace_name,
2 sum(bytes) tot_free,
3 count(*) chunks
4 from dba_free_space
5 group by tablespace_name ;
TABLESPACE_NAME TOT_FREE CHUNKS
-------------------- ---------- ----------
SYSTEM 3866624 2
DEMO 103809024 1
SYSAUX 103677952 1
UNDOTBS1 2698706944 270
ASKTOM 122945536 102
USERS 198705152 38
LARGETS 1.3993E+10 8
7 rows selected.
SQL_ID db1x4q4n8kgrs, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ tablespace_name, sum(bytes)
tot_free, count(*) chunks from dba_free_space group by
tablespace_name
Plan hash value: 190806552
-----------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | 7 |00:00:47.22 | 699K| 244K| | | |
| 1 | HASH GROUP BY | | 1 | 9 | 7 |00:00:47.22 | 699K| 244K| 1056K| 1056K| 1013K (0)|
| 2 | VIEW | DBA_FREE_SPACE | 1 | 14 | 422 |00:00:00.01 | 699K| 244K| | | |
| 3 | UNION-ALL | | 1 | | 422 |00:00:00.01 | 699K| 244K| | | |
| 4 | NESTED LOOPS | | 1 | 1 | 0 |00:00:00.01 | 12 | 0 | | | |
| 5 | NESTED LOOPS | | 1 | 1 | 0 |00:00:00.01 | 12 | 0 | | | |
|* 6 | INDEX FULL SCAN | I_FILE2 | 1 | 3 | 7 |00:00:00.01 | 1 | 0 | | | |
|* 7 | TABLE ACCESS CLUSTER | FET$ | 7 | 1 | 0 |00:00:00.01 | 11 | 0 | | | |
|* 8 | INDEX UNIQUE SCAN | I_TS# | 7 | 1 | 7 |00:00:00.01 | 4 | 0 | | | |
|* 9 | TABLE ACCESS CLUSTER | TS$ | 0 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
|* 10 | INDEX UNIQUE SCAN | I_TS# | 0 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
|* 11 | HASH JOIN | | 1 | 1 | 307 |00:00:00.01 | 67 | 0 | 1797K| 1797K| 1188K (0)|
| 12 | NESTED LOOPS | | 1 | 1 | 307 |00:00:00.01 | 50 | 0 | | | |
|* 13 | FIXED TABLE FULL | X$KTFBFE | 1 | 8 | 307 |00:00:00.01 | 46 | 0 | | | |
|* 14 | INDEX UNIQUE SCAN | I_FILE2 | 307 | 1 | 307 |00:00:00.01 | 4 | 0 | | | |
|* 15 | TABLE ACCESS FULL | TS$ | 1 | 1 | 7 |00:00:00.01 | 17 | 0 | | | |
| 16 | NESTED LOOPS | | 1 | 10 | 115 |00:01:55.93 | 699K| 244K| | | |
|* 17 | HASH JOIN | | 1 | 17 | 46 |00:00:00.01 | 22 | 0 | 1316K| 1316K| 778K (0)|
| 18 | NESTED LOOPS | | 1 | 19 | 46 |00:00:00.01 | 5 | 0 | | | |
| 19 | NESTED LOOPS | | 1 | 72 | 46 |00:00:00.01 | 4 | 0 | | | |
|* 20 | INDEX FULL SCAN | I_FILE2 | 1 | 3 | 7 |00:00:00.01 | 1 | 0 | | | |
|* 21 | INDEX RANGE SCAN | RECYCLEBIN$_TS | 7 | 24 | 46 |00:00:00.01 | 3 | 0 | | | |
| 22 | TABLE ACCESS BY INDEX ROWID| RECYCLEBIN$ | 46 | 7 | 46 |00:00:00.01 | 1 | 0 | | | |
|* 23 | TABLE ACCESS FULL | TS$ | 1 | 9 | 7 |00:00:00.01 | 17 | 0 | | | |
|* 24 | FIXED TABLE FULL | X$KTFBUE | 46 | 1 | 115 |00:00:47.14 | 699K| 244K| | | |
| 25 | NESTED LOOPS | | 1 | 1 | 0 |00:00:00.01 | 284 | 0 | | | |
| 26 | NESTED LOOPS | | 1 | 1 | 0 |00:00:00.01 | 284 | 0 | | | |
| 27 | MERGE JOIN CARTESIAN | | 1 | 138 | 336 |00:00:00.01 | 3 | 0 | | | |
|* 28 | INDEX FULL SCAN | I_FILE2 | 1 | 3 | 7 |00:00:00.01 | 1 | 0 | | | |
| 29 | BUFFER SORT | | 7 | 48 | 336 |00:00:00.01 | 2 | 0 | 2048 | 2048 | 2048 (0)|
| 30 | TABLE ACCESS FULL | RECYCLEBIN$ | 1 | 48 | 48 |00:00:00.01 | 2 | 0 | | | |
| 31 | TABLE ACCESS CLUSTER | UET$ | 336 | 1 | 0 |00:00:00.01 | 281 | 0 | | | |
|* 32 | INDEX UNIQUE SCAN | I_FILE#_BLOCK# | 336 | 1 | 41 |00:00:00.01 | 240 | 0 | | | |
|* 33 | TABLE ACCESS CLUSTER | TS$ | 0 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
|* 34 | INDEX UNIQUE SCAN | I_TS# | 0 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
| 35 | NESTED LOOPS | | 1 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
| 36 | NESTED LOOPS | | 1 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
| 37 | TABLE ACCESS FULL | NEW_LOST_WRITE_EXTENTS$ | 1 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
|* 38 | TABLE ACCESS CLUSTER | TS$ | 0 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
|* 39 | INDEX UNIQUE SCAN | I_TS# | 0 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
|* 40 | INDEX RANGE SCAN | I_FILE2 | 0 | 1 | 0 |00:00:00.01 | 0 | 0 | | | |
-----------------------------------------------------------------------------------------------------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
6 - filter(("FI"."TS#" IS NOT NULL AND "FI"."RELFILE#" IS NOT NULL))
7 - filter("F"."FILE#"="FI"."RELFILE#")
8 - access("F"."TS#"="FI"."TS#")
9 - filter("TS"."BITMAPPED"=0)
10 - access("TS"."TS#"="F"."TS#")
11 - access("TS"."TS#"="KTFBFETSN")
13 - filter(("CON_ID"=0 OR "CON_ID"=3))
14 - access("KTFBFETSN"="FI"."TS#" AND "KTFBFEFNO"="FI"."RELFILE#")
filter(("FI"."TS#" IS NOT NULL AND "FI"."RELFILE#" IS NOT NULL))
15 - filter((INTERNAL_FUNCTION("TS"."ONLINE$") AND "TS"."CONTENTS$"=0 AND "TS"."BITMAPPED"<>0 AND
BITAND("TS"."FLAGS",4503599627370496)<>4503599627370496))
17 - access("TS"."TS#"="RB"."TS#")
20 - filter(("FI"."TS#" IS NOT NULL AND "FI"."RELFILE#" IS NOT NULL))
21 - access("RB"."TS#"="FI"."TS#")
23 - filter((INTERNAL_FUNCTION("TS"."ONLINE$") AND "TS"."CONTENTS$"=0 AND "TS"."BITMAPPED"<>0 AND
BITAND("TS"."FLAGS",4503599627370496)<>4503599627370496))
24 - filter((INTERNAL_FUNCTION("CON_ID") AND "KTFBUESEGBNO"="RB"."BLOCK#" AND "KTFBUEFNO"="FI"."RELFILE#" AND "KTFBUESEGFNO"="RB"."FILE#" AND
"KTFBUESEGTSN"="RB"."TS#"))
28 - filter(("FI"."TS#" IS NOT NULL AND "FI"."RELFILE#" IS NOT NULL))
32 - access("U"."TS#"="RB"."TS#" AND "U"."SEGFILE#"="RB"."FILE#" AND "U"."SEGBLOCK#"="RB"."BLOCK#")
filter(("U"."TS#"="FI"."TS#" AND "U"."SEGFILE#"="FI"."RELFILE#"))
33 - filter("TS"."BITMAPPED"=0)
34 - access("TS"."TS#"="U"."TS#")
38 - filter((INTERNAL_FUNCTION("TS"."ONLINE$") AND BITAND("TS"."FLAGS",4503599627370496)=4503599627370496 AND "TS"."CONTENTS$"=0 AND
"TS"."BITMAPPED"<>0))
39 - access("TS"."TS#"="F"."EXTENT_DATAFILE_TSID")
40 - access("F"."EXTENT_DATAFILE_TSID"="FI"."TS#")
filter("FI"."TS#" IS NOT NULL)
Notice line 16 is a NESTED LOOP which has a cumulative total of our 244K reads. I then tracked that down to line 24 which is a full scan of the X$KTFBUE structure, but the key thing was that this scan was performed 46 times. Heading up 2 lines to lines 22, and you can see that these 46 executions were a result of 46 rows coming out of my RECYCLEBIN$ table.
Thus it looks like the performance (in this database) is related to the recyclebin. To firm up this relationship, I purged my recycle bin and re-tested the free space query
SQL> conn /@db19_pdb1 as sysdba
Connected.
SQL> purge dba_recyclebin;
DBA Recyclebin purged.
SQL> set timing on
SQL> select tablespace_name,
2 sum(bytes) tot_free,
3 count(*) chunks
4 from dba_free_space
5 group by tablespace_name ;
TABLESPACE_NAME TOT_FREE CHUNKS
-------------------- ---------- ----------
SYSTEM 3866624 2
DEMO 103809024 1
SYSAUX 103677952 1
UNDOTBS1 2698706944 270
ASKTOM 122945536 102
USERS 198705152 38
7 rows selected.
Elapsed: 00:00:00.38
Bingo! An empty recyclebin and my free space query becomes instantaneous.
On this particular database, this effect is reproducible and linear in terms of degradation, due to the nested loop. Here’s some code to demonstrate that. In a loop, I will create a table as a copy of DUAL and then drop it immediately, thus adding an object to the reyclebin. I will then run my free space query and time how long it takes to execute and fetch from it.
SQL> declare
2 s timestamp;
3 begin
4 for i in 1 .. 20 loop
5 execute immediate 'create table zz'||i||' as select * from dual';
6 execute immediate 'drop table zz'||i;
7
8 s := systimestamp;
9 for cur in (
10 select
11 tablespace_name,
12 sum(bytes) tot_free,
13 count(*) chunks
14 from dba_free_space
15 group by tablespace_name )
16 loop
17 null;
18 end loop;
19 dbms_output.put_line(i||'-'||(systimestamp-s));
20 end loop;
21 end;
22 /
1-+000000000 00:00:01.003000000
2-+000000000 00:00:01.964000000
3-+000000000 00:00:02.910000000
4-+000000000 00:00:03.954000000
5-+000000000 00:00:04.903000000
6-+000000000 00:00:05.889000000
7-+000000000 00:00:06.855000000
8-+000000000 00:00:07.729000000
9-+000000000 00:00:09.776000000
10-+000000000 00:00:10.754000000
11-+000000000 00:00:10.604000000
12-+000000000 00:00:11.606000000
13-+000000000 00:00:13.817000000
14-+000000000 00:00:13.992000000
15-+000000000 00:00:16.601000000
16-+000000000 00:00:15.626000000
17-+000000000 00:00:16.564000000
18-+000000000 00:00:19.054000000
19-+000000000 00:00:19.748000000
20-+000000000 00:00:20.553000000
PL/SQL procedure successfully completed.
You can see that each new object in the recycle bin adds some time to the execution of the query.
But here is the interesting thing. I initially discovered this on my Windows 19.6 database. To see if it was a potential bug, I patched the database to 19.8 and the slow down is still present. However, I also have several other 19.7 and 19.8 databases, both on Windows and on Linux (under VirtualBox VM’s). I did not observe this behaviour on any of those databases, no matter how many objects were in the recycle bin.
Thus its reasonable to conclude that there is some special set of dictionary statistical circumstances that will lead to this execution plan. In any event, I thought it warranted a blog post so that if you encounter this slow down on queries to DBA_FREE_SPACE, then a purge of the recycle bin will probably do the trick for you.
TL;DR: If your queries to DBA_FREE_SPACE are slow, then check your recycle bin.
Learning is not a spectator sport 
“I also have several other 19.7 and 19.8 databases, both on Windows and on Linux”
Is there a channel where i can download Oracle 19.8 db for windows OS ?
I can only see 19.3 being available:
https://www.oracle.com/database/technologies/oracle19c-windows-downloads.html
Thanks,
See here for the patch number – you download it from MOS
https://connor-mcdonald.com/2020/08/21/leaping-to-windows-19-8/
We see this issue in 12.1.0.2 databases too. It was execution plan issue. Will have to find the bug we filed and in the mean time we created sql profile to deal with it.
I will also check from this recycle bin perspective. Thanks!
We hit the same issue in ATP-S, we don’t have required privileges to purge/collect stats, so any idea, how to go about on ATP-S, where we have only admin privileges(PDB)
Thanks
you can purge dba_recyclbin on ATP-S