This post is also available in: English
Това ми отне доста време да го дебъгна. Първо, самия процес върви за час-час и половина когато е ОК и за 4-5 часа когато е зле. Второ, това е част от ETL процес, който работи през нощта – трудно се наблюдава „на живо“. Трето, един път тръгва наред, следващия се скапва. Но най-гадното е, че като се опитам да го reproduce-на, винаги си върви както трябва. А накрая се оказа и че повредата не е в този statement, просто той си го отнася заради други грешки. Но да преминем към фактите.
Ден 1
Оплакването е, че една от стъпките на нощния ETL процес е минала бавно. Този процес се движи от един сравнително сложен job chain от трийсетина стъпки, които ту вървят в паралел, ту се изчакват, абе корава работа. За щастие е много добре инструментиран и веднага се вижда кое кога е тръгнало, колко неща са вървяли по това време и така.
Разбира се, никой нищо не е пипал – последната промяна в ETL-а е от сряда, а проблема се проявява в събота (и в неделя, и в понеделник…). В такива моменти много добра подсказка може да даде графиката за изпълнение на заявката от OEM Cloud Cotntrol. Ето какво се вижда за един „бърз“ и един „бавен“ ден:
.
Симтомите са ясни – само една сесия работи по въпроса, няма паралелно изпълнение. Нека да видим плана от последното изпълнение (предната нощ):
------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | 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
Пак е минало серийно 🙁
Петък е, ден на майстора. Няма да го разбутвам, че да не се налага спешна намеса през уикенда. Все пак върви и така. И приключва преди изгрев слънце.
(следва продължение)
Sorry, the comment form is closed at this time.