Oracle mechanics

21.05.2014

Ожидание utl_file I/O

Filed under: AWR,Oracle,wait events — Игорь Усольцев @ 21:51
Tags: , ,

При анализе проблем длительного выполнения concurrent request в системе OEBS, зная CLIENT_ID/SID-ы медленно выполнявшихся дочерних процессов и номера начального/конечного снапшотов интересующего периода, достаточно просто выделить «проблемный» запрос из истории ASH:

11.2.0.4@ SQL> @ash_sql_wait_tree_hist "client_id = 'USER007' and (instance_number, session_id, session_serial#) in ((1,2251,19231),(1,1707,26715))" 67983 67991
 
LVL INST_ID BLOCKING_TREE  CLIENT_ID   EVENT                          WAITS_COUNT EXECS_COUNT SESS_COUNT AVG_WA SQL_ID        TOP_LEVEL_SQL_ID SQL_TEXT
--- ------- -------------- ----------- ------------------------------ ----------- ----------- ---------- ------ ------------- ---------------- ------------------------------------------------
  1       1 FOREGROUND     USER007     On CPU / runqueue                      940        1064          2      0 c4wtbv2xcmq78 c4wtbv2xcmq78    begin fnd_file_private.logfile_get(:s, :b); end;
  1       1 FOREGROUND     USER007     On CPU / runqueue                      285           1          2      0                                
  1       1 FOREGROUND     USER007     library cache: mutex X                  30          30          2     10 c4wtbv2xcmq78 c4wtbv2xcmq78    begin fnd_file_private.logfile_get(:s, :b); end;
  1       1 FOREGROUND     USER007     library cache: mutex X                  14           0          2     11                                
...

и убедившись, что запрос c4wtbv2xcmq78 выполнялся в это время только сессиями интересующего нас клиента:

SQL> @ash_sql_wait_tree_hist "sql_id = 'c4wtbv2xcmq78'" 67983 67991
 
LVL INST_ID BLOCKING_TREE  CLIENT_ID   EVENT                          WAITS_COUNT EXECS_COUNT SESS_COUNT AVG_WA SQL_ID        TOP_LEVEL_SQL_ID SQL_TEXT
--- ------- -------------- ----------- ------------------------------ ----------- ----------- ---------- ------ ------------- ---------------- ------------------------------------------------
  1       1 FOREGROUND     USER007     On CPU / runqueue                      940        1064          2      0 c4wtbv2xcmq78 c4wtbv2xcmq78    begin fnd_file_private.logfile_get(:s, :b); end;
  1       1 FOREGROUND     USER007     library cache: mutex X                  30          30          2     10 c4wtbv2xcmq78 c4wtbv2xcmq78    begin fnd_file_private.logfile_get(:s, :b); end;
  1       1 FOREGROUND     USER007     latch: ges resource hash list            1           1          1      0 c4wtbv2xcmq78 c4wtbv2xcmq78    begin fnd_file_private.logfile_get(:s, :b); end;
  1       1 FOREGROUND     USER007     cursor: pin S                            1           0          1     11 c4wtbv2xcmq78 c4wtbv2xcmq78    begin fnd_file_private.logfile_get(:s, :b); end;
  2       1   FOREGROUND   USER007     On CPU / runqueue                        1           1          1      0 c4wtbv2xcmq78 c4wtbv2xcmq78    begin fnd_file_private.logfile_get(:s, :b); end;

, посмотреть общесистемную статистику выполнения запроса SQL_ID c4wtbv2xcmq78 за тот же период:

SQL> @dba_hist_sqlstat "sql_id = 'c4wtbv2xcmq78' and snap_id between 67983 and 67991 and executions_delta > 0"
 
INST BEGIN_SNAP_ID BEGIN_SNAP_TIME      EXECS SQL_ID        ELA_PER_EXEC CPU_PER_EXEC CCWAITS_PER_EXEC PLSQL_PER_EXEC
---- ------------- --------------- ---------- ------------- ------------ ------------ ---------------- --------------
   1         67990 16.05 18:00       14623014 c4wtbv2xcmq78           74           17                2             59
   1         67989 16.05 17:30       17312389 c4wtbv2xcmq78           75           17                2             60
   1         67988 16.05 17:00       17168676 c4wtbv2xcmq78           74           17                2             59
   1         67987 16.05 16:30       16837013 c4wtbv2xcmq78           78           18                3             62
   1         67986 16.05 16:00       16699501 c4wtbv2xcmq78           76           18                3             61
   1         67985 16.05 15:30       17191658 c4wtbv2xcmq78           76           17                2             60
   1         67984 16.05 15:00       17215858 c4wtbv2xcmq78           75           17                2             59
   1         67983 16.05 14:30       17099998 c4wtbv2xcmq78           77           17                4             62
   1         67982 16.05 14:00       12074289 c4wtbv2xcmq78           74           16                2             59

— из которой следует, что запрос выполнялся быстро, но часто — до 10,000 раз в секунду! — из чего понятно проявление конкуренции за объекты Shared Pool (library cache: mutex X и cursor: pin S)

Учитывая, что OEBS-процедура FND_FILE_PRIVATE.LOGFILE_GET выполняет фактически лишь вызов стандартной UTL_FILE.GET_LINE, было бы логично наблюдать ожидания utl_file I/O при её выполнении:

SQL> select session_state, event, count(*)
  2    from dba_hist_active_sess_history
  3   where snap_id between 67983 and 67991
  4     and client_id = 'USER007'
  5     and (instance_number, session_id, session_serial#) in
  6         ((1, 2251, 19231), (1, 1707, 26715))
  7     and sql_id = 'c4wtbv2xcmq78'
  8   group by session_state, event
  9   order by count(*) desc
 10  /
 
SESSION_STATE EVENT                             COUNT(*)
------------- ------------------------------- ----------
ON CPU                                              1154
WAITING       library cache: mutex X                  30
WAITING       cursor: pin S                            1
WAITING       latch: ges resource hash list            1

— увы, и в AWR истории ожиданий заметного всплеска utl_file I/O с 14:00 до 18:30 также не заметно:

SQL> @awr_event_hist "utl_file I/O" 67979 67995 1
 
INST_ID SNAP_ID BEGIN_INTERVAL_TIME EVENT                          WAITS AVG_WAIT
------- ------- ------------------- --------------------------- -------- --------
      1   67994 16.05.2014 20:00    utl_file I/O                    4362     2302
      1   67993 16.05.2014 19:30    utl_file I/O                   25865      553
      1   67992 16.05.2014 19:00    utl_file I/O                  113698      278
      1   67991 16.05.2014 18:30    utl_file I/O                  564149       48
      1   67990 16.05.2014 18:00    utl_file I/O                  277581      775 -- окончание периода
      1   67989 16.05.2014 17:30    utl_file I/O                   81263     1007
      1   67988 16.05.2014 17:00    utl_file I/O                  105860      260
      1   67987 16.05.2014 16:30    utl_file I/O                   27988     1003
      1   67986 16.05.2014 16:00    utl_file I/O                   42047     1439
      1   67985 16.05.2014 15:30    utl_file I/O                  102853      314
      1   67984 16.05.2014 15:00    utl_file I/O                   61514      449
      1   67983 16.05.2014 14:30    utl_file I/O                  187713      204
      1   67982 16.05.2014 14:00    utl_file I/O                   82579      775 -- начало периода
      1   67981 16.05.2014 13:30    utl_file I/O                  170707      394
      1   67980 16.05.2014 13:00    utl_file I/O                  249921      687
      1   67979 16.05.2014 12:30    utl_file I/O                   88952     1301

Причиной судя по всему является как бы исправленный Bug 17567903 : UTL_FILE I/O WAIT IS NOT BEING REPORTED CORRECTLY IN AWR REPORTS, согласно которому в версии 11.2.0.3 вместо ожидания utl_file I/O по-прежнему неожиданно фиксируется/отображается SQL*Net message to client

Проверим на 11.2.0.4:

SQL> @awr_event_hist "SQL*Net message to client" 67979 67995 1
 
INST_ID SNAP_ID BEGIN_INTERVAL_TIME EVENT                          WAITS AVG_WAIT
------- ------- ------------------- --------------------------- -------- --------
      1   67994 16.05.2014 20:00    SQL*Net message to client     437027        1
      1   67993 16.05.2014 19:30    SQL*Net message to client     313599        1
      1   67992 16.05.2014 19:00    SQL*Net message to client     356946        1
      1   67991 16.05.2014 18:30    SQL*Net message to client     345808        1
      1   67990 16.05.2014 18:00    SQL*Net message to client   15271713        1 -- окончание периода
      1   67989 16.05.2014 17:30    SQL*Net message to client   17947950        1
      1   67988 16.05.2014 17:00    SQL*Net message to client   17750132        1
      1   67987 16.05.2014 16:30    SQL*Net message to client   17274516        1
      1   67986 16.05.2014 16:00    SQL*Net message to client   17299325        1
      1   67985 16.05.2014 15:30    SQL*Net message to client   17763557        1
      1   67984 16.05.2014 15:00    SQL*Net message to client   17999166        1
      1   67983 16.05.2014 14:30    SQL*Net message to client   17798659        1
      1   67982 16.05.2014 14:00    SQL*Net message to client   13457589        1 -- начало периода
      1   67981 16.05.2014 13:30    SQL*Net message to client    1209150        1
      1   67980 16.05.2014 13:00    SQL*Net message to client     695050        1
      1   67979 16.05.2014 12:30    SQL*Net message to client     985391        1

— действительно, очень-очень похоже, + кол-во ожиданий (WAITS) вполне соответствует кол-ву выполнений FND_FILE_PRIVATE.LOGFILE_GET / UTL_FILE.GET_LINE — до 10,000 prs, т.е. указанный баг всё ещё имеет место быть (

С другой стороны, 10,000 prs — совсем неплохой результат для используемой Oracle ACFS / iSCSI / SATA конфигурации )

P.S. Простой тест показывает, что для успешного выполнения одного вызова UTL_FILE.GET_LINE Oracle на Windows, например, фиксирует ровно одно ожидание utl_file I/O, как и должно:

11.2.0.3.ORCL1123@SCOTT SQL> CREATE DIRECTORY log_dir AS 'C:\TEMP';

Directory created.

SQL> DECLARE
  2    V1 VARCHAR2(32767);
  3    F1 UTL_FILE.FILE_TYPE;
  4  BEGIN
  5    F1 := UTL_FILE.FOPEN('LOG_DIR', '11', 'R', 256);
  6    for i in 1 .. 10 loop
  7      UTL_FILE.GET_LINE(F1, V1, 32767);
  8    end loop;
  9    UTL_FILE.FCLOSE(F1);
 10  end;
 11  /

PL/SQL procedure successfully completed.

PARSE #321534632:c=0,e=255,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=711903578953
WAIT #321534632: nam='utl_file I/O' ela= 24  p1=0 p2=0 p3=0 obj#=-1 tim=711903579427  -- UTL_FILE.FOPEN,    p1=0
WAIT #321534632: nam='utl_file I/O' ela= 84  p1=0 p2=0 p3=0 obj#=-1 tim=711903579548  -- 4 ожидания на одну операцию UTL_FILE.FOPEN
WAIT #321534632: nam='utl_file I/O' ela= 2   p1=0 p2=0 p3=0 obj#=-1 tim=711903579564
WAIT #321534632: nam='utl_file I/O' ela= 181 p1=0 p2=0 p3=0 obj#=-1 tim=711903579753
WAIT #321534632: nam='utl_file I/O' ela= 46  p1=2 p2=0 p3=0 obj#=-1 tim=711903579940  -- UTL_FILE.GET_LINE, p1=2
WAIT #321534632: nam='utl_file I/O' ela= 6   p1=2 p2=0 p3=0 obj#=-1 tim=711903579984  -- по одному ожиданию на каждый вызов UTL_FILE.GET_LINE
WAIT #321534632: nam='utl_file I/O' ela= 5   p1=2 p2=0 p3=0 obj#=-1 tim=711903580006
WAIT #321534632: nam='utl_file I/O' ela= 4   p1=2 p2=0 p3=0 obj#=-1 tim=711903580025
WAIT #321534632: nam='utl_file I/O' ela= 5   p1=2 p2=0 p3=0 obj#=-1 tim=711903580045
WAIT #321534632: nam='utl_file I/O' ela= 4   p1=2 p2=0 p3=0 obj#=-1 tim=711903580064
WAIT #321534632: nam='utl_file I/O' ela= 5   p1=2 p2=0 p3=0 obj#=-1 tim=711903580084
WAIT #321534632: nam='utl_file I/O' ela= 4   p1=2 p2=0 p3=0 obj#=-1 tim=711903580103
WAIT #321534632: nam='utl_file I/O' ela= 7   p1=2 p2=0 p3=0 obj#=-1 tim=711903580130
WAIT #321534632: nam='utl_file I/O' ela= 5   p1=2 p2=0 p3=0 obj#=-1 tim=711903580159
WAIT #321534632: nam='utl_file I/O' ela= 16  p1=3 p2=0 p3=0 obj#=-1 tim=711903580199  -- UTL_FILE.FCLOSE,   p1=3, одно ожидание
EXEC #321534632:c=0,e=1147,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=0,tim=711903580270

Приведённый трейс хорошо дополняет отсутствие описания PARAMETER1 для ожидания:

SQL> select * from v$event_name where name = 'utl_file I/O';
 
NAME          PARAMETER1 PARAMETER2 PARAMETER3 WAIT_CLASS
------------- ---------- ---------- ---------- ----------
utl_file I/O                                   User I/O

Добавить комментарий »

Комментариев нет.

RSS feed for comments on this post. TrackBack URI

Добавить комментарий

Заполните поля или щелкните по значку, чтобы оставить свой комментарий:

Логотип WordPress.com

Для комментария используется ваша учётная запись WordPress.com. Выход / Изменить )

Фотография Twitter

Для комментария используется ваша учётная запись Twitter. Выход / Изменить )

Фотография Facebook

Для комментария используется ваша учётная запись Facebook. Выход / Изменить )

Google+ photo

Для комментария используется ваша учётная запись Google+. Выход / Изменить )

Connecting to %s

Создайте бесплатный сайт или блог на WordPress.com.

%d такие блоггеры, как: