Oracle mechanics

15.05.2012

gc cr block busy при восстановлении CR копии блока (data blocks consistent reads — undo records applied)

Filed under: Oracle,statistics,wait events — Igor Usoltsev @ 00:38
Tags: , ,

Как обычно неожиданно медленно начинал выполняться обычно быстрый запрос, не возвращающий строк :(:

При этом запрос выполняется медленно  на разных инстансах по-разному, на первом:

11.2.0.3.OEBS1@SQL> SELECT NVL(SUM(RA.AMOUNT_APPLIED),0) FROM APPS.AR_RECEIVABLE_APPLICATIONS RA WHERE RA.CASH_RECEIPT_ID = '11064237' AND RA.STATUS IN ('OCC','OTHER OCC');

NVL(SUM(RA.AMOUNT_APPLIED),0)
-----------------------------
0

1 row selected.

Elapsed: 00:00:01.21

Statistics
----------------------------------------------------------
0  recursive calls
0  db block gets
4  consistent gets  --< Here be dragons
0  physical reads
0  redo size
...

а на 2-м:

Elapsed: 00:00:01.09

Statistics
----------------------------------------------------------
0  recursive calls
0  db block gets
37756  consistent gets  --< Here be dragons
0  physical reads
64  redo size
...

При одинаково прекрасном плане выполнения:

Execution Plan
----------------------------------------------------------
Plan hash value: 3019182669

---------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name                           | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                                |     1 |    17 |     6   (0)| 00:00:01 |
|   1 |  SORT AGGREGATE              |                                |     1 |    17 |            |       |
|   2 |   TABLE ACCESS BY INDEX ROWID| AR_RECEIVABLE_APPLICATIONS_ALL |     3 |    51 |     6   (0)| 00:00:01 |
|*  3 |    INDEX RANGE SCAN          | AR_RECEIVABLE_APPLICATIONS_N1  |     3 |       |     4   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------------------

Статистика выполнения на 2-м инстансе прямо показывает причину множественных чтений корневого блока индекса (index branch block) и, как следствие, медленного выполнения запроса:

Session Statistics

NAME                                                                    DELTA
---------------------------------------------------------------- ------------
logical read bytes from cache                                       309297152
consistent gets                                                         37756
session logical reads                                                   37756
consistent gets from cache                                              37756
consistent gets - examination                                           37755
data blocks consistent reads - undo records applied                     37748  --< Here be dragons
consistent changes                                                      37748
...
redo size                                                                  64
active txn count during cleanout                                            4  --  4 активные транзации перед выполнением запроса плодили undo записи в индексных блоков
...
buffer is not pinned count                                                  1
index scans kdiixs1                                                         1  --  1 сканирование индекса / доступ к корневому блоку
cleanout - number of ktugct calls                                           1
immediate (CR) block cleanout applications                                  1
cleanouts and rollbacks - consistent read gets                              1
redo entries                                                                1
calls to get snapshot scn: kcmgss                                           1
calls to kcmgas                                                             1
CR blocks created                                                           1  --  восстановлен CR образ одного блока - корневого блока индекса
free buffer requested                                                       1
db block changes                                                            1
consistent gets from cache (fastpath)

- и действительно, в обзорах gv$session и gv$transaction легко найти 4 многочасовых транзакции, запущенные на 2-м инстансе и активно меняющие блоки интересующей таблицы и соответствующего индекса

Как Oracle восстанавливает консистентную версию блока данных, многократно изменённого открытыми транзакциями (что отражается статистикой data blocks consistent reads — undo records applied) отлично описал Дж.Льюисом:

Get current block                                                                   -- берётся текущая копия блока
Notice uncommitted transaction                                                      -- в ITL находятся незавершённые транзакции
Clone current block – then ignore current block                                     -- текущий блок клонируеся
Get Undo block indicated by uncommitted ITL and apply undo change vector            -- применяются undo изменения
Repeat step four – 1,000 times                                                      -- шаг 4 повторяется N раз - по числу изменений блока
Block is now clear of all uncommitted transactions                                  -- теперь блок cleaned up - восстановлен
There are no committed transactions with a commit SCN later than the start of query -- и нет завершённых транзакций с commit SCN, превышающим время старта запроса
Display contents of block                                                           -- блок возвращается для обработки в курсоре

Интересно, что статистики и ожидания на 1-м инстансе для вышепоказанного медленного выполнения могут выглядеть либо не совсем адекватными (в смысле непозволяющими определить причину низкой производительности запроса):

Session Time Model

STAT_NAME                                                               DELTA
---------------------------------------------------------------- ------------
DB time                                                               1039650
DB CPU                                                                   3999
parse time elapsed                                                       3135
hard parse elapsed time                                                  2782
sql execute elapsed time                                              1036406
hard parse (sharing criteria) elapsed time                               2803

Session Statistics

NAME                                                                    DELTA
---------------------------------------------------------------- ------------
logical read bytes from cache                                           49152
bytes received via SQL*Net from client                                    413
bytes sent via SQL*Net to client                                          366
DB time                                                                   103
gc cr block receive time                                                  103
non-idle wait time                                                        103
cluster wait time                                                         103
non-idle wait count                                                        13
recursive calls                                                             8
consistent gets from cache                                                  6
consistent gets                                                             6
session logical reads                                                       6
buffer is not pinned count                                                  5
global enqueue releases                                                     4
global enqueue gets sync                                                    4
consistent gets - examination                                               3
no work - consistent read gets                                              3
user calls                                                                  3
parse count (total)                                                         2
table fetch by rowid                                                        2
gc cr blocks received                                                       2
calls to get snapshot scn: kcmgss                                           2
free buffer requested                                                       2
consistent gets from cache (fastpath)                                       2
ges messages sent                                                           2
gcs messages sent                                                           2
enqueue releases                                                            2
enqueue requests                                                            2
SQL*Net roundtrips to/from client                                           2
Requests to/from client                                                     2
opened cursors cumulative                                                   2
execute count                                                               2
index scans kdiixs1                                                         1
shared hash latch upgrades - no wait                                        1
parse count (hard)                                                          1

Session Wait Events

NAME                                                                    WAITS      TIME_MS     TIMEOUTS AVG_WAIT_MS
---------------------------------------------------------------- ------------ ------------ ------------ -----------
SQL*Net message from client                                                 2       152918            0     76458,8
library cache lock                                                          1            0            0         0,3
library cache pin                                                           1            0            0         0,2
Disk file operations I/O                                                    1            0            0           0
SQL*Net message to client                                                   2            0            0           0

, либо указывать в качестве причины замедления ожидание gc cr block busy:

NAME                                                                    WAITS      TIME_MS     TIMEOUTS AVG_WAIT_MS
---------------------------------------------------------------- ------------ ------------ ------------ -----------
SQL*Net message from client                                                 7       247406            0     35343,7
gc cr block busy                                                            2          572            0       285,9
...

, формально относящееся к классу Contention-Related Wait Events, что также не совсем понятно указывает источник проблемы

Или же событие gc cr block busy кроме проблем с конкуренцией отображает задержки cache fusion, связанные с восстановлением CR версии блока на удалённом инстансе

К слову, в упомянутых 4-х  долгоиграющих транзакциях на 2-м инстансе выполнение подобных запросов по той же причине со временем значительно замедляется судя по трейсу, обработанному tkprof:

SQL ID: 2kdudjnay024c Plan Hash: 3019182669

SELECT SUM(NVL(RA.AMOUNT_APPLIED,0))
FROM
AR_RECEIVABLE_APPLICATIONS RA WHERE RA.STATUS = 'XUNAPP' AND
RA.CASH_RECEIPT_ID = :B1

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     3190      0.10       0.10          0          0          0           0
Execute   3190      0.29       0.29          0          0          0           0
Fetch     3190    330.37     331.78          0    8622386          0        3190
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     9570    330.77     332.18          0    8622386          0        3190

- от 332/9570 ~ 35 мс в среднем в первой части выполнения длинной транзакции / бизнес-процесса

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse    10785      0.33       0.35          0          0          0           0
Execute  10785      1.01       1.00          0          0          0           0
Fetch    10785   2040.08    2048.59         20   53829119          0       10785
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    32355   2041.44    2049.95         20   53829119          0       10785

до 2050/32355 ~ 63 мс и более в дальнейшем

Такое же поведение при желании можно наблюдать на сыром трейсе по ключевому слову FETCH — т.к. именно так отражается в трейсе получение CR версии индексного блока:

  • в начале выполнения одной из длинных конкурирующих транзакций на FETCH для sql_id=2kdudjnay024c  тратилось не более 98 мс (максимально e=97709 мкс):
$ grep -A11 '2kdudjnay024c' OEBS2_ora_8466.trc | grep 'FETCH \#'
FETCH #140393572320184:c=8999,e=9073,p=0,cr=340,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336742598010284
FETCH #140393572320184:c=8998,e=8454,p=0,cr=340,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336742598030234
FETCH #140393572194608:c=91986,e=92280,p=0,cr=2703,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336742598422093
FETCH #140393572320184:c=93986,e=95273,p=0,cr=2703,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336742598822852
FETCH #140393572322952:c=96985,e=97709,p=0,cr=2707,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336742599520032
...
  • по прошествии времени, в результате накопления незакоммиченных undo записей — верхняя граница времени выполнения (фактически длительность FETCH) поднялась почти до 500 мс (e=479399):
$ grep -A11 '2kdudjnay024c' OEBS2_ora_8466.trc | grep 'FETCH \#' | tail
FETCH #140393572320184:c=16997,e=16625,p=0,cr=1256,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336749645285213
FETCH #140393572320184:c=476927,e=479399,p=0,cr=12923,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336749649916157
FETCH #140393572320184:c=17997,e=17785,p=0,cr=1256,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336749649940511
FETCH #140393572320184:c=17998,e=17160,p=0,cr=1256,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336749649968965
FETCH #140393572320184:c=468929,e=469419,p=0,cr=12923,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336749651358866

При неконкурентном выполнении единственная долгоиграющая транзакция выполняется заметно быстрее за счёт меньшего времени выполнения (опять практически эквивалентного времени FETCH) этих мелких запросов — не более 14 мс:

$ grep -A11 '2kdudjnay024c' OEBS2_ora_17496.trc | grep 'FETCH \#' | tail
FETCH #140663993451216:c=13997,e=13763,p=0,cr=2254,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336808772337328
FETCH #140663993451216:c=0,e=40,p=0,cr=6,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336808773027127
FETCH #140663993451216:c=12998,e=12621,p=0,cr=2254,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336808773043174
FETCH #140663993451216:c=12998,e=12892,p=0,cr=2254,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336808773064386
FETCH #140663993451216:c=0,e=45,p=0,cr=6,cu=0,mis=0,r=1,dep=1,og=1,plh=3019182669,tim=1336808773445262

- в отсутствие конкурирующих транзакций, многократно меняющих одни и те же блоки, undo records applied не требуются

About these ads

Комментарии (2) »

  1. «нет незавершённых транзакций с commit SCN, превышающим время старта запроса»- неверный перевод, правильный — «завершённых транзакций». Это же весь смысл меняет. Внимательнее надо быть.

    комментарий от Аноним — 23.11.2012 @ 15:29 | Ответить

    • благодаря внимательному анонимному читателю смысл восстановлен ;)

      комментарий от Igor Usoltsev — 23.11.2012 @ 17:05 | Ответить


RSS-лента комментариев к этой записи. TrackBack URI

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

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

Логотип WordPress.com

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

Фотография Twitter

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

Фотография Facebook

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

Google+ photo

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

Connecting to %s

Тема: Rubric. Блог на WordPress.com.

Отслеживать

Get every new post delivered to your Inbox.

Join 112 other followers

%d bloggers like this: