(495) 925-0049, ITShop интернет-магазин 229-0436, Учебный Центр 925-0049
  Главная страница Карта сайта Контакты
Поиск
Вход
Регистрация
Рассылки сайта
 
 
 
 
 

Анализ результатов tkprof

Источник: ln

Эта статья посвящена анализу результатов работы утилиты 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, придется заниматься этим самостоятельно, но если НЕ заниматься вовсе, вы получите низкую производительность и ограниченную масштабируемость. Так что, в конечном счете, решать вам.

Ссылки по теме


 Распечатать »
 Правила публикации »
  Обсудить материал в конференции Oracle »
Написать редактору 
 Рекомендовать » Дата публикации: 25.02.2010 
 

Магазин программного обеспечения   WWW.ITSHOP.RU
Oracle Database Personal Edition Named User Plus Software Update License & Support
Oracle Database Standard Edition 2 Processor License
Oracle Database Personal Edition Named User Plus License
Oracle Database Standard Edition 2 Named User Plus License
TeeGrid VCL/FMX Source Code single license
 
Другие предложения...
 
Курсы обучения   WWW.ITSHOP.RU
 
Другие предложения...
 
Магазин сертификационных экзаменов   WWW.ITSHOP.RU
 
Другие предложения...
 
3D Принтеры | 3D Печать   WWW.ITSHOP.RU
 
Другие предложения...
 
Новости по теме
 
Рассылки Subscribe.ru
Информационные технологии: CASE, RAD, ERP, OLAP
Новости ITShop.ru - ПО, книги, документация, курсы обучения
Программирование на Microsoft Access
CASE-технологии
СУБД Oracle "с нуля"
Новые материалы
Компьютерные книги. Рецензии и отзывы
 
Статьи по теме
 
Новинки каталога Download
 
Исходники
 
Документация
 
Обсуждения в форумах
Сайт инструмент (1)
Я бывший программист пользовался 1 сайтом проверенным он мне действительно помог я блогодоря...
 
Где взять лицензионный ключ для AllFusion Process Modeler (BPwin) 7? (5)
Выручайте!!! где найти ключ, ужасно срочно нужна программа. заранее спасибо!
 
работа на дому! (5)
Доброго времени суток дорогие друзья. Многоуровневый маркетинг окончательно признан...
 
Регистрация на Oracle.com (4)
Сразу прошу прощения за тупой вопрос, но вчера зарегался на oracle.com (чтоб 9i слить себе...
 
Ищу кодера (2)
Добрый день! Ищу кодера который сможет сделать копии сайтов. Сколько будет стоить скопировать...
 
 
 



    
rambler's top100 Rambler's Top100