ReSQL.ru
     
powered by simpleCommunicator - 2.0.61     © 2026 Programmizd 02
Мобильная версия    Контакт    Правила    FAQ    Помощь
Целевая тема:
Создать новую тему:
Автор:
Закрыть
Цитировать
Доб. в избранное | Игнор. тему | Прикреп. тему | Пометить прочит. / непрочит. | Фильтр
Форумы / Oracle [игнор отключен] [закрыт для гостей] / Помогите найти, на что уходит время при выполнении запроса
11 сообщений из 11, страница 1 из 1
Помогите найти, на что уходит время при выполнении запроса
    #39491271
Вадиман
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Вадиман
Участник
Всем добрый день!
Имеется: Oracle EE 12.1.0.2 на Oracle linux 86-64. RAC, 2 ноды, AMM, ASM.

 
show sga

SQL> show sga
Код: plaintext
1.
2.
3.
4.
5.
Total System Global Area 3154116608 bytes
Fixed Size                  3715784 bytes
Variable Size            2080378168 bytes
Database Buffers         1056964608 bytes
Redo Buffers               13058048 bytes


Раз в 5 минут выполняется запрос, время выполнения которого скачет от 3 секунд до 20 и выше.
Есть зафиксированный baseline (fixed=yes, он только один такой для того sql_handle).
Вот некоторая информация по выполнению, что осталась в sga:
 
селект из gv$sql
Код: plaintext
1.
2.
3.
4.
5.
   INST_ID CHILD_NUMBER LAST_ACTIVE_TIME    PLAN_HASH_VALUE SQL_PLAN_BASELINE                   LOADS INVALIDATIONS PARSE_CALLS EXECUTIONS ELAPSED_TIME BUFFER_GETS DISK_READS ROWS_PROCESSED
---------- ------------ ------------------- --------------- ------------------------------ ---------- ------------- ----------- ---------- ------------ ----------- ---------- --------------
         1            3 19.07.2017 02:05:48       495323912 SQL_PLAN_b3pxjnwkycv95efd45c5a          2             2           1          2     19018964      244751      15149             16
         1            2 19.07.2017 01:40:35       495323912 SQL_PLAN_b3pxjnwkycv95efd45c5a          5             5           0          1      4997373      122392       8229              8
         2            0 19.07.2017 01:30:36       495323912 SQL_PLAN_b3pxjnwkycv95efd45c5a         20            15           0          1      4698073      222098       9606              8


В gv$sql данный sql_id присутствует только с SQL_PLAN_BASELINE=SQL_PLAN_b3pxjnwkycv95efd45c5a.
Здесь не самые показательные цифры по elapsed time, были варианты, где один child выполнялся 1 раз за 3 секунды, а второй - 3 раза за 60 секунд. Сейчас выдернул то, что есть сейчас.
Большое кол-во invalidations, возможно, связано с регулярным ddl по объединению партиций в сканируемой таблице (делается ежечасно в периоды низкой нагрузки, итого где-то 10 раз за сутки). Кстати, как бы узнать истинную причину без догадок?

Структура партиций - RANGE-HASH, хэшей 8, интервал по часу. Партиции сейчас выглядят так:

 
партиции таблицы
Код: plaintext
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
PARTITION_NAME                 PARTITION_POSITION CREATED              LAST_DDL_TIME        STAT_NUM_ROWS STAT_BLOCKS         LR         PR  PR_DIRECT   BB_WAITS GC_CR_RECEIVED  ROW_LOCKS
------------------------------ ------------------ -------------------- -------------------- ------------- ----------- ---------- ---------- ---------- ---------- -------------- ----------
P_OLD                                           1 06.07.2017 01:36:15  06.07.2017 01:36:15        1031064       38347    4914640     223572   22332550          0           1853          0
P_2016_Q1                                       2 06.07.2017 01:36:15  06.07.2017 01:36:15         369623       18573    1379312     108984   10243650          0           1026          0
P_2016_Q2                                       3 06.07.2017 01:36:15  06.07.2017 01:36:15         450805       24236    5046304     832771   15527736          0           1658          0
P_2016_Q3                                       4 06.07.2017 01:36:15  06.07.2017 01:36:15         592966       29811   23743232    1516206   26908964          2           1210          0
P_2016_Q4                                       5 06.07.2017 01:36:15  06.07.2017 01:36:15         799076       40139   40643488    9344152   48280921          0           7858          0
P_2017_M1                                       6 06.07.2017 01:36:15  06.07.2017 01:36:15         328725       22269   17944048    1013011   25898063          0           8104          0
P_2017_M2                                       7 06.07.2017 01:36:15  06.07.2017 01:36:15         304667       21108   25535840    2191327   24873245          0           5663          0
P_2017_M3                                       8 06.07.2017 01:36:15  06.07.2017 01:36:15         408529       29908   42201184    7836283   43629612          0           5567          0
P_2017_M4                                       9 06.07.2017 01:36:15  06.07.2017 01:36:15         390700       29487   47662944    4722718   41554287          0           2928          0
P_2017_M5                                      10 06.07.2017 01:36:15  06.07.2017 01:36:15         438412       33599   23636752    7126413   67534833          0           3542          1
P_2017_M6                                      11 08.07.2017 00:25:02  08.07.2017 00:25:02         409630       31819   67153984    9213136   83081396          7          23178          0
P_2017_M7                                      12 19.07.2017 00:25:03  19.07.2017 00:25:03                                232848      55805      51300          0             46          0
P_2017_M7_D11                                  13 12.07.2017 03:11:10  12.07.2017 03:11:10          13569        1174    4591024        959     151312          0           4285          0
P_2017_M7_D12                                  14 13.07.2017 03:11:04  13.07.2017 03:11:04          14701        2054    6079792        619     177031          0           3543          0
P_2017_M7_D13                                  15 14.07.2017 01:11:04  14.07.2017 01:11:04          12728        1953    6950976        650     136001          0           2882          0
P_2017_M7_D14                                  16 15.07.2017 01:11:03  15.07.2017 01:11:03          14019        1227    5863056         72     107719          0           3038          0
P_2017_M7_D15                                  17 16.07.2017 01:11:01  16.07.2017 01:11:01           8606        1758    3660160        188      70314          0           1738          0
P_2017_M7_D16                                  18 17.07.2017 01:11:04  17.07.2017 01:11:04           8353        1739    1241856         77      27758          0            663          0
P_2017_M7_D16                                  18 17.07.2017 01:11:05  17.07.2017 01:11:05           8353        1739    1875328        112      41072          0            846          0
P_2017_M7_D17                                  19 18.07.2017 01:11:03  18.07.2017 01:11:03          12115        1887    2318640        180      20387          0           1703          0
P_2017_M7_D18                                  20 19.07.2017 01:11:09  19.07.2017 01:11:09                                 64240        861          0          0            104          0
P_2017_M7_D19                                  21 18.07.2017 23:00:02  18.07.2017 23:00:02                               3832080    1094451    1086400          0           5671          0
SYS_P42567                                     22 19.07.2017 00:00:02  19.07.2017 00:00:02                               2999440    1625906    1622288          0           5618          0
SYS_P42607                                     23 19.07.2017 01:00:00  19.07.2017 01:00:00                               1718272       2487          0          0           4192          0
SYS_P42647                                     24 19.07.2017 02:00:02  19.07.2017 02:00:02                               2470304    1736611    1736050          0           4950          0


Запрос сканирует данные за последние сутки. Соответственно, под замес попадают последние интервальные партиции и 1-2 последних подневные партиции (почасовки схлопываются в последнюю дневную).

В трассе никаких существенных ожиданий, кроме самого чтения, нет:
 
обработанная трасса
Код: plaintext
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
38.
39.
40.
41.
42.
43.
44.
45.
46.
47.
48.
49.
50.
51.
52.
53.
54.
55.
56.
57.
58.
59.
60.
61.
62.
63.
64.
65.
66.
67.
68.
69.
70.
71.
72.
73.
74.
75.
76.
77.
78.
79.
80.
81.
82.
83.
84.
85.
86.
87.
88.
89.
90.
91.
92.
93.
94.
95.
96.
97.
98.
99.
100.
call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        0      0.00       0.00          0          0          0           0
Execute      1      2.28      21.77      14238     105827       1123           0
Fetch        1      0.43       0.46        925      18680         60           8
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      2.72      22.23      15163     124507       1183           8

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 148  
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         8          8          8  SORT AGGREGATE (cr=7472 pr=0 pw=0 time=92872 us)
         1          1          1   VIEW  (cr=7472 pr=0 pw=0 time=92794 us cost=2 size=493 card=1)
    421832     421832     421832    TABLE ACCESS FULL SYS_TEMP_0FD9D954A_4D557C49 (cr=7472 pr=0 pw=0 time=86393 us cost=2 size=359 card=1)
         8          8          8  SORT AGGREGATE (cr=7472 pr=0 pw=0 time=95073 us)
        20         20         20   VIEW  (cr=7472 pr=0 pw=0 time=71681 us cost=2 size=493 card=1)
    421832     421832     421832    TABLE ACCESS FULL SYS_TEMP_0FD9D954A_4D557C49 (cr=7472 pr=0 pw=0 time=82156 us cost=2 size=359 card=1)
         8          8          8  TEMP TABLE TRANSFORMATION  (cr=123160 pr=15143 pw=925 time=21865715 us)
         0          0          0   LOAD AS SELECT  (cr=104480 pr=14218 pw=925 time=21399972 us)
         5          5          5    COLLECTION ITERATOR PICKLER FETCH AUTH_FINAL_STATUS (cr=0 pr=0 pw=0 time=730 us cost=2 size=2 card=1)
         3          3          3    COLLECTION ITERATOR PICKLER FETCH DECLINED_STATUS (cr=0 pr=0 pw=0 time=235 us cost=2 size=2 card=1)
     52729      52729      52729    WINDOW SORT (cr=104480 pr=14218 pw=0 time=21182700 us cost=116169 size=359 card=1)
     52729      52729      52729     NESTED LOOPS  (cr=104480 pr=14218 pw=0 time=20284747 us cost=116163 size=359 card=1)
     52729      52729      52729      NESTED LOOPS  (cr=76117 pr=13617 pw=0 time=17506024 us cost=116163 size=359 card=4)
     12106      12106      12106       HASH JOIN OUTER (cr=52886 pr=13287 pw=0 time=16438206 us cost=116159 size=330 card=1)
     12106      12106      12106        NESTED LOOPS  (cr=52879 pr=13287 pw=0 time=15896777 us cost=116155 size=313 card=1)
     12106      12106      12106         NESTED LOOPS  (cr=40773 pr=10093 pw=0 time=4597727 us cost=116155 size=313 card=1)
     12106      12106      12106          HASH JOIN  (cr=16564 pr=9034 pw=0 time=73378 us cost=116153 size=280 card=1)
       114        114        114           TABLE ACCESS FULL ACCOUNT (cr=7 pr=0 pw=0 time=70 us cost=4 size=1130 card=113)
     12757      12757      12757           HASH JOIN RIGHT OUTER (cr=16555 pr=9034 pw=0 time=63954 us cost=116149 size=270 card=1)
       682        682        682            VIEW  V_TERMINAL_LINK (cr=31 pr=0 pw=0 time=3402 us cost=10 size=154584 card=678)
       682        682        682             HASH JOIN  (cr=31 pr=0 pw=0 time=3175 us cost=10 size=24408 card=678)
       175        175        175              HASH JOIN  (cr=15 pr=0 pw=0 time=2100 us cost=5 size=4872 card=174)
        11         11         11               TABLE ACCESS FULL BANK (cr=7 pr=0 pw=0 time=34 us cost=3 size=220 card=11)
       175        175        175               VIEW  index$_join$_035 (cr=8 pr=0 pw=0 time=1225 us cost=2 size=1392 card=174)
       175        175        175                HASH JOIN  (cr=8 pr=0 pw=0 time=1225 us)
       175        175        175                 INDEX FAST FULL SCAN EXT_TERMINAL_PK (cr=4 pr=0 pw=0 time=113 us cost=1 size=1392 card=174)(object id 97733)
       175        175        175                 INDEX FAST FULL SCAN EXT_TERMINAL_UK1 (cr=4 pr=0 pw=0 time=192 us cost=1 size=1392 card=174)(object id 97734)
       682        682        682              TABLE ACCESS FULL TERMINAL_LINK (cr=16 pr=0 pw=0 time=142 us cost=5 size=5424 card=678)
     12757      12757      12757            HASH JOIN  (cr=16524 pr=9034 pw=0 time=50594 us cost=116139 size=42 card=1)
       105        105        105             TABLE ACCESS FULL CWALLET (cr=7 pr=0 pw=0 time=62 us cost=4 size=1040 card=104)
      12757      12757      12757             PARTITION RANGE ITERATOR PARTITION: KEY 1048575 (cr=16517 pr=9034 pw=0 time=38934 us cost=116135 size=32 card=1)
     12757      12757      12757              PARTITION HASH ALL PARTITION: 1 8 (cr=16517 pr=9034 pw=0 time=52164 us cost=116135 size=32 card=1)
     12757      12757      12757               TABLE ACCESS FULL ORDERU PARTITION: KEY 1048575 (cr=16517 pr=9034 pw=0 time=7213762 us cost=116135 size=32 card=1)
          1          1          1           SORT AGGREGATE (cr=2 pr=0 pw=0 time=28 us)
         1          1          1            TABLE ACCESS BY INDEX ROWID MONITOR_JOB_PARAM (cr=2 pr=0 pw=0 time=15 us cost=1 size=25 card=1)
         1          1          1             INDEX UNIQUE SCAN MONITOR_JOB_PARAM_UK1 (cr=1 pr=0 pw=0 time=9 us cost=0 size=0 card=1)(object id 97481)
     12106      12106      12106          INDEX UNIQUE SCAN CARD_PK (cr=24209 pr=1059 pw=0 time=4124708 us cost=1 size=0 card=1)(object id 97423)
     12106      12106      12106         TABLE ACCESS BY INDEX ROWID CARD (cr=12106 pr=3194 pw=0 time=11300343 us cost=2 size=33 card=1)
        23         23         23        TABLE ACCESS FULL BANK (cr=7 pr=0 pw=0 time=50 us cost=4 size=391 card=23)
     52729      52729      52729       INDEX RANGE SCAN ORDERU_STATUS_HISTORY_IDX2 (cr=23231 pr=330 pw=0 time=1879000 us cost=2 size=0 card=4)(object id 97427)
     52729      52729      52729      TABLE ACCESS BY INDEX ROWID ORDERU_STATUS_HISTORY (cr=28363 pr=601 pw=0 time=2568602 us cost=4 size=116 card=4)
         8          8          8   SORT ORDER BY (cr=18680 pr=925 pw=0 time=464799 us cost=17 size=2099 card=1)
         8          8          8    HASH JOIN RIGHT OUTER (cr=3736 pr=925 pw=0 time=276409 us cost=12 size=2099 card=1)
         3          3          3     VIEW  (cr=934 pr=925 pw=0 time=52651 us cost=3 size=503 card=1)
         3          3          3      HASH GROUP BY (cr=934 pr=925 pw=0 time=52650 us cost=3 size=480 card=1)
        93         93         93       VIEW  (cr=934 pr=925 pw=0 time=52272 us cost=3 size=480 card=1)
        93         93         93        HASH GROUP BY (cr=934 pr=925 pw=0 time=52179 us cost=3 size=505 card=1)
       449        449        449         VIEW  (cr=934 pr=925 pw=0 time=5500 us cost=2 size=505 card=1)
     52729      52729      52729          TABLE ACCESS FULL SYS_TEMP_0FD9D954A_4D557C49 (cr=934 pr=925 pw=0 time=11432 us cost=2 size=359 card=1)
         8          8          8     HASH JOIN RIGHT OUTER (cr=2802 pr=0 pw=0 time=223526 us cost=9 size=1596 card=1)
         4          4          4      VIEW  (cr=934 pr=0 pw=0 time=11868 us cost=3 size=490 card=1)
         4          4          4       HASH GROUP BY (cr=934 pr=0 pw=0 time=11864 us cost=3 size=493 card=1)
      8253       8253       8253        VIEW  (cr=934 pr=0 pw=0 time=11868 us cost=2 size=493 card=1)
     52729      52729      52729         TABLE ACCESS FULL SYS_TEMP_0FD9D954A_4D557C49 (cr=934 pr=0 pw=0 time=8762 us cost=2 size=359 card=1)
         8          8          8      HASH JOIN OUTER (cr=1868 pr=0 pw=0 time=211422 us cost=6 size=1106 card=1)
         8          8          8       VIEW  (cr=934 pr=0 pw=0 time=198163 us cost=3 size=616 card=1)
         8          8          8        HASH GROUP BY (cr=934 pr=0 pw=0 time=198152 us cost=3 size=507 card=1)
     52729      52729      52729         VIEW  (cr=934 pr=0 pw=0 time=26554 us cost=2 size=507 card=1)
     52729      52729      52729          TABLE ACCESS FULL SYS_TEMP_0FD9D954A_4D557C49 (cr=934 pr=0 pw=0 time=11578 us cost=2 size=359 card=1)
         3          3          3       VIEW  (cr=934 pr=0 pw=0 time=12519 us cost=3 size=490 card=1)
         3          3          3        HASH GROUP BY (cr=934 pr=0 pw=0 time=12518 us cost=3 size=493 card=1)
      7451       7451       7451         VIEW  (cr=934 pr=0 pw=0 time=12440 us cost=2 size=493 card=1)
     52729      52729      52729          TABLE ACCESS FULL SYS_TEMP_0FD9D954A_4D557C49 (cr=934 pr=0 pw=0 time=10683 us cost=2 size=359 card=1)


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  library cache lock                              1        0.00          0.00
  library cache pin                               1        0.00          0.00
  db file sequential read                      5198        0.03         18.12
  gc current block 2-way                        770        0.00          0.40
  gc cr grant 2-way                            1341        0.00          0.57
  gc cr block 2-way                              10        0.00          0.00
  enq: KO - fast object checkpoint               27        0.00          0.01
  reliable message                                9        0.01          0.03
  direct path read                              304        0.01          0.79
  KJC: Wait for msg sends to complete             2        0.00          0.00
  direct path write temp                          1        0.00          0.00
  gc current grant busy                           1        0.00          0.00
  db file scattered read                          8        0.00          0.02
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1      136.80        136.80
********************************************************************************


Повторяю вопрос: как найти причину, почему при одном и том же плане, при сравнимых количествах читаемых блоков последовательные выполнения запроса требуют сильно разного времени при том, что прочих существенных ожиданий, кроме дискового чтения, не видно?
...
Рейтинг: 0 / 0
19.07.2017, 05:52
| Ответить | Цитировать | Написать  
Помогите найти, на что уходит время при выполнении запроса
    #39491277
Фотография kinky cat
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
kinky cat
Участник
Вадиман,

почему бы стразу не смотреть DBMS_SQLTUNE.report_sql_monitor ? там все гораздо наглядней

Ну и по кол-ву ожиданий одноблочных чтений, видно что дело не в скане секции, а в досутпе к табличкам по индексам, самый жирный вроде
12106 12106 12106 TABLE ACCESS BY INDEX ROWID CARD (cr=12106 pr=3194 pw=0 time=11300343 us cost=2 size=33 card=1)
...
Рейтинг: 0 / 0
19.07.2017, 07:18
| Ответить | Цитировать | Написать  
Помогите найти, на что уходит время при выполнении запроса
    #39491278
Вадиман
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Вадиман
Участник
Про сканы секций я говорил потому, что это инвалидирует курсоры и, возможно, как-то влияет на скачки по времени исполнения.
Вопрос не про план. План один и тот же. Плохой или хороший, но он один и тот же.
...
Рейтинг: 0 / 0
19.07.2017, 07:23
| Ответить | Цитировать | Написать  
Помогите найти, на что уходит время при выполнении запроса
    #39491279
Вадиман
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Вадиман
Участник
Вадиман... потому, что это инвалидирует курсоры...
имел в виду "ddl по секциям инвалидирует курсоры"
...
Рейтинг: 0 / 0
19.07.2017, 07:25
| Ответить | Цитировать | Написать  
Помогите найти, на что уходит время при выполнении запроса
    #39491282
Фотография kinky cat
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
kinky cat
Участник
ВадиманПро сканы секций я говорил потому, что это инвалидирует курсоры и, возможно, как-то влияет на скачки по времени исполнения.
Вопрос не про план. План один и тот же. Плохой или хороший, но он один и тот же.
авторкак найти причину, почему при одном и том же плане, при сравнимых количествах читаемых блоков последовательные выполнения запроса требуют сильно разного времени при том, что прочих существенных ожиданий, кроме дискового чтения, не видно?
ну ок снимайте еще стату и сравнивайте две на отличия, логично, вроде ) причин то много может быть, зачем гадать
...
Рейтинг: 0 / 0
19.07.2017, 07:37
| Ответить | Цитировать | Написать  
Помогите найти, на что уходит время при выполнении запроса
    #39491283
Фотография Elic
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Elic
Участник
DISK_READS * avg_read_time ~= ELAPSED_TIME. Не?
...
Рейтинг: 0 / 0
19.07.2017, 07:40
| Ответить | Цитировать | Написать  
Помогите найти, на что уходит время при выполнении запроса
    #39491286
Вадиман
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Вадиман
Участник
Уже давно сделано.
Еще раз:
 
более свежая информация из gv$sql
Код: plaintext
1.
2.
3.
4.
5.
6.
7.
8.
   INST_ID CHILD_NUMBER LAST_ACTIVE_TIME    PLAN_HASH_VALUE SQL_PLAN_BASELINE                   LOADS INVALIDATIONS PARSE_CALLS  EXECS    ELAPSED BUFFER_GETS DISK_READS       ROWS
---------- ------------ ------------------- --------------- ------------------------------ ---------- ------------- ----------- ------ ---------- ----------- ---------- ----------
         2            2 2017-07-19:04:40:33       495323912 SQL_PLAN_b3pxjnwkycv95efd45c5a          6             3           2      3    9854663      368320      50527         24
         1            3 2017-07-19:04:35:31       495323912 SQL_PLAN_b3pxjnwkycv95efd45c5a          2             1           6      7   24784942      947905      82406         56
         2            0 2017-07-19:04:10:46       495323912 SQL_PLAN_b3pxjnwkycv95efd45c5a         24            17           0      1   15106701      134882      17646          8
         1            2 2017-07-19:03:35:42       495323912 SQL_PLAN_b3pxjnwkycv95efd45c5a          7             5           0      1    7842983      123083      11616          8
         1            0 2017-07-19:03:20:34       495323912 SQL_PLAN_b3pxjnwkycv95efd45c5a          8             2           0      1    4118865      121191       8710          8
         2            1 2017-07-19:03:15:35       495323912 SQL_PLAN_b3pxjnwkycv95efd45c5a         21            14           0      1    3774005      120256      12661          8


Попробуйте поделить elapsed, buffer_gets, disk_reads и rows на execs и сравнить между собой получившийся elapsed.
А в трассах будет нечто очень похожее на уже приведенную трассу.
Извините, что не вывалил десяток трасс сюда.
...
Рейтинг: 0 / 0
19.07.2017, 07:46
| Ответить | Цитировать | Написать  
Помогите найти, на что уходит время при выполнении запроса
    #39491287
Вадиман
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Вадиман
Участник
ElicDISK_READS * avg_read_time ~= ELAPSED_TIME. Не?
avg_read_time - это надо откуда-то взять или просто сейчас измерить?
Заглянул в sys.aux_stats$, там какая-то бяда :(

 
system stats
Код: plaintext
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
SNAME                          PNAME                               PVAL1 PVAL2
------------------------------ ------------------------------ ---------- ------------------------------
SYSSTATS_INFO                  STATUS                                    COMPLETED
SYSSTATS_INFO                  DSTART                                    07-07-2014 06:53
SYSSTATS_INFO                  DSTOP                                     07-07-2014 06:53
SYSSTATS_INFO                  FLAGS                                   1
SYSSTATS_MAIN                  CPUSPEEDNW                      3308.9701
SYSSTATS_MAIN                  IOSEEKTIM                              10
SYSSTATS_MAIN                  IOTFRSPEED                           4096
SYSSTATS_MAIN                  SREADTIM
SYSSTATS_MAIN                  MREADTIM
SYSSTATS_MAIN                  CPUSPEED
SYSSTATS_MAIN                  MBRC
SYSSTATS_MAIN                  MAXTHR
SYSSTATS_MAIN                  SLAVETHR
...
Рейтинг: 0 / 0
19.07.2017, 07:52
| Ответить | Цитировать | Написать  
Помогите найти, на что уходит время при выполнении запроса
    #39491297
Фотография Elic
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Elic
Участник
Вадиманavg_read_time - это надо откуда-то взять или просто сейчас измерить?V$FILESTAT ?
...
Рейтинг: 0 / 0
19.07.2017, 08:30
| Ответить | Цитировать | Написать  
Помогите найти, на что уходит время при выполнении запроса
    #39491310
Вадиман
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Вадиман
Участник
ElicВадиманavg_read_time - это надо откуда-то взять или просто сейчас измерить?V$FILESTAT ?
Данные лежат вот здесь:
 
gv$filestat по одному tbs
Код: plaintext
1.
2.
3.
   INST_ID      FILE#     PHYRDS    PHYWRTS   PHYBLKRD OPTIMIZED_PHYBLKRD  PHYBLKWRT SINGLEBLKRDS    READTIM   WRITETIM SINGLEBLKRDTIM   AVGIOTIM   LSTIOTIM   MINIOTIM   MAXIORTM   MAXIOWTM     CON_ID
---------- ---------- ---------- ---------- ---------- ------------------ ---------- ------------ ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ----------
         1          6   44740413     621637 1308173022                  0    1110211     19885431   16900077     764554        8383758          0          1          0     105498     108903          0
         2          6   38492537     569925  770230328                  0     885249     16121692   22193177     309211        6547290          0          0          0         60         23          0


Получу ли я среднее время, если readtim поделю на phyrds? По первому инстансу получается где-то 3.7ms, по второму - 5.7ms.
Disk reads (8k, 9k, 15k - в среднем, допустим, 10k) * avg = 37 секунд. Много. Время хоть и скачет, но все-таки меньше.
Что не так делаю?
...
Рейтинг: 0 / 0
19.07.2017, 08:52
| Ответить | Цитировать | Написать  
Помогите найти, на что уходит время при выполнении запроса
    #39491313
Вадиман
Скрыть профиль Поместить в игнор-лист Сообщения автора в теме
Вадиман
Участник
В сырой трассе вижу такие скачки:
 
вырезка из raw trace
Код: plaintext
1.
2.
3.
4.
5.
6.
7.
8.
9.
10.
11.
12.
13.
14.
15.
16.
17.
18.
19.
20.
21.
22.
23.
24.
25.
26.
27.
28.
29.
30.
31.
32.
33.
34.
35.
36.
37.
WAIT #140294503426440: nam='db file sequential read'  ela= 9126  file#=14 block#=652324 blocks=1 obj#=97098 tim=9681236320396
WAIT #140294503426440: nam='gc current block 2-way' ela= 588 p1=6 p2=61757 p3=1 obj#=97423 tim=9681236321105
WAIT #140294503426440: nam='db file sequential read'  ela= 2328  file#=6 block#=26357 blocks=1 obj#=97098 tim=9681236323505
WAIT #140294503426440: nam='gc current block 2-way' ela= 351 p1=6 p2=61318 p3=1 obj#=97423 tim=9681236323983
WAIT #140294503426440: nam='db file sequential read' ela= 9012 file#=6 block#=18430 blocks=1 obj#=97098 tim=9681236333102
WAIT #140294503426440: nam='gc cr grant 2-way' ela= 244 p1=6 p2=61967 p3=1 obj#=97423 tim=9681236333492
WAIT #140294503426440: nam='db file sequential read' ela= 6074 file#=6 block#=61967 blocks=1 obj#=97423 tim=9681236339610
WAIT #140294503426440: nam='db file sequential read' ela= 3479 file#=6 block#=21652 blocks=1 obj#=97098 tim=9681236343158
WAIT #140294503426440: nam='db file sequential read' ela= 5553 file#=6 block#=906260 blocks=1 obj#=97098 tim=9681236348799
WAIT #140294503426440: nam='db file sequential read'  ela= 2332  file#=6 block#=62407 blocks=1 obj#=97423 tim=9681236351238
WAIT #140294503426440: nam='db file sequential read' ela= 5096 file#=6 block#=19172 blocks=1 obj#=97098 tim=9681236356428
WAIT #140294503426440: nam='gc current block 2-way' ela= 461 p1=6 p2=61347 p3=1 obj#=97423 tim=9681236357071
WAIT #140294503426440: nam='db file sequential read'  ela= 1567  file#=6 block#=26783 blocks=1 obj#=97098 tim=9681236358748
WAIT #140294503426440: nam='gc current block 2-way' ela= 556 p1=6 p2=61805 p3=1 obj#=97423 tim=9681236359433
WAIT #140294503426440: nam='db file sequential read' ela= 3600 file#=6 block#=24255 blocks=1 obj#=97098 tim=9681236363117
WAIT #140294503426440: nam='gc current block 2-way' ela= 475 p1=6 p2=62565 p3=1 obj#=97423 tim=9681236363738
WAIT #140294503426440: nam='db file sequential read' ela= 2350 file#=6 block#=27978 blocks=1 obj#=97098 tim=9681236366161
WAIT #140294503426440: nam='gc current block 2-way' ela= 466 p1=6 p2=62500 p3=1 obj#=97423 tim=9681236366800
WAIT #140294503426440: nam='gc current block 2-way' ela= 522 p1=6 p2=26687 p3=1 obj#=97098 tim=9681236367436
WAIT #140294503426440: nam='gc current block 2-way' ela= 368 p1=6 p2=62370 p3=1 obj#=97423 tim=9681236367964
WAIT #140294503426440: nam='db file sequential read' ela= 7787 file#=6 block#=25497 blocks=1 obj#=97098 tim=9681236375898
WAIT #140294503426440: nam='db file sequential read' ela= 6865 file#=6 block#=62364 blocks=1 obj#=97423 tim=9681236382941
WAIT #140294503426440: nam='gc cr grant 2-way' ela= 391 p1=6 p2=23586 p3=1 obj#=97098 tim=9681236383506
WAIT #140294503426440: nam='db file sequential read' ela= 6647 file#=6 block#=23586 blocks=1 obj#=97098 tim=9681236390204
WAIT #140294503426440: nam='gc current block 2-way' ela= 418 p1=6 p2=61633 p3=1 obj#=97423 tim=9681236390785
WAIT #140294503426440: nam='gc current block 2-way' ela= 468 p1=14 p2=654910 p3=1 obj#=97098 tim=9681236391380
WAIT #140294503426440: nam='db file sequential read'  ela= 12065  file#=6 block#=23033 blocks=1 obj#=97098 tim=9681236403545
WAIT #140294503426440: nam='db file sequential read' ela= 6197 file#=6 block#=62345 blocks=1 obj#=97423 tim=9681236409840
WAIT #140294503426440: nam='db file sequential read' ela= 8822 file#=6 block#=17711 blocks=1 obj#=97098 tim=9681236418732
WAIT #140294503426440: nam='db file sequential read' ela= 6011 file#=6 block#=61592 blocks=1 obj#=97423 tim=9681236424856
WAIT #140294503426440: nam='db file sequential read' ela= 2822 file#=6 block#=22295 blocks=1 obj#=97098 tim=9681236427775
WAIT #140294503426440: nam='db file sequential read' ela= 1513 file#=6 block#=20873 blocks=1 obj#=97098 tim=9681236429383
WAIT #140294503426440: nam='db file sequential read' ela= 4742 file#=6 block#=22869 blocks=1 obj#=97098 tim=9681236434232
WAIT #140294503426440: nam='db file sequential read' ela= 1293 file#=6 block#=23772 blocks=1 obj#=97098 tim=9681236435635
WAIT #140294503426440: nam='db file sequential read' ela= 2486 file#=6 block#=905923 blocks=1 obj#=97098 tim=9681236438232
WAIT #140294503426440: nam='db file sequential read' ela= 3405 file#=6 block#=3194014 blocks=1 obj#=97423 tim=9681236441728
WAIT #140294503426440: nam='db file sequential read' ela= 5175 file#=6 block#=20130 blocks=1 obj#=97098 tim=9681236446978


Это укладывается в допустимую погрешность или так не должно быть? Сервер был почти пустой в это время (в БД активных пользовательских сессий не было)
...
Рейтинг: 0 / 0
19.07.2017, 09:00
| Ответить | Цитировать | Написать  
11 сообщений из 11, страница 1 из 1
Форумы / Oracle [игнор отключен] [закрыт для гостей] / Помогите найти, на что уходит время при выполнении запроса
Найденые пользователи ...
Разблокировать пользователей ...
Читали тему (0):
Читали форум (0):
Пользователи онлайн (0):
Польз. соглашение   Полит. конфиден.  
NoSQL.ru       Кролег: Проекты, Новости, Чат       РЕД ФОРУМ       Фотоальбом: Участники, Встречи
Закрыть
start [/forum/topic.php?fid=52&msg=39491310&tid=1885580]:
 0ms
get settings:
 8ms
get forum list:
 9ms
check forum access:
 2ms
check topic access:
 2ms
track hit:
 155ms
get topic data:
 10ms
get forum data:
 2ms
get page messages:
 52ms
get tp. blocked users:
 1ms
others: 205ms
total:  446ms
созд. / загр.: 446ms
x
x
Закрыть


Просмотр
0 / 0
Close
Debug Console [Select Text]