Эта статья посвящена анализу результатов работы утилиты tkprof и выявлению причин проблем производительности, о которых эти результаты свидетельствуют.
Анализ результатов tkprof
Том!
Я пытаюсь интерпретировать следующий результат, и не понимаю, в чем дело. В таблице TRACE - всего 220 строк. Что ты думаешь по этому поводу?
********************************************************************************
select TRACE01.TYPE ,TRACE01.STATUS ,TRACE01.SEQUENCE into :b0,:b1,:b2
from
TRACE TRACE01 where TRACE01.TYPE=NVL(RTRIM(:b3,' '),' ')
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.01 0.00 0 0 0 0
Execute 19012 3.10 3.56 0 0 0 0
Fetch 19012 1056.38 1517.15 0 43282981 76048 19012
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 38028 1059.49 1520.71 0 43282981 76048 19012
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 33 (OPS$MAXBATCH)
Rows Row Source Operation
------- ---------------------------------------------------
4905 TABLE ACCESS FULL TRACE
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
4905 TABLE ACCESS GOAL: ANALYZED (FULL) OF 'TRACE'
********************************************************************************
Ответ Тома Кайта
Метка максимального уровня (high water mark - HWM) (максимальный размер таблицы за все время существования) очень велика (около 2275 блоков). Однажды в таблице было намного больше 220 строк.
При полном просмотре (full scan) таблица просматривается вплоть до HWM. Рассмотрим пример:
ops$tkyte@ORA817DEV.US.ORACLE.COM> create table t pctfree 90 pctused 10
2 as
3 select * from all_objects;
Table created.
ops$tkyte@ORA817DEV.US.ORACLE.COM> delete from t where object_id <> 55;
23663 rows deleted.
ops$tkyte@ORA817DEV.US.ORACLE.COM> commit;
Commit complete.
ops$tkyte@ORA817DEV.US.ORACLE.COM> set autotrace on
ops$tkyte@ORA817DEV.US.ORACLE.COM> select object_name from t;
OBJECT_NAME
------------------------------
I_UGROUP1
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE
1 0 TABLE ACCESS (FULL) OF 'T'
Statistics
----------------------------------------------------------
0 recursive calls
27 db block gets
5395 consistent gets
0 physical reads
130980 redo size
377 bytes sent via SQL*Net to client
425 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
ops$tkyte@ORA817DEV.US.ORACLE.COM> set autotrace off
Видите - 5395 consistent gets - потому что таблица была вот аткой большой. Для уменьшения значения HWM надо либо удалить (drop) таблицу, либо усечь (truncate), и заново заполнить ее строками. В вашем случае, однако, индекс по столбцу TYPE тоже "решит" проблему.
ops$tkyte@ORA817DEV.US.ORACLE.COM> create table tmp as select * from t;
Table created.
ops$tkyte@ORA817DEV.US.ORACLE.COM> truncate table t;
Table truncated.
ops$tkyte@ORA817DEV.US.ORACLE.COM> insert into t select * from tmp;
1 row created.
ops$tkyte@ORA817DEV.US.ORACLE.COM> drop table tmp;
Table dropped.
ops$tkyte@ORA817DEV.US.ORACLE.COM> set autotrace on
ops$tkyte@ORA817DEV.US.ORACLE.COM> select object_name from t;
OBJECT_NAME
------------------------------
I_UGROUP1
Execution Plan
----------------------------------------------------------
0 SELECT STATEMENT Optimizer=CHOOSE
1 0 TABLE ACCESS (FULL) OF 'T'
Statistics
----------------------------------------------------------
0 recursive calls
4 db block gets
1 consistent gets
0 physical reads
0 redo size
377 bytes sent via SQL*Net to client
425 bytes received via SQL*Net from client
2 SQL*Net roundtrips to/from client
0 sorts (memory)
0 sorts (disk)
1 rows processed
ops$tkyte@ORA817DEV.US.ORACLE.COM> set autotrace off
Как видите, в результате мы получаем 1 consistent get...
Как сбросить HWM?
Том!
У меня есть таблица, увеличивающаяся в размерах со, скажем, 200 строк утром до, примерно, 11000 строк вечером, когда пакетное задание удаляет из нее строки. Поскольку эта таблица хранит данные сеансов, она очень интенсивно используется. Какой подход следует применять, чтобы гарантироват актуальности статистической информации в течение дня и сбрасывать HWM по вечерам, чтобы стоимостной оптимизатор не вел себя так, как было продемонстрировано в твоем примере? Можно ли сбросить значение HWM, не теряя доступа к данным?
В твоем примере, если проанализовать таблицу t после удаления, что это даст?
Ответ Тома Кайта
Я продемонстрировал два способа уменьшить значение HWM для простой таблицы: truncate и drop.
Для понижения значения HWM используйте промежуточную таблицу+truncate+insert.
Видимо, у вас таблица просматривается полностью каждый раз, индексо нет, так что, актуальность статистической информации, вероятно, не имеет значения. Но если индексы есть - анализируйте таблицу периодически в течение дня. При 11000 строк для этого потребуется несколько секунд.
Относительно последнего вопроса, см. это обсуждение...
Alter table move
Привет, Том!
Вместо использования промежуточной таблицы+truncate+insert для понижения значения HWM я предпочитаю использовать "alter table t move". Нужен всего один оператор и гарантируется отсутствие конфликтов с любыми ограничениями целостности, индексами триггерами и т.п.
Откуда 2275 блоков?
Том, как ты определил, что в таблице 2275 блоков?
Ответ Тома Кайта
ops$tkyte@ORA920> select 43282981/19012 from dual;
43282981/19012
--------------
2276.61377
query mode gets делится на количество выполнений запроса.
Уточнение
query mode gets делится на количество выполнений запроса.
Не дает ли эта формула количество блоков, выбираемых при каждом выполнении? Как это может дать нам общее количество блоков в таблице?
И еще, почему количество строк, которое возвращает tkprof (19012) отличается от указанного в плане выполнения (4905)?
Ответ Тома Кайта
Rows Row Source Operation ------- --------------------------------------------------- 4905 TABLE ACCESS FULL TRACE
TABLE ACCESS FULL - значит, при каждом выполнении был прочитан каждый блок. Берем общее количество блоков, прочитанных при многократном выполнении запроса, и делим на количество выполнений. Получаем количество блоков в таблице...
Количество строк не отличается - значение 4905 не является частью плана выполнения запроса. Это - количество строк, прошедших через соответствующую стадию плана выполнения при реальном выполнении (другими словами, это действительное значение, так оно и было).
Далее, не стоит надеяться, что ПРЕДПОЛАГАЕМОЕ количество строк (ESTIMATED cardinality) всегда будет совпадать или онемного тличаться от реального. Это же ПРЕДПОЛОЖЕНИЯ.
Спасибо... Комментарий читателя от 17 декабря 2002 года
Том,
Расчет количества блоков в таблице теперь мне намного понятнее, спасибо.
Что касается количества строк: в исходном вопросе сказано, что в таблице около 220 строк. Строк через стадию TABLE ACCESS FULL прошло 4905 (> 220). По результатам tkprof, за 19012 выполнений было обработано 19012 строк. Не мог бы ты объяснить, как все это соотносится?
Ответ Тома Кайта
Хорошо, потребовалось немного подумать, но вот их ситуация, воспроизведенная с точностью до деталей:
ops$tkyte@ORA817DEV.US.ORACLE.COM> create table t (x int, y char(2000)) pctfree 90 pctused 10; Table created. ops$tkyte@ORA817DEV.US.ORACLE.COM> insert into t select rownum, rownum from all_objects where rownum < 2275; 2274 rows created. ops$tkyte@ORA817DEV.US.ORACLE.COM> commit; Commit complete. ops$tkyte@ORA817DEV.US.ORACLE.COM> delete from t where x > 220; 2054 rows deleted. ops$tkyte@ORA817DEV.US.ORACLE.COM> commit; Commit complete. ops$tkyte@ORA817DEV.US.ORACLE.COM> exec show_space( 'T' ) Free Blocks.............................2054 Total Blocks............................2304 Total Bytes.............................18874368 Unused Blocks...........................29 Unused Bytes............................237568 Last Used Ext FileId....................7 Last Used Ext BlockId...................38793 Last Used Block.........................35 PL/SQL procedure successfully completed.
Итак, у нас есть такая же таблица - такое же количество блоков и строк. Теперь сымитируем их процесс.
Помните - у них было 4 анализа, так что я тоже организую 4 анализа:
ops$tkyte@ORA817DEV.US.ORACLE.COM> alter session set sql_trace=true; Session altered. ops$tkyte@ORA817DEV.US.ORACLE.COM> declare 2 l_rec t%rowtype; 3 begin 4 for i in 1 .. 19012 5 loop 6 begin 7 if ( mod(i,4) = 0 ) 8 then 9 select * into l_rec from t where x = mod(i,220)+1; 10 elsif ( mod(i,4) = 1 ) 11 then 12 select * into l_rec from t where x = mod(i,220)+1; 13 elsif ( mod(i,4) = 2 ) 14 then 15 select * into l_rec from t where x = mod(i,220)+1; 16 else 17 select * into l_rec from t where x = mod(i,220)+1; 18 end if; 19 exception 20 when no_data_found then null; 21 end; 22 end loop; 23 end; 24 / PL/SQL procedure successfully completed.
Теперь вызовем утилиту tkprof со стандартными установками (в частности, aggregate=YES, так что будет один общий отчет для представленных выше 4 запросов - текст у них одинаковый, так что, имеет смысл их объединить:
SELECT * FROM T WHERE X = MOD (:b1,220) + 1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 4 0.00 0.00 0 0 0 0 Execute 19012 2.05 1.95 0 0 0 0 Fetch 19012 536.14 537.00 0 43234322 133084 19012 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 38028 538.19 538.95 0 43234322 133084 19012 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 605 (recursive depth: 1) Rows Row Source Operation ------- --------------------------------------------------- 4753 TABLE ACCESS FULL T
Знакомые результаты? Примерно такое же количество query mode gets (постоянный полный просмотр 2275 блоков)...
Такое же количество обработанных строк, 19012.
В плане выполнения запроса - 4753 строки. Почему именно столько, а не одно из следующих значений:
220*19012 или 19012 ???
Чтобы понять это, надо разобраться, что это вообще за число. 4735 - это количество строк НА ВЫХОДЕ полного просмотра (поэтому по 220 строк за каждый полный просмотр быть не может, поскольку запрос возвращает при каждом просмотре всего одну строку. Как максимум, в данном случае можно ожидать 19012 строк).
Ну, так и почему 4735? Это следствие того, что запрос анализировался 4 раза (для него в определенный момент было 4 курсора, как я явно и сделал) И использовался стандартный параметр aggregate=yes в командной строке tkprof.
Aggregate = yes приводит к агрегированию всех записей EXEC (со значениями consistent gets, cpu time и т.д.), но при этом не могут и не должны агрегироваться записи STAT. Записи STAT - это фактические планы выполнения запросов с количеством строк на выходе соответствующего шага (учтите: в версиях вплоть до 8.0 выдавалось количество строк НА ВХОДЕ каждой стадии). Есть 4 набора записей stat в результатах этого вызова tkprof, поскольку было четыре запроса. Вы видите записи stat только ДЛЯ ОДНОГО ИЗ НИХ. При вызове tkprof с параметром aggregate = no, я получил:
SELECT * FROM T WHERE X = MOD (:b1,220) + 1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 4753 0.56 0.36 0 0 0 0 Fetch 4753 134.05 134.48 0 10809356 33271 4753 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 9507 134.61 134.84 0 10809356 33271 4753 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 605 (recursive depth: 1) Rows Row Source Operation ------- --------------------------------------------------- 4753 TABLE ACCESS FULL T -------------------------------------------------------------------------------- SELECT * FROM T WHERE X = MOD (:b1,220) + 1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 4753 0.60 0.62 0 0 0 0 Fetch 4753 133.89 134.01 0 10808322 33271 4753 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 9507 134.49 134.63 0 10808322 33271 4753 Misses in library cache during parse: 0 Optimizer goal: CHOOSE Parsing user id: 605 (recursive depth: 1) Rows Row Source Operation ------- --------------------------------------------------- 4753 TABLE ACCESS FULL T SELECT * FROM T WHERE X = MOD (:b1,220) + 1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 4753 0.42 0.44 0 0 0 0 Fetch 4753 134.19 134.15 0 10808322 33271 4753 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 9507 134.61 134.59 0 10808322 33271 4753 Misses in library cache during parse: 0 Optimizer goal: CHOOSE Parsing user id: 605 (recursive depth: 1) Rows Row Source Operation ------- --------------------------------------------------- 4753 TABLE ACCESS FULL T -------------------------------------------------------------------------------- SELECT * FROM T WHERE X = MOD (:b1,220) + 1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 4753 0.47 0.53 0 0 0 0 Fetch 4753 134.01 134.36 0 10808322 33271 4753 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 9507 134.48 134.89 0 10808322 33271 4753 Misses in library cache during parse: 0 Optimizer goal: CHOOSE Parsing user id: 605 (recursive depth: 1) Rows Row Source Operation ------- --------------------------------------------------- 4753 TABLE ACCESS FULL T
Видите - 4 плана, 4 запроса, и 4 записи stat, каждая с 4753 строками в плане запроса И в столбце rows. Все их надо складывать, но при "агрегировании" утилитой tkprof они не складываются.
Утилита tkprof показывает, что parses=execute. Что делать?
У меня parses=execute=4, fetch=8 при единственной выбираемой строке. consistent gets=1.
Все остальные результаты tkprof, вроде, в порядке.
SELECT ROWID,UNIT_CODE, NAME, DEPT, ADDR_1, ADDR, LOCATION, STATE,
POSTAL_CODE, COUNTRY, COMPANY_DOCTOR, DOCTOR_ROLE, CONTACT_PHONE_NO,
CONTACT_FAX_NO, FDA_REGISTRATION_NUMBER, DATABASE_ID, TYPE_COMPANY_UNIT,
USER_ID, TO_CHAR(DATE_MODIFIED,'YYYY-MM-DD HH24:MI:SS'),
TO_CHAR(DATE_CREATED,'YYYY-MM-DD HH24:MI:SS'), RECORD_ID, UNIT_TYPE_FLAG,
DGFPS_NO, INTERCHANGE_ID, E2B_FILE_FORMAT
FROM
COMPANY_UNIT Where UNIT_CODE = 'BIO'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 0.00 0 0 0 0
Fetch 8 0.00 0.00 0 8 0 4
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 16 0.00 0.00 0 8 0 4
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 43
Rows Row Source Operation
------- ---------------------------------------------------
1 TABLE ACCESS BY INDEX ROWID COMPANY_UNIT
1 INDEX UNIQUE SCAN (object id 25233)
В книге Expert one on one... вы рекомендуете использовать связываемые перменные, но здесь мне нужна константа.
В другом тесте я получил parse=execute=fetch=159 при том же количестве обработанных строк. Как это понять?
Ответ Тома Кайта
Вам надо найти программиста, который написал этот код, и научить его правилу "анализировать один раз, выполнять - много раз, курсор без крайней надобности не закрывать"
Это поможет исправить количество parse - оно должно быть равно 1. Количество fetch тоже должно быть равно 4 - код у них написан примерно так:
prepare open fetch fetch close
а надо:
if ( первый_раз ) prepare open fetch using array fetch size of 2
То же и в более "вопиющем" примере с количеством 159. Это - ошибка программирования, которую допустили разработчики. Они слишком рано закрывают курсор.
Row source 0
Том!
Я уверен, что ты писал где-то о том, почему значение "rows" в результатах работы tkprof иногда 0. Не мог бы ты дать ссылку на эту статью - мне не удается ее найти...
Ответ Тома Кайта
Я лично такой статьи не помню... Если в результатах tkprof есть план выполнения и параметр explain=пользователь/пароль не задавался, значит, записи STAT были.
Возможно, вы используете параметр explain=пользователь/пароль для генерации плана? Например, если я сделаю так:
SQL> alter session set sql_trace=true; SQL> select * from emp; SQL> host <теперь запустить tkprof с параметром explain=пользователь/пароль>
Я получаю:
select * from emp
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 4 0 14
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 315 (OPS$TKYTE)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
0 TABLE ACCESS (FULL) OF 'EMP'
а если потом выйти и вернуться в sqlplus:
$ exit SQL> exit
а затем выйти и из sqlplus (закрывая файл трассировки), и снова запустить tkprof, получим следующий результат:
select * from emp
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 0.00 0.00 0 4 0 14
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 0.00 0 4 0 14
Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 315 (OPS$TKYTE)
Rows Row Source Operation
------- ---------------------------------------------------
14 TABLE ACCESS FULL OBJ#(48637) (cr=4 r=0 w=0 time=226 us)
Rows Execution Plan
------- ---------------------------------------------------
0 SELECT STATEMENT GOAL: CHOOSE
14 TABLE ACCESS (FULL) OF 'EMP'
Так что, может быть, вы видите план выполнения с нулями, и это просто означает "все курсоры были не закрыты ИЛИ файл трассировки был усечен - достигнуто значение max dump size"...
Consistent gets?
Уважаемый Том!
По твоему ответу я понял, что большие значения consistent gets - это не очень хорошо, и причиной может быть очень большое значение HWM или большой размер таблицы. Для решения этой проблемы используется либо оператор alter table ... move, либо экспорт/импорт.
Меня интересует, как узнать, что у таблицы очень большое значение HWM, и каким должно быть отношение значения consistent gets к общему количеству строк или к какому-нибудь другому параметру?
Ответ Тома Кайта
Очерь РЕДКО большое количество consistent gets бывает связано с тем, что таблица просматривается до (слишком большого) HWM.
В миллион раз чаще это связано со следующими причинами:
- избыточное количество индексов;
- неправильная индексация таблиц;
- плохо спроектированные модели данных, вынуждающие для получения ответа выполнять сикстиллионы операций логического ввода/вывода.
Не привязывайтесь к одной причине, не всегда проблема связана с HWM - фактически, она с этим значеним почти никогда не связана.
Постарайтесь выявить запросы, наиболее существенно загружающие систему (с помощью statspack). Сконцентрируйтесь на уменьшении количства операций логического ввода/вывода, выполняемых ими, а для этого:
- Выполняйте эти запросы реже - они что, действительно нужны? (Часто, как ни странно, ответ будет отрицательным)
- Выполняйте их более эффективно.
Еще проблемы с tkprof
Как определить, что процесс не использует обработку массивов (array processing)?
Если для запроса я получаю:
call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 0 0.00 0.00 0 0 0 0 Execute 3377 1.19 1.90 0 0 0 3377 Fetch 3377 1.82 342.39 4759 15243 0 2 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 6754 3.01 344.29 4759 15243 0 3379
используется ли в нем обработка массивов?
И еще, откуда на стадии execute берутся чтения с диска/чтения буферов?
Ответ Тома Кайта
Я сомневаюсь. Но если и использовалась, что с того? Выбрано было всего две строки.
В общем случае, поделите количество строк на количество операций выборки. Вы и получите размер массива.
В вашем случае, похоже, кто-то выполняет неэффективный поиск.
Запросы могут включать стадию execute, в зависимости от сути запроса, но вы же не представили запрос, так что, я могу только предполагать ;)
Нечасто, однако, бывает, что rows имеет ненулевое значение и на стадии execute, и на стадии fetch. Было бы интересно увидеть тестовый пример, на котором этот результат получен.
Большое количество прочитанных буферов при вставке
Хотелось бы узнать, что может привести к большому количеству buffer gets при вставке данных. Я получил следующий результат tkprof:
INSERT INTO gcprt_scon_solic_cons
(scon_num_solic, dcrp_grp_cons, dcrp_tipo_cons, scon_tipo_movi,
scon_valo_cons, scon_param_cons, scon_estado_solic,
scon_usuario, scon_timestamp)
VALUES (gcprt_scon_num_seq.NEXTVAL, :b1, :b2, :b3,
:b4, :b5, :b6,
:b7, SYSDATE)
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.02 0.02 0 0 0 0
Execute 530 11.40 69.05 7520 57698 6340 530
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 531 11.42 69.07 7520 57698 6340 530
В таблице есть всего один индекс (первичный ключ, одностолбцовый), значение current gets невелико (так что, я предполагаю, в таблице выполнено не так уж много изменений), но buffer gets составляет порядка 110 на каждое выполнение. Мне кажется, для вставки многовато. В чем может быть причина?
Ответ Тома Кайта
Ну, так покажите оператор create table и прочие детали - слишком уж много чтений с ДИСКА (физического ввода/вывода) и current mode gets для таблицы с единственным индексом.
Определение таблицы
Таблица создается так:
CREATE TABLE GCPRT_SCON_SOLIC_CONS
(
SCON_NUM_SOLIC NUMBER NOT NULL,
DCRP_GRP_CONS VARCHAR2(10) NOT NULL,
DCRP_TIPO_CONS VARCHAR2(10),
SCON_TIPO_MOVI VARCHAR2(2) NOT NULL,
SCON_VALO_CONS VARCHAR2(300) NOT NULL,
SCON_PARAM_CONS VARCHAR2(500),
SCON_ESTADO_SOLIC VARCHAR2(2) NOT NULL,
SCON_USUARIO VARCHAR2(8) NOT NULL,
SCON_TIMESTAMP DATE NOT NULL
)
TABLESPACE ETGCPRT100
PCTUSED 85
PCTFREE 10
INITRANS 1
MAXTRANS 255
STORAGE (
INITIAL 10M
NEXT 128M
MINEXTENTS 1
MAXEXTENTS 2147483645
PCTINCREASE 0
FREELISTS 1
FREELIST GROUPS 1
)
NOCACHE
NOPARALLEL;
ALTER TABLE GCPRT_SCON_SOLIC_CONS ADD (
CONSTRAINT PK_GCPRT_SCON_SOLIC_CONS PRIMARY KEY (SCON_NUM_SOLIC)
USING INDEX
TABLESPACE EIGCPRT100
PCTFREE 10
INITRANS 2
MAXTRANS 255
STORAGE (
INITIAL 10M
NEXT 10M
MINEXTENTS 1
MAXEXTENTS 2147483645
PCTINCREASE 0
FREELISTS 1
FREELIST GROUPS 1
));
Еще у нее есть триггер по столбцу SCON_ESTADO_SOLIC, - он не может быть причиной? (Является ли значение buffer gets, выдаваемое tkprof, суммарным для оператора insert и триггера?)
Ответ Тома Кайта
Да, триггер и является причиной. Рассмотрим пример:
ops$tkyte@ORA817DEV> create table t ( x int primary key, y char(80) ); Table created. ops$tkyte@ORA817DEV> @trace ops$tkyte@ORA817DEV> alter session set events '10046 trace name context forever, level 12'; Session altered. ops$tkyte@ORA817DEV> insert into t /* test1 */ (x,y) values ( -1, 'x' ); 1 row created. ops$tkyte@ORA817DEV> create or replace trigger t_trigger 2 before insert on t 3 declare 4 l_cnt number; 5 begin 6 select count(*) into l_cnt from all_objects; 7 end; 8 / Trigger created. ops$tkyte@ORA817DEV> insert into t /* test2 */ (x,y) values ( 1, 'x' ); 1 row created. insert into t /* test1 */ (x,y) values ( -1, 'x' ) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 0.00 0.00 0 1 10 1 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 0.00 0.00 0 1 10 1 insert into t /* test2 */ (x,y) values ( 1, 'x' ) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.01 0.01 0 0 0 0 Execute 1 2.76 6.16 370 64886 9 1 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 2.77 6.17 370 64886 9 1
Результат tkprof в примере на стр. 561 - "Oracle для профессионалов"
Речь идет о стр. 464 оригинала или о стр. 561 первого тома моего перевода. - Прим. В.К.
Привет, Том!
Когда я попытался выполнить указанный пример из книги (на самом деле, весь PL/SQL-блок после выполнения команды ALTER SESSION SET EVENTS), то получил следующий результат:
UPDATE emp set ename = lower(ename)
where
empno = :b1
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.07 0.06 0 0 0 0
Execute 1 0.00 100.18 0 1 2 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.07 100.25 0 1 2 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 88 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 UPDATE (cr=1 r=0 w=0 time=49141 us)
1 INDEX UNIQUE SCAN PK_EMP (cr=1 r=0 w=0 time=27 us)(object id 37436)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enqueue 33 3.12 100.13
Выдана также информация об ожиданиях (wait events). Я думаю, что это новое свойство утилиты TKPROF в Oracle9i (9.2.0.3). Значит ли это, что изучать исходные трассировочные файлы более не придется?
В представленных результатах выдано ожидание события "enqueue" и общее время этого ожидания. Меня интересует столбец "Times Waited". Почему в этом столбце указано, что ждать пришлось 33 раза? Откуда взялось это число?
Ответ Тома Кайта
Да, это новая замечательная возможность tkprof в Oracle9i's (начиная с версии 9.0).
Изучать трассировочный файл придется, чтобы выяснить, какое зачение имела переменная :B1, а вот ожидания там, действительно, можно уже и не искать...
Мы проверяем состояние ожидания enqueue wait каждые три секунды, проверяя, "и что же происходит", а затем снова засыпая в ожидании того, что блокирующий сеанс зафиксирует или откатит транзакцию.
А нельзя ли изменить этот интервал в 3 секунды?
Совсем забыл про значения связываемых переменных в исходном файле трассировки. Спасибо, что напомнил. Но, в принципе, утилита tkprof свободно могла бы выдавать и эти значения тоже (они же есть в исходном файле трассировки). Мне интересно, почему она их не выбирает?
В своем ответе ты написал:
Мы проверяем состояние ожидания enqueue wait каждые три секунды, проверяя, "и что же происходит"...
Являются ли эти 3 секунды стандартным таймаутом для ожидания в ? Почему именно 3 секунды? Я предполагаю, что меньше было бы слишком мало, а больше - слишком долго для ждущего сеанса. Правильно?
1). Является ли этот таймаут 3 секунды стандартным для всех версий Oracle или он различен для разных версий Oracle (или может измениться в будущем)?
2). Зависит ли хоть как-то это значение от конфигурации сервера?
3). Оно где-то описано в документации или мы просто "его знаем"?
Ответ Тома Кайта
Утилита tkprof значения связываемых переменных пока не выдает.
3 секунды выбрали разработчики, - именно поэтому, например, приходится ждать до 3 секунд при выявлении взаимной блокировки.
1) Это значение, как все вообще, "может измениться".
2) Нет
3) Мы просто "его знаем". Точнее, это значение можно определить по таким результатам, как представленные выше.
Рекурсивный SQL в tkprof
Том!
Не мог бы ты прояснить, включает ли значение buffer gets, выдаваемое утилитой tkprof, рекурсивный sql или нет. В главе 10 руководства Oracle 9i Performance Tuning Guide сказано:
"Ресурсы, выдаваемые для оператора, включают весь SQL, выполненный по ходу обработки оператора. Поэтому включаются все ресурсы, использованные в триггере, а также ресурсы, используемые любыми рекурсивными SQL-операторами (например, используемыми при выделении пространства). Если включена трассировка SQL Trace, TKPROF учитывает эти ресурсы дважды. Не пытайтесь настраивать производительность оператора DML, если фактически ресурс использован на нижнем уровне рекурсии."
Однако я выполнил простой тест:
select * from sto_tab where id = sto_select.get_id(id) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.01 0.00 0 0 0 0 Execute 1 0.00 0.00 0 0 0 0 Fetch 2 0.02 0.01 0 32 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.03 0.02 0 32 0 1 Misses in library cache during parse: 1
В функции sto_select.get_id я выполняю запрос:
function get_id(x in number) return number is xx number; begin select count(*) into xx from all_objects where rownum <= 100000; return 1; end;
Этот sql-оператор я вижу в трассировочном файле:
SELECT count(*) from all_objects where rownum <= 100000 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.02 0.01 0 0 0 0 Execute 2 0.00 0.00 0 0 0 0 Fetch 2 8.34 8.49 556 579806 0 2 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 5 8.36 8.50 556 579806 0 2
Итак, значение buffer gets явно не было включено в исходный запрос. Что, в руководстве Performance Tuning Guide ошибка? А как насчет операторов DML? (Я выполнял тест на сервере версии 9.2.0.3.)
Ответ Тома Кайта
Это было правильно. Рассмотрим пример:
Connected to: Oracle8i Enterprise Edition Release 8.1.7.4.0 - Production With the Partitioning option JServer Release 8.1.7.4.0 - Production ops$tkyte@ORA817DEV> set echo on ops$tkyte@ORA817DEV> @test ops$tkyte@ORA817DEV> drop table t; Table dropped. ops$tkyte@ORA817DEV> create table t ( x int ); Table created. ops$tkyte@ORA817DEV> create or replace trigger t_trigger 2 before insert on t 3 begin 4 for x in ( select count(*) from all_objects ) 5 loop 6 null; 7 end loop; 8 end; 9 / Trigger created. ops$tkyte@ORA817DEV> @trace ops$tkyte@ORA817DEV> alter session set events '10046 trace name context forever, level 12'; Session altered. ops$tkyte@ORA817DEV> insert into t values ( 1 ); 1 row created.
tkprof выдает:
insert into t
values
( 1 )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 2.54 5.83 359 64968 12 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 2.54 5.83 359 64968 12 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 742
********************************************************************************
SELECT COUNT(*)
FROM
ALL_OBJECTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 2.54 5.79 358 64967 4 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 2.54 5.79 358 64967 4 1
Так что значение consistent gets ранее агрегировалось. Но по тем же данным в 9ir2 получаем:
insert into t
values
( 1 )
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 1 20 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 1 20 1
Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 89
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
select count(*)
from
all_objects
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 3.52 3.43 0 75729 0 1
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 3.52 3.43 0 75729 0 1
так что он больше не учитывает это дважды.
Я выставлю ошибку в документации.
Количество строк, обработанных при выполнении insert
Привет, Том!
Утилита TKPROF выдает:
INSERT INTO CDRCS_EO (col1, col2, col3, col4, col5) VALUES (:v1, :v2, :v3, :v4, :v5) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 291 1.25 14.77 0 0 0 0 Execute 291 15.40 1317.90 10011 1047 317037 105147 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 582 16.65 1332.67 10011 1047 317037 105147 Misses in library cache during parse: 0 Optimizer goal: RULE
Вопрос: оператор был выполнен 291 раз. Это означает, что обработана (вставлена) может быть максимум 291 строка. Почему обработано больше строк, чем количество выполнений оператора?
И еще, что этот оператор (insert) делает на диске?
Объясни, пожалуйста.
Ответ Тома Кайта
Разработчик выполнил замечательную вставку массивом. Около 370 строк всатвляется при каждой вставке (жаль только, что курсор не оставили открытым! В идеале должен быть 1 анализ, 291 выполнение.)
Что касается того, "что этот оператор (insert) делает на диске" - данные надо вставить "куда-то". При вставке сервер идет в список свободных мест; там сказано, что "в блоке 20 файла 5 есть место". Если блока 20 нет в буферном кэше, придется его прочитать с диска. Кроме того, при вставке строки в таблицу, по которой есть индексы, данные должны попасть во вполне конкретные блоки. "name=frank" - идет в блок 200 файла 20 (это выясняется после прочтения корневого и промежуточных блоков индекса). Если блок 200 файла 20 находится на диске, его придется прочитать, чтобы изменить.
Пакетное задание: elapsed time. Комментарий читателя от 19 декабря 2003
У нас есть пакетное задание, которое выполняется около 5 часов, но, протрассировав задание, мы обработали файл трассировки с помощью tkprof и получили следующее:
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 595504 65.83 81.66 0 531 0 0 Execute 595508 346.99 452.31 5 25 21 8 Fetch 891520 1379.24 11759.50 1069624 6984725 3 605893 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2082532 1792.06 12293.48 1069629 6985281 24 605901 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 525 0.10 0.13 0 0 0 0 Execute 947 0.36 0.41 0 0 0 1 Fetch 1819 0.16 1.37 123 3457 0 1345 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3291 0.62 1.91 123 3457 0 1346
По мнению TKPROF, процесс выполнялся около 3,9 часа... Это что, общее время выполнения на сервере? Или это вообще не имеет отношения к времени выполнения пакетного задания сервером?
На что уходит 1,1 часа?
Ответ Тома Кайта
Эти 1,1 часа уходят на передачу данных по сети + время обработки на клиенте. Вероятно, в основном на обработку на клиенте, с учетом среднего количества возвращаемых строк (если только у вас не слишком медленная сеть)
Ваш пакетный процесс должен анализировать операторы один раз, а выполнять многократно. То, что parse почти совпадает с execute - плохо (разработчикам надо это исправить).
Возможно, SOFT parse...
Ваш пакетный процесс должен анализировать операторы один раз, а выполнять многократно. То, что parse почти совпадает с execute - плохо (разработчикам надо это исправить).
В представленном отчете TKPROF большинство выполненных анализов могли быть типа SOFT PARSE. Правильно? И как разработчики могут это исправить?
Ответ Тома Кайта
Разработчики должны писать так:
подпрограмма X
static variable ОПЕРАТОР
if (оператор еще не был проанализирован в этой подпрограмме)
then
проанализировать оператор
end if;
bind оператор
execute оператор
/* никогда не закрывать его, оставить открытым */
end подпрограмма
Анализ есть анализ. Быстрее всего он будет выполняться, если ВООБЩЕ НЕ АНАЛИЗИРОВАТЬ.
Спросите разработчиков: "Стали бы вы КОМПИЛИРОВАТЬ подпрограмму перед каждым выполнением - выполнять код и тут же выбрасывать". Конечно, не стали бы. Так почему они так поступают с SQL-операторами?
Но это же web-приложение
/* никогда не закрывать его, оставить открытым */
Но в web-приложении очень поасно НЕ ЗАКРЫВАТь оператор. Состояние не сохраняется, и транзакции - максимально короткие. Мы не знаеми, каким будет следующий запрос.
Ответ Тома Кайта
Можено держать курсоры открытыми как можно дольше.
Если поступать иначе, вы резко снизите производительность.
Не вижу причин, почему, если вы анализируете и выполняете оператор 500 раз на одной web-странице, НЕЛЬЗЯ проанализировать его один раз и выполнить 500 раз.
Нет причин (кроме "мне лень").
Один из вариантов - построить хэш-таблицу для подключения - каждый проанализированный/выполняемый оператор, который вы открываете, попадает в эту хэш-таблицу. Прежде чем анализировать любой оператор поищите для него дескриптор в хэш-таблице. Если вы его получите, используйте повторно. Если нет - проанализируйте (prepare) оператор и добавьте его в таблицу. Затем, прежде чем возвращать подключение ОБРАТНО в пул (я предполагаю, что вы используете пул подключений, что не гарантировано на 100%, но скорее всего, судя по вопросу), надо пройти по записям хэш-таблицы и закрыть все операторы.
Знаете, я использую модуль mod_plsql, который прекрасно "сбрасывает состояние сеанса" после каждого вызова. Никаких утечек курсоров при переходе со страницы на страницу. Если использовать более сложный язык, типа Java, придется заниматься этим самостоятельно, но если НЕ заниматься вовсе, вы получите низкую производительность и ограниченную масштабируемость. Так что, в конечном счете, решать вам.