Мар. 272013
 

This post is also available in: English

Това ми отне доста време да го дебъгна. Първо, самия процес върви за час-час и половина когато е ОК и за 4-5 часа когато е зле. Второ, това е част от ETL процес, който работи през нощта – трудно се наблюдава „на живо“. Трето, един път тръгва наред, следващия се скапва. Но най-гадното е, че като се опитам да го reproduce-на, винаги си върви както трябва. А накрая се оказа и че повредата не е в този statement, просто той си го отнася заради други грешки. Но да преминем към фактите.

Ден 1
Оплакването е, че една от стъпките на нощния ETL процес е минала бавно. Този процес се движи от един сравнително сложен job chain от трийсетина стъпки, които ту вървят в паралел, ту се изчакват, абе корава работа. За щастие е много добре инструментиран и веднага се вижда кое кога е тръгнало, колко неща са вървяли по това време и така.

Разбира се, никой нищо не е пипал – последната промяна в ETL-а е от сряда, а проблема се проявява в събота (и в неделя, и в понеделник…). В такива моменти много добра подсказка може да даде графиката за изпълнение на заявката от OEM Cloud Cotntrol. Ето какво се вижда за един „бърз“ и един „бавен“ ден:

screenshot-1.

Симтомите са ясни – само една сесия работи по въпроса, няма паралелно изпълнение. Нека да видим плана от последното изпълнение (предната нощ):

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                               | Name                     | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     | Pstart| Pstop |    TQ  |IN-OUT| PQ Distrib |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | INSERT STATEMENT                        |                          |       |       |       |    11M(100)|          |       |       |        |      |            |
|   1 |  LOAD AS SELECT                         |                          |       |       |       |            |          |       |       |        |      |            |
|   2 |   PX COORDINATOR                        |                          |       |       |       |            |          |       |       |        |      |            |
|   3 |    PX SEND QC (RANDOM)                  | :TQ10012                 |   445M|  1737G|       |    11M  (1)| 31:41:37 |       |       |  Q1,12 | P->S | QC (RAND)  |
|   4 |     HASH JOIN OUTER BUFFERED            |                          |   445M|  1737G|   779M|    11M  (1)| 31:41:37 |       |       |  Q1,12 | PCWP |            |
|   5 |      PX RECEIVE                         |                          |    33M|  2738M|       |   104K  (2)| 00:17:41 |       |       |  Q1,12 | PCWP |            |
|   6 |       PX SEND HASH                      | :TQ10010                 |    33M|  2738M|       |   104K  (2)| 00:17:41 |       |       |  Q1,10 | P->P | HASH       |
|   7 |        VIEW                             |                          |    33M|  2738M|       |   104K  (2)| 00:17:41 |       |       |  Q1,10 | PCWP |            |
|   8 |         WINDOW SORT                     |                          |    33M|  1636M|  1896M|   104K  (2)| 00:17:41 |       |       |  Q1,10 | PCWP |            |
|   9 |          HASH JOIN RIGHT OUTER          |                          |    33M|  1636M|       |  5799  (17)| 00:00:59 |       |       |  Q1,10 | PCWP |            |
|  10 |           PX RECEIVE                    |                          |    33M|   409M|       |   544  (19)| 00:00:06 |       |       |  Q1,10 | PCWP |            |
|  11 |            PX SEND HASH                 | :TQ10007                 |    33M|   409M|       |   544  (19)| 00:00:06 |       |       |  Q1,07 | P->P | HASH       |
|  12 |             PX BLOCK ITERATOR           |                          |    33M|   409M|       |   544  (19)| 00:00:06 |       |       |  Q1,07 | PCWC |            |
|  13 |              INDEX FAST FULL SCAN       | DIM_xxxx_x_xx_x_xxx_xx_x |    33M|   409M|       |   544  (19)| 00:00:06 |       |       |  Q1,07 | PCWP |            |
|  14 |           PX RECEIVE                    |                          |    33M|  1227M|       |  5092  (15)| 00:00:52 |       |       |  Q1,10 | PCWP |            |
|  15 |            PX SEND HASH                 | :TQ10008                 |    33M|  1227M|       |  5092  (15)| 00:00:52 |       |       |  Q1,08 | P->P | HASH       |
|  16 |             HASH JOIN RIGHT OUTER       |                          |    33M|  1227M|       |  5092  (15)| 00:00:52 |       |       |  Q1,08 | PCWP |            |
|  17 |              PX RECEIVE                 |                          |   152K|  1786K|       |    11   (0)| 00:00:01 |       |       |  Q1,08 | PCWP |            |
|  18 |               PX SEND BROADCAST         | :TQ10000                 |   152K|  1786K|       |    11   (0)| 00:00:01 |       |       |  Q1,00 | P->P | BROADCAST  |
|  19 |                PX BLOCK ITERATOR        |                          |   152K|  1786K|       |    11   (0)| 00:00:01 |       |       |  Q1,00 | PCWC |            |
|  20 |                 TABLE ACCESS FULL       | DIM_xxxxxxxx             |   152K|  1786K|       |    11   (0)| 00:00:01 |       |       |  Q1,00 | PCWP |            |
|  21 |              PX BLOCK ITERATOR          |                          |    33M|   849M|       |  5015  (14)| 00:00:51 |       |       |  Q1,08 | PCWC |            |
|  22 |               TABLE ACCESS FULL         | DIM_xxxxxxxx             |    33M|   849M|       |  5015  (14)| 00:00:51 |       |       |  Q1,08 | PCWP |            |
|  23 |      PX RECEIVE                         |                          |   448M|  1713G|       |  5689K  (1)| 16:03:56 |       |       |  Q1,12 | PCWP |            |
|  24 |       PX SEND HASH                      | :TQ10011                 |   448M|  1713G|       |  5689K  (1)| 16:03:56 |       |       |  Q1,11 | P->P | HASH       |
|  25 |        VIEW                             |                          |   448M|  1713G|       |  5689K  (1)| 16:03:56 |       |       |  Q1,11 | PCWP |            |
|  26 |         SORT UNIQUE                     |                          |   448M|    50G|    54G|  5689K  (1)| 16:03:56 |       |       |  Q1,11 | PCWP |            |
|  27 |          WINDOW SORT                    |                          |   448M|    50G|    54G|  5689K  (1)| 16:03:56 |       |       |  Q1,11 | PCWP |            |
|  28 |           PX RECEIVE                    |                          |   448M|    50G|       |   120K (16)| 00:20:21 |       |       |  Q1,11 | PCWP |            |
|  29 |            PX SEND HASH                 | :TQ10009                 |   448M|    50G|       |   120K (16)| 00:20:21 |       |       |  Q1,09 | P->P | HASH       |
|  30 |             HASH JOIN                   |                          |   448M|    50G|       |   120K (16)| 00:20:21 |       |       |  Q1,09 | PCWP |            |
|  31 |              PX RECEIVE                 |                          |    21 |   126 |       |     2   (0)| 00:00:01 |       |       |  Q1,09 | PCWP |            |
|  32 |               PX SEND BROADCAST         | :TQ10001                 |    21 |   126 |       |     2   (0)| 00:00:01 |       |       |  Q1,01 | P->P | BROADCAST  |
|  33 |                PX BLOCK ITERATOR        |                          |    21 |   126 |       |     2   (0)| 00:00:01 |       |       |  Q1,01 | PCWC |            |
|  34 |                 TABLE ACCESS FULL       | DIM_xxx_xxx              |    21 |   126 |       |     2   (0)| 00:00:01 |       |       |  Q1,01 | PCWP |            |
|  35 |              HASH JOIN                  |                          |   448M|    47G|       |   119K (16)| 00:20:12 |       |       |  Q1,09 | PCWP |            |
|  36 |               PX RECEIVE                |                          |     8 |   128 |       |     2   (0)| 00:00:01 |       |       |  Q1,09 | PCWP |            |
|  37 |                PX SEND BROADCAST        | :TQ10002                 |     8 |   128 |       |     2   (0)| 00:00:01 |       |       |  Q1,02 | P->P | BROADCAST  |
|  38 |                 PX BLOCK ITERATOR       |                          |     8 |   128 |       |     2   (0)| 00:00:01 |       |       |  Q1,02 | PCWC |            |
|  39 |                  TABLE ACCESS FULL      | DIM_xxx_xxxxxx           |     8 |   128 |       |     2   (0)| 00:00:01 |       |       |  Q1,02 | PCWP |            |
|  40 |               HASH JOIN                 |                          |   448M|    40G|       |   118K (15)| 00:20:03 |       |       |  Q1,09 | PCWP |            |
|  41 |                PX RECEIVE               |                          |   135 |  2160 |       |     2   (0)| 00:00:01 |       |       |  Q1,09 | PCWP |            |
|  42 |                 PX SEND BROADCAST       | :TQ10003                 |   135 |  2160 |       |     2   (0)| 00:00:01 |       |       |  Q1,03 | P->P | BROADCAST  |
|  43 |                  PX BLOCK ITERATOR      |                          |   135 |  2160 |       |     2   (0)| 00:00:01 |       |       |  Q1,03 | PCWC |            |
|  44 |                   TABLE ACCESS FULL     | DIM_xxx_xxxx             |   135 |  2160 |       |     2   (0)| 00:00:01 |       |       |  Q1,03 | PCWP |            |
|  45 |                HASH JOIN                |                          |   455M|    34G|       |   117K (15)| 00:19:54 |       |       |  Q1,09 | PCWP |            |
|  46 |                 PX RECEIVE              |                          |    55 |   385 |       |     2   (0)| 00:00:01 |       |       |  Q1,09 | PCWP |            |
|  47 |                  PX SEND BROADCAST      | :TQ10004                 |    55 |   385 |       |     2   (0)| 00:00:01 |       |       |  Q1,04 | P->P | BROADCAST  |
|  48 |                   PX BLOCK ITERATOR     |                          |    55 |   385 |       |     2   (0)| 00:00:01 |       |       |  Q1,04 | PCWC |            |
|  49 |                    TABLE ACCESS FULL    | DIM_xxxxxxxx             |    55 |   385 |       |     2   (0)| 00:00:01 |       |       |  Q1,04 | PCWP |            |
|  50 |                 HASH JOIN               |                          |   463M|    32G|       |   116K (14)| 00:19:45 |       |       |  Q1,09 | PCWP |            |
|  51 |                  PX RECEIVE             |                          |   152K|  1786K|       |    12   (9)| 00:00:01 |       |       |  Q1,09 | PCWP |            |
|  52 |                   PX SEND BROADCAST     | :TQ10005                 |   152K|  1786K|       |    12   (9)| 00:00:01 |       |       |  Q1,05 | P->P | BROADCAST  |
|  53 |                    PX BLOCK ITERATOR    |                          |   152K|  1786K|       |    12   (9)| 00:00:01 |       |       |  Q1,05 | PCWC |            |
|  54 |                     TABLE ACCESS FULL   | DIM_xxxxxxxx             |   152K|  1786K|       |    12   (9)| 00:00:01 |       |       |  Q1,05 | PCWP |            |
|  55 |                  HASH JOIN              |                          |   557M|    32G|       |   115K (13)| 00:19:34 |       |       |  Q1,09 | PCWP |            |
|  56 |                   PX RECEIVE            |                          |     2 |    10 |       |     2   (0)| 00:00:01 |       |       |  Q1,09 | PCWP |            |
|  57 |                    PX SEND BROADCAST    | :TQ10006                 |     2 |    10 |       |     2   (0)| 00:00:01 |       |       |  Q1,06 | P->P | BROADCAST  |
|  58 |                     PX BLOCK ITERATOR   |                          |     2 |    10 |       |     2   (0)| 00:00:01 |       |       |  Q1,06 | PCWC |            |
|  59 |                      TABLE ACCESS FULL  | DIM_xxxxxxxxx            |     2 |    10 |       |     2   (0)| 00:00:01 |       |       |  Q1,06 | PCWP |            |
|  60 |                   PX PARTITION RANGE ALL|                          |   557M|    30G|       |   114K (12)| 00:19:22 |     1 |  4429 |  Q1,09 | PCWC |            |
|  61 |                    TABLE ACCESS FULL    | FACT_xxxxxx              |   557M|    30G|       |   114K (12)| 00:19:22 |     1 |  4429 |  Q1,09 | PCWP |            |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------

А! Шах с пешката. Всичко изглежда доста паралелно. Значи оптимизатора е решил да подходи паралелно към заявката, но execution engine е решил да не се съобрази и да си го изпълни серийно.

Реших да го пусна аз, на ръка, да видим какво ще стане. Ами какво да стане – мина си паралелно, за час и десет минути. Както и да го въртях, ако не му махна хинта parallel, не тръгва серийно! И да, хинта си го има в заявката, която се изпълнява.

Тук искам да вмъкна един от безценните съвети на Jonathan Lewis относно хинта parallel. Този хинт има доста малка тежест. Той не казва на оптимизатора „изпълни това с такъв и такъв паралелизъм“. Не, той само подсказва „абе я погледни тук дали няма да е далавера ако използваме паралелизъм X“. Да, обаче при нас случая не е такъв – оптимизатора съвсем чинно си съставя паралелен план. Така си е записано и във v$sql_plan. Т.е. оптимизатора, който е виновен по default за повечето проблеми, тук не е сгрешил. Съответно стандартните подходи като baselines или sql profiles няма да хванат дикиш.

След като си утрепах няколко часа в опити да го reproduce-на, денят свърши незадоволително. При тестове всичко е наред. Да видим какво ще стане нощес. Нали утрото било по-мъдро от вечерта…

Ден 2

Отново е минало бавно. Това е много дразнещо. Колкото и да се опитвам да го пусна – минава „бързо“ (относително – за час и нещо). А като си тръгне самó, се прецаква. Най-вбесяващото е, че плана в SQL cache отново е паралелен, но изпълнението е серийно.

Може би не ни достигат parallel query slaves? Хайде за довечера ще ги вдигнем от 20 на 32:

alter system set parallel_max_servers=32;

Ден 3

Пак е минало серийно 🙁

Петък е, ден на майстора. Няма да го разбутвам, че да не се налага спешна намеса през уикенда. Все пак върви и така. И приключва преди изгрев слънце.

(следва продължение)

 Posted by at 7:01

Sorry, the comment form is closed at this time.