Indagini sul comportamento di Oracle RAC

Quasi un mese fa ho scritto un post intitolato “Problemi di interconnessione con RAC“. Il fatto di avere un valore stranamente alto nella statistica “packet reassembles failed” visualizzato con il comando neststat -s faceva pensare a qualche problema harware.  In realtà dopo alcuni reboot delle macchine si sono notati comportamenti variabili, che, insieme alla mancanza di altri indizi di anomalie hardware,  mi portano a pensare non si tratti di problemi della singola macchina; al massimo può essere un problema dello switch al quale le interfacce di interconnessione sono attaccate.

Il fatto è che all’aumentare dell’attività di modifica e conteporanea interrogazione massiva dei dati, le prestazioni del RAC  peggioravano, per cui è capitato che una query, un full scan su una tabella non enorme, che in condizioni normali ci impiega tra uno e dieci secondi, ci mettesse anche dieci minuti.

Ho fatto un piccolo test, l’impianto ricordo è un RAC 10.2.0.4 a 4 nodi, con ASM su Linux x86-64. Ho lanciato in sequenza sui quattro nodi una coppia di query che fanno un full scan su due tabelle da circa 80000 blocchi (da 8kB), ad ogni giro ho lanciato questa query:

select TO_CHAR(INST_ID,'9') INST_ID,
TO_CHAR(executions,'999','NLS_NUMERIC_CHARACTERS = '',.''') EXECS,
TO_CHAR(buffer_gets,'99999999','NLS_NUMERIC_CHARACTERS = '',.''') BG,
TO_CHAR(disk_reads,'99999999','NLS_NUMERIC_CHARACTERS = '',.''') DR,
TO_CHAR(CLUSTER_WAIT_TIME/1000000,'99999D99','NLS_NUMERIC_CHARACTERS = '',.''') avg_wclu,
TO_CHAR(USER_IO_WAIT_TIME/1000000,'99999D99','NLS_NUMERIC_CHARACTERS = '',.''') avg_wio,
TO_CHAR(CPU_TIME/1000000,'9999999D99','NLS_NUMERIC_CHARACTERS = '',.''') avg_CPU,
TO_CHAR(elapsed_time/1000000,'999999D99','NLS_NUMERIC_CHARACTERS = '',.''') ELAPs ,
TO_CHAR((CPU_TIME+USER_IO_WAIT_TIME+CLUSTER_WAIT_TIME)/1000000,'99999D99','NLS_NUMERIC_CHARACTERS = '',.''') SUMw,
TO_CHAR((CLUSTER_WAIT_TIME/1000/(BUFFER_GETS-DISK_READS)),'999999D99','NLS_NUMERIC_CHARACTERS = '',.''') "AVGWX_GSBLOCK (ms)",
TO_CHAR((user_io_WAIT_TIME/1000/(DISK_READS)),'999999D99','NLS_NUMERIC_CHARACTERS = '',.''') "AVGW_X_IOBLOCK (ms)"
from Gv$sql where sql_text like'select /* CRISTIAN_TEST%' ORDER BY INST_ID,SQL_TEXT;

L’intento era quello di verificare “l’efficenza” della Global Cache, e l’affermazione secondo cui reperire un blocco dalla cache di un’altro nodo dovrebbe essere più efficente e veloce che reperirlo da disco, il tutto utilizzando le interessanti informazioni fornite dall GV$SQL

Ecco il risultato di questa query dopo circa quattro giri:

INST_ID EXECS BG        DR        AVG_WCLU  AVG_WIO   AVG_CPU     ELAPS      SUMW      AVGWX_GSBLOCK (ms) AVGW_X_IOBLOCK (ms)
------- ----- --------- --------- --------- --------- ----------- ---------- --------- ------------------ -------------------
 1         5     447250    238414    331,58     22,48       17,53     365,27    371,59       1,59                ,09
 1         4     300141     59236     13,92      5,39        9,21      25,30     28,52        ,06                ,09
 2         4     357740    202052     12,82     20,75       12,88      41,83     46,46        ,08                ,10
 2         4     300161      4386     56,95      1,78       11,17      66,46     69,90        ,19                ,41
 3         4     357708    220675     24,39     21,01       14,31      54,25     59,71        ,18                ,10
 3         4     300142       771     31,37       ,65        8,81      37,34     40,83        ,10                ,84
 4         4     357700    237445     32,37     18,48       14,21      60,23     65,05        ,27                ,08
 4         4     300324      1237     60,16      1,44       12,43      68,08     74,04        ,20               1,17

E’ accaduto che al terzo lancio di una delle due query sul primo dei due nodi, l’esecuzione è durata quasi dieci minuti contro una media compresa tra cinque e quindici secondi. La “causa” di ciò è evidenziata nella tabella sopra, ovvero in un elevato tempo di attesa sui blocchi tramite GCS.  Ho fatto delle approssimazioni nell’analisi e nella costruzione di questa tabella; ho preso i buffer gets come numero totale di blocchi necessari,  i “disk reads” come numero di blocchi non presenti in cache e letti su disco, la differenza l’ho considerata come blocchi recuperati dalla “Global Cache”. Quest’ultima può sembrare ed essere veramente una approssimazione forte, ma i risultati secondo me dimostrano comunque ciò che volevo vedere. Una parte dei blocchi probabilmente è gia presente nella cache locale, ma il tempo per accedere a questi dovrebbe essere trascurabile. Ho fatto dei controlli incrociati sulle V$SESSION_EVENT e V$SESSTAT e penso che le approssimazioni siano accettabili.

Il punto è che un caso anomalo (su cinque esecuzioni) ha portato sulla prima istanza, per la prima delle due query ad avere un tempo medio di attesa su un blocco (“gc cr multi block request”) molto alto. Quello è il caso eclattante e grave, ma nella stessa tabella vi sono altre due righe in cui risulta un tempo medio di attesa sul blocco via GCS  (AVGWX_GSBLOCK (ms)) più alto di quello di attesa sul blocco da disco (AVGW_X_IOBLOCK (ms))

Questa mia indagine è nata dalla stessa analisi fatta su una serie di query lanciate dall’applicativo, infatti li il problema sembra analogo:

INST_ID EXECS BG        DR        AVG_WCLU  AVG_WIO   AVG_CPU     ELAPS      SUMW      AVGWX_GSBLOCK (ms) AVGW_X_IOBLOCK (ms)
------- ----- --------- --------- --------- --------- ----------- ---------- --------- ------------------ -------------------
 2        41    3585914   1987821    328,85    173,20      124,13     586,50    626,17        ,21                ,09
 2        41    3585734   1937563    211,74    165,57      104,53     454,35    481,85        ,13                ,09
 3       206   17995303   3855412   1000,00    329,20      515,54    1673,86   1844,74        ,07                ,09
 3        45    3878755   1640542    680,64    158,28      134,38     930,06    973,29        ,30                ,10
 3        38    3291803   1322199    587,86    135,06      106,99     799,74    829,91        ,30                ,10
 3       185   16172079   3765261    884,73    282,55      406,00    1425,50   1573,28        ,07                ,08

Si tratta di un piccolo campione. Mancano le istanze 1 e 4 che in questo momento, tramite “SERVICES” sono state escluse in quanto il sistema non è a pieno reggime e con due istanze si comporta molto meglio che con tutte e quattro. In ogni caso nel campione si vede che quasi sempre sembra sia più veloce acquisire i blocchi da disco che non dalla cache di altre istanze.

Se non è un problema hardware, o un bug ed il normale comportamento di RAC è un grosso problema.

Nella mia indagine potrebbe esserci qualche buco, sono gradite eventuali segnalazioni, sta di fatto che il comportamento anomalo, che ha pesato sull’utente finale è una certezza