Look Oracle from inside (tracing internal calls) --- Execution Plan

[中文]

Author:  fuyuncat

Source:  www.HelloDBA.com

Date:  2010-06-09 03:52:11

Share to 

Oracle provided many method for us to understand its behaviors, help us to manage and improve it. Such as execution plan, statistics data, dynamic views, and even the events trace and dumping. However, as a DBA, we always want to get more informations to find its secrets, operation details. For example, when we tuning a SQL, we will get the consistent gets (Logical IOs) as an important performance reference. However, sometimes such figure may confuse us. why the logical IOs number is so high eventhough it scans an empty table? Why we get so many logical IOs even it hited index? ... In such scenario, we will want to know what the exact data blocks it got. But this is the Oracle internal behaviors, it did not provide any method to look into it. Now, let's change our view, look it from oracle inside. As we know, all of operations are finally implemented by oracle internal functions. If we can find such functions and trace their calling, we will get what we want. In unix/linux, there are several utilities to trace the call stack, such as pstack. ORADEBUG can also dump the call stacks. But such result may not enough for us. In windows (32), I built a tool (OraTracer) to trace special functions, try to detect their arguments. I will use it get the information we interested in.      WARNING: Never play OraTracer in any crytical system!  Execution Plan     Execution Plan is actually the pathes that oracle fetch the data. It's a tree structure. The leaf nodes first access the physical data to fetch data with access predications, then transfer data as row source to upper nodes. Finally, the row source output from the root node is the result of the query. In oracle internal, there is a function to implement the operation of each of the node. Tracing such functions, we will understand how does the execution plan fetch the data. They have a name like qer*Fetch*.     We will take below query as an example to trace the query execution. SQL代码 HELLODBA.COM>select /*+index(t1 t_test1_pk) index(t2 t_test2_pk) gather_sql_statistics*/      2   t1.data_object_id,      3   t2.TABLE_NAME,      4   t2.STATUS,      5   t2.NUM_ROWS,      6   t2.COMPRESSION      7    from demo.t_test1 t1, demo.t_test2 t2      8   where t1.owner = t2.owner      9     and t1.object_name = t2.table_name     10     and t1.object_id <= 1000     11     and t1.temporary='Y';       DATA_OBJECT_ID TABLE_NAME                     STATUS     NUM_ROWS COMPRESS    -------------- ------------------------------ -------- ---------- --------                   ATEMPTAB$                      VALID               DISABLED                   MAP_OBJECT                     VALID               DISABLED                   CLUSTER_DATABASES              VALID               DISABLED                   CLUSTER_NODES                  VALID               DISABLED                   CLUSTER_INSTANCES              VALID               DISABLED       HELLODBA.COM>select sql_id, child_number from v$sql where sql_text like 'select /*+index(t1 t_test1_pk) index(t2 t_test2_pk) gather_sql_statistics*/%';       SQL_ID        CHILD_NUMBER    ------------- ------------    613dpf9vps5h3            0       HELLODBA.COM>select * from table(dbms_xplan.display_cursor('613dpf9vps5h3', 0, 'ALLSTATS LAST'));       PLAN_TABLE_OUTPUT    -------------------------------------------------------------------------------------------------------------------------------       SQL_ID  613dpf9vps5h3, child number 0    -------------------------------------    select /*+index(t1 t_test1_pk) index(t2 t_test2_pk) gather_sql_statistics*/  t1.data_object_id,  t2.TABLE_NAME,  t2.STATUS,    t2.NUM_ROWS,  t2.COMPRESSION   from demo.t_test1 t1, demo.t_test2 t2  where t1.owner = t2.owner    and t1.object_name =    t2.table_name    and t1.object_id <= 1000    and t1.temporary='Y'      Plan hash value: 2465336739       -----------------------------------------------------------------------------------------------------    | Id  | Operation                    | Name       | Starts | E-Rows | A-Rows |   A-Time   | Buffers |    -----------------------------------------------------------------------------------------------------    |   1 |  NESTED LOOPS                |            |      1 |      1 |      5 |00:00:00.01 |      37 |    |*  2 |   TABLE ACCESS BY INDEX ROWID| T_TEST1    |      1 |      1 |      6 |00:00:00.01 |      24 |    |*  3 |    INDEX RANGE SCAN          | T_TEST1_PK |      1 |    952 |    910 |00:00:00.01 |       4 |    |   4 |   TABLE ACCESS BY INDEX ROWID| T_TEST2    |      6 |      1 |      5 |00:00:00.01 |      13 |    |*  5 |    INDEX UNIQUE SCAN         | T_TEST2_PK |      6 |      1 |      5 |00:00:00.01 |       8 |    -----------------------------------------------------------------------------------------------------       Predicate Information (identified by operation id):    ---------------------------------------------------          2 - filter("T1"."TEMPORARY"='Y')       3 - access("T1"."OBJECT_ID"<=1000)       5 - access("T1"."OBJECT_NAME"="T2"."TABLE_NAME" AND "T1"."OWNER"="T2"."OWNER")          25 rows selected.       From the excution plan, we know it's a nested loop join, and the driver is T_TEST1. With access predicate ("T1"."OBJECT_ID"<=1000), the 3rd operation (INDEX RANGE SCAN) got 910 rows from index T_TEST1_PK; after be filtered by predicate ("T1"."TEMPORARY"='Y'), it go 6 rows from table T_TEST1 in the 2nd operation (TABLE ACCESS BY INDEX ROWID); From the inner side, it fetch 5 rows from table T_TEST2; and finally returned 5 rows.     Now, let trace it. Get the spid (TID) of the session we want to trace first. SQL代码 HELLODBA.COM>select distinct spid from v$mystat m, v$session s, v$process p where m.sid=s.sid and s.paddr=p.addr;       SPID    ------------    8292       Config the query fetch functions as trace points in the Tracepoint.txt. You may download all of the query functions at here.     http://www.HelloDBA.com/Download/TracePoints_ALL_Query_Calls.zip     Or just config the fetch functions involved in this execution plan. SQL代码 _qerjotFetch (0*2,0*2,0*2,0*2,0*2,0*2)    _qertbFetchByRowID (0*2,0*2,0*2,0*2,0*2,0*2)    _qerixtFetch (0*2,0*2,0*2,0*2,0*2,0*2)    _qerixFetchUniqueIndex (0*2,0*2,0*2,0*2,0*2,0*2)       Here we suspect they have 6 arguments.     Config [DETECTRET]=on in the config.ini file to trace the call returning, help us to understand the recursive calling relationship.     Then, run OraTracer.exe, select "ORACLE.EXE" from the processes list, select thread with TID (8292) in threads list, click "Trace" button. And execute the query in the session be traced.     Note: To avoid recursive calls, execute the query before tracing. SQL代码 HELLODBA.COM>select /*+index(t1 t_test1_pk) index(t2 t_test2_pk) gather_sql_statistics*/      2   t1.data_object_id,      3   t2.TABLE_NAME,      4   t2.STATUS,      5   t2.NUM_ROWS,      6   t2.COMPRESSION      7    from demo.t_test1 t1, demo.t_test2 t2      8   where t1.owner = t2.owner      9     and t1.object_name = t2.table_name     10     and t1.object_id <= 1000     11     and t1.temporary='Y';       DATA_OBJECT_ID TABLE_NAME                     STATUS     NUM_ROWS COMPRESS    -------------- ------------------------------ -------- ---------- --------                   ATEMPTAB$                      VALID               DISABLED                   MAP_OBJECT                     VALID               DISABLED                   CLUSTER_DATABASES              VALID               DISABLED                   CLUSTER_NODES                  VALID               DISABLED                   CLUSTER_INSTANCES              VALID               DISABLED       Now, all of the fetch calls have been traced&logged in the log window. SQL代码 [2010-06-08 11:13:42.471]User call: _qerjotFetch (Return Addr: 0x01de3203; TID: 5148)         [Args(6)]:             0x1467fa84(=>0x10000(=>0x4c0041))            0x1de2ef8(=>0x83dc8b53(=>NULL))            0x7a3d75c(=>0x1467fa14(=>0xffff0000))            1            0x73216f8(=>0x500003e9(=>NULL))            0x7232278(=>0x4b7a2e8(=>0xa3c0308))    [2010-06-08 11:13:42.487]User call: _qertbFetchByRowID (Return Addr: 0x01de326d; TID: 5148)         [Args(6)]:             0x1472769c(=>0x20000(=>0x1000))            0            0x7a3d6c8(=>1)            1            0x3000(=>NULL)            0    [2010-06-08 11:13:42.487]User call: _qerixtFetch (Return Addr: 0x01de326d; TID: 5148)         [Args(6)]:             0x147279e4(=>0x30000(=>NULL))            0            0x7a3d424(=>1)            1            0xa3c0048(=>0)            0         _qerixtFetch return at 0x01de326d     [2010-06-08 11:13:42.518]User call: _qerixtFetch (Return Addr: 0x01de326d; TID: 5148)         [Args(6)]:             0x147279e4(=>0x30000(=>NULL))            0            0x7a3d424(=>1)            1            0x7347fd0(=>4)            0x7243814(=>0x14727358(=>0x59))         _qerixtFetch return at 0x01de326d     ...       Now, following the trace, let's walk through the plan pathes.     Correspond to the 1st operation (the root node of the plan tree, NESTED LOOPS), it first called _qerjotFetch. An interesting argument is the 4th one, which is the row number to be fetched. We noted it's just 1 row to be fetched in the 1st round fetch. Following _qerjotFetch, is _qertbFetchByRowID, which is function of the 2nd operation (TABLE ACCESS BY INDEX ROWID). And we must noted _qerjotFetch did not return yet. That means the _qertbFetchByRowID was called in _qerjotFetch. Then we can see the _qerixtFetch, which was called in _qertbFetchByRowID and map to the 3rd operation (INDEX RANGE SCAN). It accessed to the index with predicate T_TEST1_PK ("T1"."OBJECT_ID"<=1000), fetched 1 row (include the ROWID) and returned to _qertbFetchByRowID. In _qertbFetchByRowID, oracle accessed the table T_TEST1 by the ROWID, but it's filtered by the predicate ("T1"."TEMPORARY"='Y'), so it continue call _qerixtFetch to fetch another row. After fetched 333 rows from T_TEST1_PK, the result not be filtered, and _qertbFetchByRowID returned. The _qerjotFetch called another _qertbFetchByRowID, which correspond to the 4th operation, and this operation called the 5th operation, _qerixFetchUniqueIndex, to have an INDEX UNIQUE SCAN on T_TEST2_PK. The result finally returned to _qerjotFetch. Since it just need fetch 1 row in the 1st round, _qerjotFetch returned the result, and then raise the next round fetch. SQL代码 [2010-06-08 11:13:53.159]User call: _qerixtFetch (Return Addr: 0x01de326d; TID: 5148)         [Args(6)]:             0x147279e4(=>0x30000(=>NULL))            0            0x7a3d424(=>1)            1            0x7347fd0(=>4)            0x7243814(=>0x14727358(=>0x59))         _qerixtFetch return at 0x01de326d          _qertbFetchByRowID return at 0x01de326d     [2010-06-08 11:13:53.206]User call: _qertbFetchByRowID (Return Addr: 0x01de3203; TID: 5148)         [Args(6)]:             0x1467fd30(=>0x40003(=>NULL))            0x1de2ef8(=>0x83dc8b53(=>NULL))            0x7a3d680(=>0x1467faec(=>0xffff0000))            1            0xc48(=>NULL)            0x7243124(=>0x10000(=>0x4c0041))    [2010-06-08 11:13:53.222]User call: _qerixFetchUniqueIndex (Return Addr: 0x01de326d; TID: 5148)         [Args(6)]:             0x14727194(=>0x50003(=>NULL))            0            0x7a3d424(=>1)            1            0x7347fd0(=>4)            0x7243814(=>0x14727358(=>0x59))         _qerixFetchUniqueIndex return at 0x01de326d          _qertbFetchByRowID return at 0x01de3203          _qerjotFetch return at 0x01de3203     [2010-06-08 11:13:53.284]User call: _qerjotFetch (Return Addr: 0x01de3203; TID: 5148)         [Args(6)]:             0x1467fa84(=>0x10000(=>0x4c0041))            0x1de2ef8(=>0x83dc8b53(=>NULL))            0x7a3d93c(=>0x1467fa14(=>0xffff0000))            0xf(=>NULL)            0x1fc(=>NULL)            0xc00001fd(=>NULL)    [2010-06-08 11:13:53.316]User call: _qertbFetchByRowID (Return Addr: 0x01de3203; TID: 5148)         [Args(6)]:             0x1467fd30(=>0x40003(=>NULL))            0x1de2ef8(=>0x83dc8b53(=>NULL))            0x7a3d860(=>0x1467faec(=>0xffff0000))            0xf(=>NULL)            0            0    [2010-06-08 11:13:53.394]User call: _qerixFetchUniqueIndex (Return Addr: 0x01de326d; TID: 5148)         [Args(6)]:             0x14727194(=>0x50003(=>NULL))            0            0x7a3d604(=>1)            1            0x12ff675c(=>0x10ffb964(=>0x1e652550))            0x031eeb8c(=>"kcbz.c")         _qerixFetchUniqueIndex return at 0x01de326d          _qertbFetchByRowID return at 0x01de3203     [2010-06-08 11:13:53.441]User call: _qertbFetchByRowID (Return Addr: 0x01de326d; TID: 5148)         [Args(6)]:             0x1472769c(=>0x20000(=>0x1000))            0            0x7a3d8a8(=>1)            1            0            0    [2010-06-08 11:13:53.456]User call: _qerixtFetch (Return Addr: 0x01de326d; TID: 5148)         [Args(6)]:             0x147279e4(=>0x30000(=>NULL))            0            0x7a3d604(=>1)            1            0x12ff675c(=>0x10ffb964(=>0x1e652550))            0x031eeb8c(=>"kcbz.c")         _qerixtFetch return at 0x01de326d          _qertbFetchByRowID return at 0x01de326d     ...       In this round, we can note that it wanted to fetch 15 rows at most, which is the array size of client (SQL*Plus). Since the last row from the 4th operation is a matched row, it still call functions of 4th&5th operations to fetch rows, until it reached to the max row number or unmatched the predicate ("T1"."OBJECT_NAME"="T2"."TABLE_NAME" AND "T1"."OWNER"="T2"."OWNER").     The following steps repeated previous procedure. It finally completed scaning the driver table and fetched other 4 rows from T_TEST2. SQL代码 ...    [2010-06-08 11:14:12.691]User call: _qerixtFetch (Return Addr: 0x01de326d; TID: 5148)         [Args(6)]:             0x147279e4(=>0x30000(=>NULL))            0            0x7a3d604(=>1)            1            0x7347fd0(=>4)            0x7243814(=>0x14727358(=>0x59))         _qerixtFetch return at 0x01de326d     [2010-06-08 11:14:12.723]User call: _qerixtFetch (Return Addr: 0x01de326d; TID: 5148)         [Args(6)]:             0x147279e4(=>0x30000(=>NULL))            0            0x7a3d604(=>1)            1            0x7347fd0(=>4)            0x7243814(=>0x14727358(=>0x59))         _qerixtFetch return at 0x01de326d          _qertbFetchByRowID return at 0x01de326d          _qerjotFetch return at 0x01de3203        So far, we can draw another map with the internal functions mirror to the execution plan. SQL代码 -----------------------------------------------------------------------------------    | Id  |  Function                    | Name       |  Calls |Predicate     -----------------------------------------------------------------------------------    |   1 |  _qerjotFetch                |            |      2 |                          |*  2 |   _qertbFetchByRowID         | T_TEST1    |    6+1 |filter("T1"."TEMPORARY"='Y')    |*  3 |    _qerixtFetch              | T_TEST1_PK |  910+1 |access("T1"."OBJECT_ID"<=1000)    |   4 |   _qertbFetchByRowID         | T_TEST2    |    5+1 |                          |*  5 |    _qerixFetchUniqueIndex    | T_TEST2_PK |  5*2+1 |access("T1"."OBJECT_NAME"="T2"."TABLE_NAME" AND "T1"."OWNER"="T2"."OWNER")    -----------------------------------------------------------------------------------       One thing we need to know is that all the fetch functions are not called directly by the upper level function. There is a general entry function named _qerstFetch. It will find the fetch function address, convert the argments as required by the functions, then call them. And if you set to print call stacks for the leaf note function in the tree, you will get more clear picture. SQL代码 [2010-06-09 11:27:06.033]User call: _qerixtFetch (Return Addr: 0x01de326d; TID: 8292)         Call Stacks(8):            0x01de3268 (ORACLE.EXE!_qerstFetch+312)            0x022e8de6 (ORACLE.EXE!_qertbFetchByRowID+470)            0x01de3268 (ORACLE.EXE!_qerstFetch+312)            0x022c282a (ORACLE.EXE!_qerjotFetch+238)            0x01de31fe (ORACLE.EXE!_qerstFetch+206)            0x02014d13 (ORACLE.EXE!_opifch2+3099)            0x020140eb (ORACLE.EXE!_opifch+51)            0x00851749 (ORACLE.EXE!_opiodr+1097)       [2010-06-09 11:27:15.158]User call: _qerixFetchUniqueIndex (Return Addr: 0x01de326d; TID: 8292)         Call Stacks(8):            0x01de3268 (ORACLE.EXE!_qerstFetch+312)            0x022e8de6 (ORACLE.EXE!_qertbFetchByRowID+470)            0x01de31fe (ORACLE.EXE!_qerstFetch+206)            0x022c27ef (ORACLE.EXE!_qerjotFetch+179)            0x01de31fe (ORACLE.EXE!_qerstFetch+206)            0x02014d13 (ORACLE.EXE!_opifch2+3099)            0x020140eb (ORACLE.EXE!_opifch+51)            0x00851749 (ORACLE.EXE!_opiodr+1097)       You can download the OraTracer at here:     http://www.HelloDBA.com/Download/OraTracer.zip     --- Fuyuncat ---