Le (dis)avventure con SMON

I problemi di performance sono difficili da digerire, sia da uno sviluppatore che da un DBA. Il fatto è che per far funzionare le cose nel modo corretto, occorre sapere come funziona Oracle. Il che, il più delle volte è impossibile. Non è fattibile, almeno dal mio punto di vista, essere in grado di seguire l'evoluzione del database dopo ogni nuovo rilascio. Ammeno che non si abbia già una discreta conoscenza del funzionamento delle release precedenti.
Questo ovviamente non vuol dire ci si debba arrendere difronte ad un nuovo problema o che non si possa essere DBA. Sto dicendo piuttosto che il fatto di non sapere una cosa non vuol dire che quella cosa non si possa fare o che non esista.
Facciamo un esempio. Se desidero tracciare l'insert fallita a causa di un errore, il DBA potrebbe dire che l'unico modo è quello di tracciare la cosa applicativamente. Questo ovviamente è falso, o almeno lo è a partire dalla versione 10g, in cui è stato introdotta l'opzione LOG ERRORS nello statement di INSERT. Di seguito riporto l'esempio tratto direttamente dal manuale 10gR2.

Inserting Into a Table with Error Logging: Example The following statements create a raises table in the sample schema hr, create an error logging table using the DBMS_ERRLOG package, and populate the raises table with data from the employees table. One of the inserts violates the check constraint on raises, and that row can be seen in errlog. If more than ten errors had occurred, the statement would have aborted, rolling back any insertions made:


CREATE TABLE raises (emp_id NUMBER, sal NUMBER
  CONSTRAINT check_sal CHECK(sal > 8000));

EXECUTE DBMS_ERRLOG.CREATE_ERROR_LOG('raises', 'errlog');

INSERT INTO raises
  SELECT employee_id, salary*1.1 FROM employees
  WHERE commission_pct > .2
  LOG ERRORS INTO errlog ('my_bad') REJECT LIMIT 10;

SELECT ORA_ERR_MESG$, ORA_ERR_TAG$, emp_id, sal FROM errlog;

ORA_ERR_MESG$ ORA_ERR_TAG$ EMP_ID SAL
--------------------------- -------------------- ------ -------
ORA-02290: check constraint my_bad 161 7700
(HR.SYS_C004266) violated

Dopo questa piccola introduzione, vediamo cosa ha combinato il nostro DBA.

Da qualche giorno, un job che esegue una procedura di un package, impiega moltissimo tempo per fineire il lavoro. Questo comporta che processi esterni che devono lavorare sulle stesse righe, restano bloccati in attesa della sua conclusione.
Chiamaiamo allora il nostro, e gli raccontiamo la storia. Lui prima suggerisce di fare un pò di manutenzione sulla tabella perché è troppo grande (1,5GB) e poi di ricostruire gli indici (Tom Kyte nel suo post Index Rebuild and analyze spiega che in realtà non serve ricostruire gli indici). Comunque, seguiamo il suggerimento e prima eseguiamo il MOVE della tabella e poi procediamo con il REBUILD degli indici. Ovviamente il giorno dopo nulla è cambiato e così lo risentiamo nuovamente quando il problema si ripresenta.
Gli suggeriamo allora di vedere come mai il nostro processo esterno è bloccato. Per semplicità, simuliamo una conversazione telefonica.

Noi: <Ciao DBA, il mio processo si è bloccato nuovamente. Puoi vedere come mai? Quel job che fa gli update sta ancora girando.>
DBA: <Si, un attimo......dunque, io vedo che il job sta ancora lavorando ed ha coinvolto 500.000 blocchi della tabella>

Ma che informazione è? Io volgio sapere perché il mio processo è fermo.

Noi: <Capisco. Facciamo così, fa il kill del job in modo che io possa modificare la procedura: faccio l'update su un sottinsieme di righe.>
DBA: <...ok ho fatto>
Noi: <Bene, adesso modifico gli UPDATE presenti....>
DBA: <...ti consiglio di mettere prima numeri bassi e poi di procedere per gradi. Poi lanciala manualmente.>

Però...bella idea.

Noi: <...fatto. adesso la lancio da TOAD......beh è rimasta appesa. Puoi controllare chi mi sta bloccando?>
DBA: <Io non vedo nulla>
Noi: <Hai controllato la V$SESSION_WAIT, per vedere come mai è bloccata?>
DBA: <enqueue, WAITING>

Traduzione: vuol dire che l'evento di attesa è "enqueue" e che lo stato è WAITING: la sessione sta aspettando su un enqueue.

Noi: <Scusa ma hai controllato sulla V$LOCK? Lì c'è scritto sicuramente chi mi sta bloccando>
DBA: <No>

AAAAAAAAAAAGH

DBA: <Quì vedo che la tua sessione ha due lock uno TX e l'altro TM, però non ricordo cosa significano>

Ma non basta cercare su metalink? TX e TM

Noi: <Dunque se fai una ricerca su metalink della parola enqueue, dovresti ottenre un documento in cui ti viene fornito lo statement di SELECT che ti consente di risalire alla sessione che mi sta bloccando>
DBA: <Aspetta...ho trovato il documento...beh vedo che ti sta bloccando il SID 5: è un processo di background>

Che genio: i processi con SID basso (fino a 9, 10. Dipende dalla versione dell'RDBMS) sono sempre di Oracle.

Noi: <E non puoi dirmi che processo è? Magari è un processo che sta facendo il rollback della sessione precedente, visto che abbiamo fatto il kill di un job che aveva aggiornato tutti quei blocchi>
DBA: <No! Non sta facendo rollback perchè io non vedo la sessione del job>

:-(

Noi: <Va bene, ma almeno mi puoi dire che processo è?>
DBA: <Guarda, sta facendo una cosa che per me è senza significato: SELECT...FROM FET$ WHERE TS#=...>

:-() Senza senso? Ma sta scherzando? Davvero no senza senso per lui? SIGH. Voglio piangere.

DBA: <La colonna username della V$SESSION è vuota, perché il processo è un processo in background>

Prendere un'altra colonna no, vero?

GUTAPROD(SYS)> select username,program from v$session where sid=5;

USERNAME PROGRAM
------------------------------ --------------------------------------------
oracle@antares (SMON)

Noi: <Allora aiutati con la V$PROCESS, da lì riesci a prendere sicuramente il nome del processo>
DBA: <Ah ecco. Il processo è SMON>

A si?

Noi: <Bhe è molto strano. Questo vuol dire che SMON sta cercando spazio libero: la FET$ è la tabella del dizionario dati dove Oracle tiene traccia degli extent liberi per i tablespace DICTIONARY MANAGED. Perché non cerchiamo di capire cosa sta facendo esattamente SMON? Magari lo metti sotto trace così sappiamo come mai perde tempo.>
DBA: <E' inutile. SMON è un processo in background. Tutte le analisi successive sono inutili. Dobbiamo aspettare che concluda il suo lavoro. Invece credo che si debba procedere in altro modo. Devi lanciare l'UPDATE (quelli presenti nella procedura) a mano. Vediamo che succede. E' inutile indagare dal basso verso l'alto: bisogna procedere per gradi.>

Alto? Basso? Gradi? Bisogna aspettare che SMON finisca il lavoro? E' inutile continuare l'indagine?????????

Bene. E' stata allucinante, ma questa conversazione permette di fare alcune riflessioni. Innanzitutto mai dire che una cosa è senza senso. A parte che si rischia di fare una brutta figura, la cosa comunque denota una scarsissima propensione all'analisi del problema: se c'è davvero qualcosa che uno non sa, ci si documenta e la si approfondisce. Quando ad un passo dal riuscire a comprendere che stava succededo, il DBA ha mollato, abbiamo perso un occasione d'oro. E' come aver sbagliato un gol a porta vuota. Perché non proseguire? Il sapere che la procedura di UPDATE ha iniziato una chiamata ricorsiva sul dizionario dati (FET$) per la ricerca di spazio libero, era quasi un punto di arrivo. C'è un collo di bottiglia? Conviene trasformare il tablespace in LOCALLY MANAGED? E' davvero un problema della procedura? Tutte queste domande ed altre, potevano avere una risposta immediata.

Comunque, proseguiamo la nostra storia.

Il giorno dopo, ci rimettiamo al lavoro per capire cosa c'è che non andava. Sfruttando i suggerimenti del DBA, lanciamo manualmente i due UPDATE presenti nella procedura. Cominciamo con la prima, mettendo una where condition con ROWNUM<20. Tempo impiegato 5 secondi. Strano!!! Il risultato atteso era ovviamente quello di un blocco dello statement. Proviamo allora con il secondo UPDATE e sempre con una where condition di ROWNUM<20. Ancora 5 secondi. Davvero strano!!! Vuoi vedere che il DBA aveva raggione? Vuoi vedere che il problema è della procedura nel suo complesso? Rieseguiamo il primo UPDATE ma con un ROWNUM<200. Tempo impiegato 30 secondi. Gulp!!! E poi proviamo con il secondo UPDATE. Ancora 30 secondi. Impossibile!!!! Non c'è nessuna spiegazione logica a questo comportamente, se non che, come detto, la procedura originale abbia davvero qualche problema. Il DBA è un grande. Ultima prova. Eseguiamo il primo ed secondo UPDATE con ROWNUM<2000. Tempo impiegato circa 2 minuti. Noooooo!!!! Panico totale. Impossibile. Perché la procedura che contiene 2 UPDATE consecutivi si pianta, mentre i due statement eseguiti singolarmente funzionano?
Unica soluzione possibile è che le conclusioni a cui eravamo giunti erano palesemente sbagliate: nessun problema con SMON; nessun problema con chiamate ricorsive al dizionario dati. Con la coda tra le gambte allora eseguiamo la procedura originale (quella schedulata con il job), sapendo che si sarebbe bloccata. Modifichiamo quindi gli statement all'interno per iniziare la sessione di test come fatto precedentemente: mettiamo come where condition il ROWNUM<20.

Lanciamo la procedura e......tempo impiegato circa 1 minuto.

Ora, va bene che le leggi di Murphy hanno una loro applicazione pressocché universale, ma in questo caso siamo oltre: forse abbiamo trovato noi stessi un qualche crollario.

Rieseguiamo la procedura manualmente, modificando le condizioni di where condition e scopriamo che, non solo non si blocca, ma che i tempi sono proporzionali a qulli misurati precedentemente. Cosa è successo. Non lo sapremo mai. Che rabbia. Se solo avessimo continuato l'analisi il giorno prima.....Poiché non sappiamo cosa sia accaduto, non ci resta che inviare una e-mail agli interessati (DBA compreso) affermando che i problemi riscontrati durante tutta la settimana, sono scomparsi magicamente.

Ma.....colpo di scena. Dopo la nosta e-mail, il DBA, risponde dicendo che:

Ciao, il problema era il seguente: sul tbs TABLESPACEALTROSCHEMA si erano creati una ventina di segmenti temporanei ciascuno di 250M. Normalmente i segmenti temporanei vengono creati per oparazioini quali move table o rebuild index, e vengono rilasciati quando l'operazioine si è conclusa. Questo compito spetta al processo in Background SMON. Tale processo quindi era impegnato totalmente per cercare di smaltire questi segmenti. Il risultato di tutto ciò è che anche il job 1234, che non riguarda lo schema ALTROSCHEMA ma lo schema SCHEMACONPROBLEMIJOB, veniva lockato dal processo SMON.
Questa notte ho droppato tutti i segmenti temporanei di ALTROSCHEMA, prima di tutto liberando 4G di spazio sul suo TBS, e poi permettendo al SMON di lavorare correttamente.

Riassumendo la causa di tutto ciò è stata la generazione dei segmenti temporanei su ALTROSCHEMA senza il conseguente loro rilascio. Per far si che non si generi un altra volta il problema bisognerebbe innanzitutto non killare continuamente forzatamente i processi e alleggerire tutte le procedure dove è possibile.

In ogni caso se si dovesse ripresentare il problema sappiamo come affrontarlo.

Che cooooooooosaaaaaaaaaaaaa? Segmenti temporanei????? SMON?????? Spazio libero (lui lo chiama smaltire)???????????? Ma.....ma.....ma....

Va bhé. Come non detto. (Giusto una precisazine. I segmenti "temporanei", creati a seguito di un REBUILD INDEX o MOVE TABLE, restano tali finché l'operazione non si conclude. Se termina con successo, Oracle modifica tale segmento temporaneo dandogli il nome corretto e rendendolo non TEMPORARY (di tipo TABLE per esempio), e poi cancella il vecchio).
Il fatto però è che non è proprio chiaro cosa sia successo. Fondamentalemente manca la correlazione tra i due schemi: ALTROSCHEMA e SCHEMACONPROBLEMIJOB. Perché "sul tbs TABLESPACEALTROSCHEMA si erano creati una ventina di segmenti temporanei ciascuno di 250M". Inoltre visto che "bisognerebbe innanzitutto non killare continuamente forzatamente i processi", e visto che siamo noi stessi a gestire ALTROSCHEMA, sapendo che non c'è mai stato un kill, come spiegare l'accaduto?
In ogni caso, tutto ciò è mooooolto interessante. Come ha fatto il DBA a "droppare tutti i segmenti temporanei di ALTROSCHEMA"? Urge una ricerca immediata su Metalink. Così, cercando cercando, troviamo molte cose interessanti.
Ma molto importante, per il caso in esame, sono i documenti 61997.1 e 47400.1. Entrambi parlano di SMON. Il primo descrive come lavora, mentre nel secondo troviamo la soluzione al nostro problema.
In sostanza, forziamo SMON ad eseguire la pulizia dei segmenti temporanei, impostando l'evento DROP_SEGMENTS al valore TS#+1, dove TS# è il numero del tablespace a cui siamo interessati, prelevato dalla V$TABLESPACE. La sintassi è la seguente:

select ts# from v$tablespace where name = '<nomedeltablespace>';

alter session set events 'immediate trace name DROP_SEGMENTS level TS#+1';

Beh, non c'è che dire, davvero notevole, e bravo il DBA pure a trovare la documentazione e ad eseguire le operazioni necessarie. Un piccolo dubbio però mi viene. Perché si è messo a cercare questi documenti visto che era così convito che non potevamo far nulla con SMON? Eppure non solo lo avevamo avvisato, ma aveva addirittura letto lo statement ricorsivo che SMON stava facendo sul dizionario dati. Mi sa che non aveva la minima idea di ciò che stava succedendo (<...guarda, sta facendo una cosa che per me è senza significato...>) al db, e pur di non volerlo ammettere ha deciso di non prosegure l'indagine.
Questo è il classico esempio di come un'informazione errata possa essere dannosa. Immaginate cosa fosse successo nel caso di un fault e si doveva procedere con un recovery. Se il DBA non è competente, ha informazioni sbagliate e soprattutto non accetta suggerimenti, la cosa potrebbe portare ad un disastro.
Comunque, visto che non siamo del tutto soddisfatti, non avendo tutte le risposte che ci occorrono, scriviamo al nostro DBA:

DBA,
puoi gentilmente spiegarmi in dettaglio come il processo SMON bloccava sia ALTROSCHEMA che il job 1234 di SCHEMACONPROBLEMIJOB? Puoi illustrarmi in dettaglio, cosa hai fatto per risolvere il problema?
Dall’analisi fatta ieri sera, ti ricordo infatti che eravamo arrivati alla conclusione che il job di SCHEMACONPROBLEMIJOB, che aveva dato problemi tutta la settimana, era bloccato da SMON. Tuttavia in modo categorigo, avevi detto che non era necessario indagare oltre, in quanto essedo un processo di Oracle, dovevamo semplicemente attendere che SMON concludesse il suo lavoro, e non hai voluto proseguire oltre neanche dopo una mia certa insistenza.
Inoltre, perché non mi hai avvisato? Potevo tranquillamente risparmiarmi una mezza giornata di lavoro nel cercare di capire come mai SCHEMACONPROBLEMIJOB avevano ripreso a funzionare inspiegabilmente.

Ovviamente a completamento della torta, manca solo la ciliegina. Ecco come la sua risposta:

Ho seguito le indicazioni di questa nota "61997.1". In modo particolare la "47400.1".

Ah sì? Quest'è? Tutte le domande che avevo fatto si riducono in due sole note su metalink? Nessuna spiegazione? Nessun chiarimento? Nessun confronto? Però. Complimenti.

Due giorni dopo, comunque, sentiamo il nostro e, cerchiamo di capire cosa sia successo. Secondo lui, il tempo di lavoro di SMON era tale da bloccare l'attività del job in questione e di conseguenza la procedura che lanciavamo. Da un ulteriore controllo poi, risulta che il tablespace in questione è LOCALLY MANAGED.
Ma perché il job veniva bloccato da SMON? Sappiamo che il job non faceva altro che eseguire degli UPDATE, quindi ci chiediamo, che relazione intercorre tra i due? Gran belle domande. Peccato che non troveranno mai risposta.

Tuttavia un pò di curiosità ci è venuta. Nonostante il tablespace fosse LOCALLY MANAGED, SMON eseguiva statement sul dizionario dati per liberare spazio? Eppure eravamo conviti che con tali tablespace, tali chiamate ricorsive non erano più necessarie. Come mai allora vediamo ancora strane chiamate SQL fatte dal System Monitor?

Dopo un piccola ricerca e qualche test, ecco cosa sono riuscito a trovare.

Cosa abbiamo imparato da questa storia? Che è fondamentale ascoltare le opinioni di altre persone, valutare i risultati ottenuti, essere critici su quanto osservato, ma soprattutto mettere sempre in discussione le proprie convinzioni. Potrebbero essere valide oggi, ma del tutto superate ed inadeguate domani.

Alla prossima.