Another in my MEEK (maybe everyone else knows) series…
Without going into too much detail I found myself looking at parameters for “buffer busy waits” after getting a report that a single statement had spent over 5 hours waiting on this event!
The output below shows the parameters for the “buffer busy waits” as they occurred:
SQL> select p1, p2, p3, count(*) from gv$session
2 where event = 'buffer busy waits' group by p1, p2, p3;
P1 P2 P3 COUNT(*)
---------- ---------- ---------- ----------
5002 2 13 42
SQL>
Finding the file and block is easy right? For the file you just take P1 (for file#) and query v$datafile on file#, as covered in the documentation here and to find the segment use both P1 (for file#) and P2 (for block#) with the query found here.
All cool. Well, until you get this:
SQL> select name from v$datafile where file# = 5002;
no rows selected
SQL>
My next thought was, “OK, what about v$tempfile?”
SQL> select name from v$tempfile where file# = 5002;
no rows selected
SQL>
Working on this was not a priority to the project, but it had me confused so kept rattling about in my head. I asked a few people, but that didn’t turn up any ideas regarding this apparently missing file.
I kept coming back to it when I had a few spare minutes and the person with the original issue would periodically ask me if I’d worked it out yet, just to make sure I had not forgotten him. He was convinced it was temporary tablespace related and I was happy to believe that he was right, but I needed proof. I needed to understand where the wait event parameters were coming from…
One thing that made me question the temporary tablespace theory was that the trace file I’d generated from one of the parallel slaves during a re-run of the statement, to confirm the problem was not intermittent, did not show any “temp” specific wait events. All I had in the trace for file#=5002 were:
- ‘buffer busy waits’
- ‘db file single write’
- ‘gc buffer busy acquire’
- ‘gc buffer busy release’
- ‘gc current multi block request’
- ‘local write wait’
I shouldn’t have let that sway me. It wasn’t a complete trace.
I’d done a fair bit of digging on MOS, but hadn’t been able to find anything applicable so I turned to Google. I guess I hit upon the right search term as I found this thread on Oracle-L which points out that the file# for tempfiles in wait events and trace files is db_files (parameter) + v$tempfile.file#.
This tied up nicely. db_files was set to 5000 and we had a couple of temporary tablespaces…
I passed this information back and said I’d look for official documentation that confirms this. After a bit of searching in MOS and the documentation I gave up, having realised that I could easily verify the “theory” on my local XE installation. After all, empirical evidence is what counts… The information may be there in MOS or the documentation, I just failed to find it!
For anyone interested in the test, this is what I did:
SQL> col name for a60
SQL> select file#, name from v$tempfile
FILE# NAME
---------- ------------------------------------------------------------
1 C:\ORACLEXE\APP\ORACLE\ORADATA\XE\TEMP.DBF
SQL> show parameter db_files
NAME TYPE VALUE
------------------------------------ ----------- ------------------------------
db_files integer 200
SQL> create global temporary table gtt (c1 number);
Table created.
SQL> exec dbms_session.session_trace_enable
PL/SQL procedure successfully completed.
SQL> insert into gtt select rownum from dual connect by rownum <= 10000;
10000 rows created.
SQL> exec dbms_session.session_trace_disable
PL/SQL procedure successfully completed.
SQL> conn / as sysdba
Connected.
SQL> alter system set db_files = 100 scope = spfile;
System altered.
SQL> startup force
.
.
.
SQL> conn mnash
Enter password:
Connected.
SQL> exec dbms_session.session_trace_enable
PL/SQL procedure successfully completed.
SQL> insert into gtt select rownum from dual connect by rownum <= 10000;
10000 rows created.
SQL> exec dbms_session.session_trace_disable
PL/SQL procedure successfully completed.
SQL>
As you’d expect writing rows to a global temporary table will write to the temporary tablespace and inspecting the two trace files shows that file# (actually “fileno” on Windows) changes by the change in the db_files parameter.
From trace file 1
WAIT #255303800: nam='Disk file operations I/O' ela= 21086 FileOperation=2 fileno=201 filetype=2 obj#=-1 tim=283987684761
From trace file 2
WAIT #1086755940: nam='Disk file operations I/O' ela= 3527 FileOperation=2 fileno=101 filetype=2 obj#=-1 tim=285287446239
ORAganism 