2008/10/28

Неудачные значения при bind peeking.

Проводя ежедневный осмотр моей боевой БД, обнаружил долгоиграющий запрос. На 3 запуска более 80000 секунд времени исполняния (по данным v$sql). Естественно, не дожидаясь отклика "благодарных" пользователей начал исследовать это явление.

Промышленная база версии 10.2.0.4.
Для иллюстрации буду использовать вот такие тестовые данные:

create table t1 as select * from all_objects;
create table t2 as select * from all_objects;
create index t1_i1 on t1(owner,object_type);
create index t2_i1 on t2(owner,object_type);
exec dbms_stats.gather_table_stats(null,'t1',cascade=>true,method_opt=>'for all indexed columns size 254')
exec dbms_stats.gather_table_stats(null,'t2',cascade=>true,method_opt=>'for all indexed columns size 254')

переменные:

variable p_owner varchar2(30)
variable p_type varchar2(20)

запрос:

select /*+gather_plan_statistics*/ count(1)
from t1,t2 where t1.owner=t2.owner and t1.object_type=t2.object_type
and t1.owner=:p_owner and t1.object_type=:p_type;

А теперь, собственно, ход исследования. Предполагается, что запрос уже кем-то где-то в приложении запущен, и моя задача найти и проанализировать информацию о нём.
Сначала получаю план из разделяемого пула:

SQL> select * from table(dbms_xplan.display_cursor('gmf7sa93m8tk4',null,'LAST ALLSTATS'));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------
SQL_ID gmf7sa93m8tk4, child number 0
-------------------------------------
select /*+gather_plan_statistics*/ count(1) from t1,t2 where t1.owner=t2.owner and
t1.object_type=t2.object_type and t1.owner=:p_owner and t1.object_type=:p_type

Plan hash value: 1472244417

--------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:04.28 | 8 | | | |
| 2 | MERGE JOIN CARTESIAN| | 1 | 1 | 516K|00:00:03.10 | 8 | | | |
|* 3 | INDEX RANGE SCAN | T2_I1 | 1 | 1 | 719 |00:00:00.01 | 4 | | | |
| 4 | BUFFER SORT | | 719 | 1 | 516K|00:00:01.04 | 4 | 73728 | 73728 | |
|* 5 | INDEX RANGE SCAN | T1_I1 | 1 | 1 | 719 |00:00:00.01 | 4 | | | |
--------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

3 - access("T2"."OWNER"=:P_OWNER AND "T2"."OBJECT_TYPE"=:P_TYPE)
5 - access("T1"."OWNER"=:P_OWNER AND "T1"."OBJECT_TYPE"=:P_TYPE)

По статистике выполнения видно, что как минимум, тип соединения не подходит для данных, которые обрабатываются (результирующая кардинальность на шаге 2 плана крайне отличается от прогнозируемой).

Первая гипотеза - неужели статистика устарела? Хотя автоматический сбор статистики не отключал...

Пробую получить план "непосредтсвенно от CBO":

SQL> explain plan for
2 select /*+gather_plan_statistics*/ count(1)
3 from t1,t2 where t1.owner=t2.owner and t1.object_type=t2.object_type
4 and t1.owner=:p_owner and t1.object_type=:p_type;

Explained.

SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------
Plan hash value: 1849716936

----------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 30 | 3 (34)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 30 | | |
|* 2 | HASH JOIN | | 11125 | 325K| 3 (34)| 00:00:01 |
|* 3 | INDEX RANGE SCAN| T2_I1 | 103 | 1545 | 1 (0)| 00:00:01 |
|* 4 | INDEX RANGE SCAN| T1_I1 | 108 | 1620 | 1 (0)| 00:00:01 |
----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("T1"."OWNER"="T2"."OWNER" AND
"T1"."OBJECT_TYPE"="T2"."OBJECT_TYPE")
3 - access("T2"."OWNER"=:P_OWNER AND "T2"."OBJECT_TYPE"=:P_TYPE)
4 - access("T1"."OWNER"=:P_OWNER AND "T1"."OBJECT_TYPE"=:P_TYPE)

Результат несколько озадачивает - совершенно нормальный план (способ доступа и тип соединения). Почему же в разделяемом пуле нечто совершенно другое? В общем, отбрасываю версию об устаревшей статистике.

После недолгих раздумий начинаю вспоминать недавно прочитанное у Джонатана Льюса (см. ссылку внизу). Возникает вторая гипотеза - влияние bind peeking.

Проверяю текущие значения переменных привязки:

SQL> select last_captured,name,datatype_string,value_string from v$sql_bind_capture
2 where sql_id='gmf7sa93m8tk4';

LAST_CAPTURED NAME DATATYPE_STRING
------------------- ------------------------------ ---------------
VALUE_STRING
---------------------------------------------------------------------
28/10/2008 21:27:37 :P_OWNER VARCHAR2(32)
SYS

28/10/2008 21:27:37 :P_TYPE VARCHAR2(32)
TABLE

Строю план, заменяя переменные литералами с соответствующими текущим значениями:

SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------
Plan hash value: 1962103783

----------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
----------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 30 | 11 (46)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 30 | | |
|* 2 | HASH JOIN | | 678K| 19M| 11 (46)| 00:00:01 |
|* 3 | INDEX RANGE SCAN| T1_I1 | 812 | 12180 | 3 (0)| 00:00:01 |
|* 4 | INDEX RANGE SCAN| T2_I1 | 835 | 12525 | 3 (0)| 00:00:01 |
----------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("T1"."OWNER"="T2"."OWNER" AND
"T1"."OBJECT_TYPE"="T2"."OBJECT_TYPE")
3 - access("T1"."OWNER"='SYS' AND "T1"."OBJECT_TYPE"='TABLE')
4 - access("T2"."OWNER"='SYS' AND "T2"."OBJECT_TYPE"='TABLE')

Очевидно, что запрос из разделяемого пула разбирался при других значениях переменных. Проверяю что было при разборе (в следующем отчете среди прочего выводятся значения переменных привязки, которые использовались при разборе запроса):

SQL> select * from table(dbms_xplan.display_cursor('gmf7sa93m8tk4',null,'typical +peeked_binds'));

PLAN_TABLE_OUTPUT
-----------------------------------------------------------------------------
SQL_ID gmf7sa93m8tk4, child number 0
-------------------------------------
select /*+gather_plan_statistics*/ count(1) from t1,t2 where
t1.owner=t2.owner and t1.object_type=t2.object_type and
t1.owner=:p_owner and t1.object_type=:p_type

Plan hash value: 1472244417

-------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | | | 2 (100)| |
| 1 | SORT AGGREGATE | | 1 | 30 | | |
| 2 | MERGE JOIN CARTESIAN| | 1 | 30 | 2 (0)| 00:00:01 |
|* 3 | INDEX RANGE SCAN | T2_I1 | 1 | 15 | 1 (0)| 00:00:01 |
| 4 | BUFFER SORT | | 1 | 15 | 1 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | T1_I1 | 1 | 15 | 1 (0)| 00:00:01 |
-------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - :P_OWNER (VARCHAR2(30), CSID=171): 'SCOTT'
2 - :P_TYPE (VARCHAR2(30), CSID=171): 'TABLE'

Predicate Information (identified by operation id):
---------------------------------------------------

3 - access("T2"."OWNER"=:P_OWNER AND "T2"."OBJECT_TYPE"=:P_TYPE)
5 - access("T1"."OWNER"=:P_OWNER AND "T1"."OBJECT_TYPE"=:P_TYPE)


Наконец, перепроверяю вторую гипотезу:

SQL> explain plan for
2 select /*+gather_plan_statistics*/ count(1)
3 from t1,t2 where t1.owner=t2.owner and t1.object_type=t2.object_type
4 and t1.owner='SCOTT' and t1.object_type='TABLE';

Explained.

SQL> select * from table(dbms_xplan.display);

PLAN_TABLE_OUTPUT
-------------------------------------------------------------------------------
Plan hash value: 1472244417

-------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | 30 | 2 (0)| 00:00:01 |
| 1 | SORT AGGREGATE | | 1 | 30 | | |
| 2 | MERGE JOIN CARTESIAN| | 1 | 30 | 2 (0)| 00:00:01 |
|* 3 | INDEX RANGE SCAN | T2_I1 | 1 | 15 | 1 (0)| 00:00:01 |
| 4 | BUFFER SORT | | 1 | 15 | 1 (0)| 00:00:01 |
|* 5 | INDEX RANGE SCAN | T1_I1 | 1 | 15 | 1 (0)| 00:00:01 |
-------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

3 - access("T2"."OWNER"='SCOTT' AND "T2"."OBJECT_TYPE"='TABLE')
5 - access("T1"."OWNER"='SCOTT' AND "T1"."OBJECT_TYPE"='TABLE')

Так и есть, разбор происходил при не очень удачных значениях переменных привязки.
Возникает законный вопрос: как бороться с этим? Изящное решение проблемы находися в следующей версии - Oracle 11g. Я имею ввиду новшество "Intelligent Cursor Sharing".

Там аналогичная ситуация выглядела бы вот так:

SQL> begin
2 :p_owner:='SCOTT'; :p_type:='SEQUENCE';
3 end;
4 /

PL/SQL procedure successfully completed.

SQL> select /*+gather_plan_statistics*/ count(1)
2 from t1,t2 where t1.owner=t2.owner and t1.object_type=t2.object_type
3 and t1.owner=:p_owner and t1.object_type=:p_type;

COUNT(1)
----------
0

SQL> select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID gmf7sa93m8tk4, child number 0
-------------------------------------
select /*+gather_plan_statistics*/ count(1) from t1,t2 where
t1.owner=t2.owner and t1.object_type=t2.object_type and
t1.owner=:p_owner and t1.object_type=:p_type

Plan hash value: 2988039147

--------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:00.01 | 2 | | | |
| 2 | MERGE JOIN CARTESIAN| | 1 | 1 | 0 |00:00:00.01 | 2 | | | |
|* 3 | INDEX RANGE SCAN | T1_I1 | 1 | 1 | 0 |00:00:00.01 | 2 | | | |
| 4 | BUFFER SORT | | 0 | 1 | 0 |00:00:00.01 | 0 | 73728 | 73728 | |
|* 5 | INDEX RANGE SCAN | T2_I1 | 0 | 1 | 0 |00:00:00.01 | 0 | | | |
--------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

3 - access("T1"."OWNER"=:P_OWNER AND "T1"."OBJECT_TYPE"=:P_TYPE)
5 - access("T2"."OWNER"=:P_OWNER AND "T2"."OBJECT_TYPE"=:P_TYPE)

...

SQL> begin
2 :p_owner:='SYS'; :p_type:='TABLE';
3 end;
4 /

SQL> select /*+gather_plan_statistics*/ count(1)
2 from t1,t2 where t1.owner=t2.owner and t1.object_type=t2.object_type
3 and t1.owner=:p_owner and t1.object_type=:p_type;

COUNT(1)
----------
872356

SQL> select * from table(dbms_xplan.display_cursor(null,null,'allstats last +peeked_binds'));

PLAN_TABLE_OUTPUT
----------------------------------------------------------------------------------
SQL_ID gmf7sa93m8tk4, child number 1
-------------------------------------
select /*+gather_plan_statistics*/ count(1) from t1,t2 where
t1.owner=t2.owner and t1.object_type=t2.object_type and
t1.owner=:p_owner and t1.object_type=:p_type

Plan hash value: 1849716936

-----------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------
| 1 | SORT AGGREGATE | | 1 | 1 | 1 |00:00:02.43 | 10 | | | |
|* 2 | HASH JOIN | | 1 | 1824K| 872K|00:00:00.88 | 10 | 909K| 909K| 361K (0)|
|* 3 | INDEX RANGE SCAN| T2_I1 | 1 | 1321 | 934 |00:00:00.01 | 5 | | | |
|* 4 | INDEX RANGE SCAN| T1_I1 | 1 | 1381 | 934 |00:00:00.01 | 5 | | | |
-----------------------------------------------------------------------------------------------------------------

Peeked Binds (identified by position):
--------------------------------------

1 - (VARCHAR2(30), CSID=171): 'SYS'
2 - (VARCHAR2(30), CSID=171): 'TABLE'

Predicate Information (identified by operation id):
---------------------------------------------------

2 - access("T1"."OWNER"="T2"."OWNER" AND "T1"."OBJECT_TYPE"="T2"."OBJECT_TYPE")
3 - access("T2"."OWNER"=:P_OWNER AND "T2"."OBJECT_TYPE"=:P_TYPE)
4 - access("T1"."OWNER"=:P_OWNER AND "T1"."OBJECT_TYPE"=:P_TYPE)

После изменения значений переменных произошел повторный разбор, в итоге новый child cursor и новый, а главное - подходящий план.
А для используемой мною версии Oracle Database 10.2.0.4, простых решений вероятно не существует. Можно например вытеснять из разделяемого пула выбранный разобранный запрос (dbms_shared_pool.purge). Возможно для некоторых случаев подойдет принудительный (не автоматический) периодичесикий сбор статистики без гистограмм, с последующей фиксацией (dbms_stats.lock_table_stats).

Ссылки:
Jonathan Lewis "Bind Capture"
Troubleshooting Oracle Performance by Christian Antognini