Oracle mechanics

13.03.2014

Диагностика проблем сетевых соединений с использованием Oracle wait event интерфейса

Filed under: Active Session History,Диагностика системы (instance),Oracle — Игорь Усольцев @ 00:06
Tags: ,

Беда пришла, как обычно, откуда не ждали — т.е. неизвестно откуда:

sqlnet_bad

— ось ординат на графике мониторинга отражает резко увеличившееся время выполнения некоего набора критически важных запросов и процедур

Ну и поскольку кроме графика из логов приложения получить никакой дополнительной информации не было решительно никакой возможности — пришлось нам с Дмитрием Якубеней искать причины возникновения проблем средствами Oracle

При рассмотрении AWR на втором месте в топе было замечено нехарактерное для системы ожидание SQL*Net more data from client:

Top 5 Timed Foreground Events
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
                                                           Avg
                                                          wait   % DB
Event                                 Waits     Time(s)   (ms)   time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
DB CPU                                            2,486          57.3
SQL*Net more data from client        83,952       1,287     15   29.7 Network
...

История ожидания (в части ср.продолжительности) отчётливо коррелировала с историей возникновения проблем:

SQL> @dba_hist_system_event "event_name = 'SQL*Net more data from client' and snap_id between 288370 and 288386"

INST_ID SNAP_ID BEGIN_INTERVAL_TIME EVENT_NAME                      WAIT_COUNT AVG_WAIT_TIME_NS
------- ------- ------------------- ------------------------------- ---------- ----------------
      1  288370 27.02.2014 17:30    SQL*Net more data from client       145653              474 -- здесь было очень хорошо,
      2  288370 27.02.2014 17:30    SQL*Net more data from client       145717              193
      1  288371 27.02.2014 18:00    SQL*Net more data from client       136143              290
      2  288371 27.02.2014 18:00    SQL*Net more data from client       200342              161
      1  288372 27.02.2014 18:30    SQL*Net more data from client       184590              199
      2  288372 27.02.2014 18:30    SQL*Net more data from client       117560              137
      1  288373 27.02.2014 19:00    SQL*Net more data from client       108733              308
      2  288373 27.02.2014 19:00    SQL*Net more data from client       172209              123
      1  288374 27.02.2014 19:30    SQL*Net more data from client       111704              553
      2  288374 27.02.2014 19:30    SQL*Net more data from client       112484              317
...
      2  288383 28.02.2014 00:00    SQL*Net more data from client       109507            10330 -- а тут уже не очень
      1  288384 28.02.2014 00:30    SQL*Net more data from client        76504            21222
      2  288384 28.02.2014 00:30    SQL*Net more data from client       182375            10474
      1  288385 28.02.2014 01:00    SQL*Net more data from client       109505            16642
      2  288385 28.02.2014 01:00    SQL*Net more data from client       120262            18268
...

Для подавляющей части этих ожиданий в ASH не отражались не только SQL_ID, но и состояние/этап выполнения:

SQL> select in_connection_mgmt,
  2         in_parse,
  3         in_hard_parse,
  4         in_sql_execution,
  5         in_plsql_execution,
  6         in_plsql_rpc,
  7         in_bind,
  8         in_cursor_close,
  9         top_level_call_name,
 10         time_model,
 11         nvl2(sql_id, sql_id, top_level_sql_id) as sql_id,
 12         count(*)
 13    from gv$active_session_history
 14   where event = 'SQL*Net more data from client'
 15   group by in_connection_mgmt,
 16            in_parse,
 17            in_hard_parse,
 18            in_sql_execution,
 19            in_plsql_execution,
 20            in_plsql_rpc,
 21            in_bind,
 22            in_cursor_close,
 23            top_level_call_name,
 24            time_model,
 25            nvl2(sql_id, sql_id, top_level_sql_id)
 26  having count(*) > 200
 27   order by count(*) desc
 28  /

IN_CONNECTION_MGMT IN_PARSE IN_HARD_PARSE IN_SQL_EXECUTION IN_PLSQL_EXECUTION IN_PLSQL_RPC IN_BIND IN_CURSOR_CLOSE TOP_LEVEL_CALL_NAME TIME_MODEL SQL_ID          COUNT(*)
------------------ -------- ------------- ---------------- ------------------ ------------ ------- --------------- ------------------- ---------- ------------- ----------
N                  N        N             N                N                  N            N       N               V8 Bundled Exec              0                    36082
N                  N        N             N                N                  N            N       N               LOB/FILE operations          0 aj86056xjbbg4       2413
N                  N        N             N                N                  N            N       N               LOB/FILE operations          0 0j0vyhq5924pw       2247
N                  N        N             N                N                  N            N       N               V8 Bundled Exec              0 aacbmsphch1t0        843
N                  N        N             N                N                  N            N       N               LOB/FILE operations          0 9jxtg63xxrj25        284
N                  N        N             N                N                  N            N       N               LOB/FILE operations          0                      234

— при V$ACTIVE_SESSION_HISTORY.TIME_MODEL = 0 из чего при желании также можно извлечь полезную информацию*

В топе наблюдаемых запросов в проблемный период был замечен служебный top_level_sql_id 5ur69atw3vfhj, очевидно характерный для фазы установки SQL*Net соединения:

SQL> select top_level_sql_id, count(*)
  2    from gv$active_session_history
  3   where event = 'SQL*Net more data from client'
  4     and sql_id is null
  5   group by top_level_sql_id
  6   order by count(*) desc
  7  /

TOP_LEVEL_SQL_ID   COUNT(*)
---------------- ----------
                      34440
aacbmsphch1t0           758
5ur69atw3vfhj           131 -- select decode(failover_method, NULL, 0 , 'BASIC', 1, 'PRECONNECT', 2 , 'PREPARSE', 4 , 0), decode(failover_type, NULL, 1 , 'NONE', 1 , 'SESSION', 2, 'SELECT',  4, 1), failover_retries, failover_delay, flags from service$ where name = :1
8b8dza48t7w9v            15
...

Ещё более интересным оказался экспресс-анализ географического происхождения ожиданий:

SQL> select program, count(*), round(avg(time_waited)) as avg_time_waited_ns
  2  from gv$active_session_history where event = 'SQL*Net more data from client'
  3  group by program
  4  order by count(*) desc
  5  /

PROGRAM                                        COUNT(*) AVG_TIME_WAITED_NS
-------------------------------------------- ---------- ------------------
python2.7@apps1f.000.ru (TNS V1-V3)               20280             112640
python2.7@apps1g.000.ru (TNS V1-V3)               11354             114556
python2.7@apps2g.000.ru (TNS V1-V3)               10366             115874
python2.7@apps2f.000.ru (TNS V1-V3)                1844             122125
python2.7@apps1e.000.ru (TNS V1-V3)                  20               7308
python2.7@apps2e.000.ru (TNS V1-V3)                  16                380

— хорошо заметное отличие кол-ва и грубой оценки ср.продолжительности сетевых ожиданий точно указало на (впоследствие подтверждёные) проблемы связи с дц F и G, в то время как сетевых проблем с дц E не было

Тот же график после диагностики/исправления сетевых проблем подтвердил правильность предположений:)

sqlnet_good_full

*) уже после разрешения проблем посмотрел что можно «получить» из значения V$ACTIVE_SESSION_HISTORY.TIME_MODEL = 0

Например, из запроса всего текущего ASH можно заключить что time_model = 0 характерно для:

SQL> select session_type,
  2         decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue') as EVENT,
  3         case when in_connection_mgmt = 'N'
  4               and in_parse = 'N'
  5               and in_hard_parse = 'N'
  6               and in_sql_execution = 'N'
  7               and in_plsql_execution = 'N'
  8               and in_plsql_rpc = 'N'
  9               and in_bind = 'N'
 10               and in_cursor_close = 'N'
 11         then 'Unknown state' else 'Known state' end as EXEC_STATE,
 12         top_level_call_name,
 13         count(*)
 14    from gv$active_session_history
 15     where time_model = 0
 16   group by session_type,
 17            decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue'),
 18            case when in_connection_mgmt = 'N'
 19                 and in_parse = 'N'
 20                 and in_hard_parse = 'N'
 21                 and in_sql_execution = 'N'
 22                 and in_plsql_execution = 'N'
 23                 and in_plsql_rpc = 'N'
 24                 and in_bind = 'N'
 25                 and in_cursor_close = 'N'
 26            then 'Unknown state' else 'Known state' end,
 27            top_level_call_name
 28  having count(*) > 1000
 29   order by count(*) desc
 30  /

SESSION_TYPE EVENT                          EXEC_STATE    TOP_LEVEL_CALL_NAME    COUNT(*)
------------ ------------------------------ ------------- -------------------- ----------
BACKGROUND   log file parallel write        Unknown state                            7660 -- служебных/системных процессов во время выполнения служебных действий
BACKGROUND   On CPU / runqueue              Unknown state                            7621
BACKGROUND   control file sequential read   Unknown state LOGOFF                     7305
BACKGROUND   ARCH wait on SENDREQ           Unknown state LOGOFF                     3941
BACKGROUND   control file sequential read   Unknown state ROLLBACK                   3768
BACKGROUND   db file parallel write         Unknown state                            3577
BACKGROUND   On CPU / runqueue              Unknown state LOGOFF                     3221
FOREGROUND   log file sync                  Unknown state COMMIT                     2576 -- пользовательских процессов в моменты ожидания выполнения служебных действий
BACKGROUND   control file sequential read   Unknown state VERSION2                   2459
BACKGROUND   ARCH wait on SENDREQ           Unknown state ROLLBACK                   2358
BACKGROUND   On CPU / runqueue              Unknown state ROLLBACK                   1960
BACKGROUND   gcs log flush sync             Unknown state                            1680
FOREGROUND   On CPU / runqueue              Unknown state V8 Bundled Exec            1402 -- пользовательских процессов на ЦПУ???
BACKGROUND   On CPU / runqueue              Unknown state VERSION2                   1174
BACKGROUND   Log archive I/O                Unknown state LOGOFF                     1136
BACKGROUND   ARCH wait on SENDREQ           Unknown state VERSION2                   1071

Если выделить только пользовательские процессы:

SQL> select decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue') as EVENT,
  2         top_level_call_name,
  3         sql_opname,
  4         sql_plan_operation,
  5         count(*)
  6    from gv$active_session_history
  7   where time_model = 0
  8     and session_type = 'FOREGROUND'
  9     and in_connection_mgmt = 'N'
 10     and in_parse = 'N'
 11     and in_hard_parse = 'N'
 12     and in_sql_execution = 'N'
 13     and in_plsql_execution = 'N'
 14     and in_plsql_rpc = 'N'
 15     and in_bind = 'N'
 16     and in_cursor_close = 'N'
 17   group by decode(session_state, 'WAITING', EVENT, 'On CPU / runqueue'),
 18            top_level_call_name,
 19            sql_opname,
 20            sql_plan_operation
 21  having count(*) > 200
 22   order by count(*) desc
 23  /

EVENT                          TOP_LEVEL_CALL_NAME  SQL_OPNAME  SQL_PLAN_OPERATION    COUNT(*)
------------------------------ -------------------- ----------- ------------------- ----------
log file sync                  COMMIT                                                     2549
On CPU / runqueue              V8 Bundled Exec      SELECT      SELECT STATEMENT          1044 -- **
SQL*Net more data from client  V8 Bundled Exec                                             818
On CPU / runqueue              ROLLBACK                                                    439
On CPU / runqueue              V8 Bundled Exec                                             323
null event                     LOGOFF                                                      266
log file sync                  ROLLBACK                                                    247
On CPU / runqueue              LOGOFF               SELECT                                 234
On CPU / runqueue              COMMIT                                                      228
On CPU / runqueue              Cursor close all                                            222

** — то кроме выполнения служебных действий (COMMIT, ROLLBACK, LOGOFF, etc.), создаётся впечатление, что time_model = 0 как-то связано с ЦПУ активностью на этапе выполнения

Что при ближайшем рассмотрении, в большинстве случаев, оказывается отражением сетевых ожиданий на этапах установки (1st — первая запись сессии в ASH) или завершения (Last) соединения:

SQL> select p1text,
  2         case
  3           when rn = 1 then '1st'
  4           when rn = cnt then 'Last'
  5           else 'Other'
  6         end as "Order",
  7         count(*)
  8    from (select p1text,
  9                 ROW_NUMBER() OVER(PARTITION BY inst_id, session_id, session_serial# ORDER BY sample_id) rn,
 10                 COUNT(*) OVER(PARTITION BY inst_id, session_id, session_serial#) cnt
 11            from gv$active_session_history
 12           where time_model = 0
 13             and session_type = 'FOREGROUND'
 14             and in_connection_mgmt = 'N'
 15             and in_parse = 'N'
 16             and in_hard_parse = 'N'
 17             and in_sql_execution = 'N'
 18             and in_plsql_execution = 'N'
 19             and in_plsql_rpc = 'N'
 20             and in_bind = 'N'
 21             and in_cursor_close = 'N'
 22             and top_level_call_name = 'V8 Bundled Exec'
 23             and sql_opname = 'SELECT'
 24             and sql_plan_operation is not null
 25             and session_state <> 'WAITING')
 26   group by p1text,
 27         case
 28           when rn = 1 then '1st'
 29           when rn = cnt then 'Last'
 30           else 'Other'
 31         end
 32   order by count(*) desc
 33  /

P1TEXT                                                           Order   COUNT(*)
---------------------------------------------------------------- ----- ----------
driver id                                                        1st          861
driver id                                                        Last         102
driver id                                                        Other         42
outstanding #aio                                                 1st           14
file#                                                            1st           11
address                                                          1st            2
file number                                                      1st            1
sleeptime/senderid                                               1st            1

, на что указывает и название первого параметра ожидания (на который имхо нелишне смотреть даже при session_state = ‘ON CPU’), характерного только для SQL*Net ожиданий:

SQL> select name, wait_class from v$event_name where parameter1 = 'driver id';

NAME                                                             WAIT_CLASS
---------------------------------------------------------------- -----------
SQL*Net message to client                                        Network
SQL*Net message to dblink                                        Network
SQL*Net more data to client                                      Network
SQL*Net more data to dblink                                      Network
SQL*Net message from client                                      Idle
SQL*Net more data from client                                    Network
SQL*Net message from dblink                                      Network
SQL*Net more data from dblink                                    Network
SQL*Net vector message from client                               Idle
SQL*Net vector message from dblink                               Idle
SQL*Net vector data to client                                    Network
SQL*Net vector data from client                                  Network
SQL*Net vector data to dblink                                    Network
SQL*Net vector data from dblink                                  Network
SQL*Net break/reset to client                                    Application
SQL*Net break/reset to dblink                                    Application

5 комментариев »

  1. Вот это детектив.

    комментарий от poxid — 13.03.2014 @ 09:21 | Ответить

  2. Холмс, вы гений! Интересный случай и столь же интересный итог разруливания проблемы. Вы, мастер своего дела.

    комментарий от Аноним — 13.03.2014 @ 19:05 | Ответить

  3. Рад, что понравилось)

    Вдогонку с leborchuk разобрали значение поля TIME_MODEL как простого бинарного состояния запроса:

    SQL> col tm_to_bin for 99999999999999999999
    SQL> select t.*,
      2         XMLQuery('declare function local:to_bin($dec)
      3                      {
      4                        if ($dec != 0) then
      5                         concat(local:to_bin(floor($dec * 0.5)),substring("01",($dec mod 2)+1,1))
      6                        else (0)
      7                      }; (: eof :)
      8                      local:to_bin(number())' PASSING XMLELEMENT(time_model, time_model) RETURNING CONTENT)
      9         .getnumberval() tm_to_bin
     10    from (SELECT
     11                 IN_SEQUENCE_LOAD,
     12                 in_cursor_close,
     13                 in_bind,
     14                 IN_JAVA_EXECUTION,
     15                 IN_PLSQL_COMPILATION,
     16                 in_plsql_rpc,
     17                 in_plsql_execution,
     18                 in_sql_execution,
     19                 in_hard_parse,
     20                 in_parse,
     21                 in_connection_mgmt,
     22                 time_model
     23            FROM gv$active_session_history ash
     24           GROUP BY time_model,
     25                    in_connection_mgmt,
     26                    in_parse,
     27                    in_hard_parse,
     28                    in_sql_execution,
     29                    in_plsql_execution,
     30                    in_plsql_rpc,
     31                    IN_PLSQL_COMPILATION,
     32                    IN_JAVA_EXECUTION,
     33                    in_bind,
     34                    in_cursor_close,
     35                    IN_SEQUENCE_LOAD) t
     36   ORDER BY time_model
     37  /
    
    I I I I I I I I I I I TIME_MODEL             TM_TO_BIN
    - - - - - - - - - - - ---------- ---------------------
    N N N N N N N N N N N          0                     0
    N N N N N N N N N N Y          8                  1000
    N N N N N N N N N Y N         16                 10000
    N N N N N N N N N Y Y         24                 11000
    N N N N N N N N Y Y N        144              10010000
    N N N N N N N Y N N N       1024           10000000000
    N N N N N N N Y N N Y       1032           10000001000
    N N N N N N N Y N Y N       1040           10000010000
    N N N N N N N Y Y Y N       1168           10010010000
    N N N N N N Y Y N N N       3072          110000000000
    N N N N N N Y Y N Y N       3088          110000010000
    N N N N N Y N Y N N N       5120         1010000000000
    N N N N N Y Y N N N N       6144         1100000000000
    N N N N Y N N N Y Y N       8336        10000010010000
    N N N N Y N N Y Y Y N       9360        10010010010000
    N N Y N N N N N N N N      32768      1000000000000000
    N N Y N N N N N N N Y      32776      1000000000001000
    N N Y N N N N N Y Y N      32912      1000000010010000
    N N Y N N N N Y N N N      33792      1000010000000000
    N N Y N N N N Y Y Y N      33936      1000010010010000
    N Y N N N N N N N N N      65536     10000000000000000
    N Y N N N N N N N N Y      65544     10000000000001000
    N Y N N N N N Y Y Y N      66704     10000010010010000
    N Y N N N N Y Y N N N      68608     10000110000000000
    Y N N N N N N Y N N N     132096    100000010000000000
    Y N N N N N N Y N Y N     132112    100000010000010000

    При запуске запроса из PL/SQL Developer легко поймать мутный Bug 18057060 : ORA-600 [QMXQRWREWRNDUPLUS2] CREATING XMLTYPE VIEW, неповторяемый из SQL*Plus

    комментарий от Игорь Усольцев — 13.03.2014 @ 22:45 | Ответить

  4. А что было то? В чем причина?

    комментарий от jimroll — 13.03.2014 @ 22:54 | Ответить

    • сетевые «проблемы связи с дц F и G», собственно Oracle работал штатно)

      комментарий от Игорь Усольцев — 13.03.2014 @ 23:36 | Ответить


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 такие блоггеры, как: