recycle bin

How to make queries to DBA_FREE_SPACE faster

Posted by

The other day as my PC popped up its usual “Hey, you really should look at buying a bigger disk” Smile 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.

3 comments

  1. 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!

Got some thoughts? Leave a comment

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out /  Change )

Google photo

You are commenting using your Google account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s

This site uses Akismet to reduce spam. Learn how your comment data is processed.