V$SQL_BIND_CAPTURE e TRACE 10046, stesso baco?

giovedì 7 febbraio 2008 alle 07:00 | Pubblicato su Performance Tuning, SQL | 2 commenti

Un paio di giorni fa mi sono trovato ad indagare su un problema giratomi da un programmatore. In pratica succede che sporadicamente un programma segnala un errore ORA-01722 durante una operazione di insert. Il programma è un programma Java, con driver JDBC. La stessa query viene eseguita migliaia di volte al giorno senza problemi.

Essendo il tono della richiesta disperato (nel senso che il programmatore aveva analizzato ogni singolo passo della procedura senza individuare nessuna anomalia) ho voluto provare a riprodurre la cosa. Solo dopo aver messo in piedi un programmino Java di test con gli stessi driver (sui quali ho concentrato i mie sospetti) mi sono reso conto che in realtà l’analisi giratami dal programmatore mancava di un dettaglio: il problema non si ripete sistematicamente; questo nonostante il programmatore mi avesse girato il pezzo di codice del programma dove si genera l’errore e un “test case”, cioè dei dati da usare per una insert. Secondo lui l’insert fatta da un client non dava problemi. Il fatto è che anche l’insert da programma non da problemi e quindi capire cosa non va è difficile.

Di questa cosa (della non sistematicità dell’errore) mi sono reso conto quando mi sono collegato al server di produzione ed ho visto che il programma girava regolarmente. A questo punto ho provato la mossa disperata: attivare il trace della sessione oracle usata dal programma (che per fortuna usa una sola sessione) e attendere. Il trace ha fatto vedere un sacco di informazioni, ma non essendosi ripresentato l’errore in due giorni non ricavato un granch’é se non un paio di grossi file di trace.

Guardando questi trace ho notato una cosa che mi fa arrivare al tema principale (da cui il titolo) di questo post: i valori delle bind variable per i campi di tipo date della insert non comparivano, mentre per le altre si. Mi vi è venuto quindi in mente un post di Don Seiler, in cui pare l’autore spiega come si trovasse ad analizzare un problema non molto diverso dal mio, nel suo caso il problema era con un campo di tipo DATE, nel mio pare essere con un campo di tipo number.

Ho deciso quindi di studiare un po’ questa vista di sistema dal nome V$SQL_BIND_CAPTURE. In realtà sono stato troppo frettoloso nella lettura del manuale e mi è sfuggita una cosa importante. Ho cominciato a fare dei test con degli insert usando bind variables da SQL*Plus, ma non trovavo su tale vista i valori delle bind variables, comparivano tutti i record ma risultava che le bind variables non erano state “catturate”. Per farla breve, solo dopo mi sono reso conto di una frase neppura molto nascosta nella descrizione della vista:

when the bind variable is used in the WHERE or HAVING clauses of the SQL statement.

Facendo io le prove con delle insert secche quindi le mie bind variable non me le trovavo valorizzate. Evidentemente questa vista serve per analisi di performance tuning e quindi hanno rilevanza solo quel tipo di bind variable.

Devo dire che il problema riscontrato da Don Seiler è probabilmente lo stesso che ho incontrato io. Infatti per motivi che non mi sono del tutto chiari, il nostro programma quando valorizza i valori delle bind variable usa il metodo setTimestimestamp, anche per i campi di tipo data e questo fa si (suppongo) che si rientri nel baco segnalato.

Una mia prova pare confermare che lo stesso baco riguardi anche l’output del trace (evento 10046, con bind variables):

desc gabibbo
 Nome                          Nullo?   Tipo
 ----------------------------- -------- --------------------
 A                                      NUMBER
 B                                      VARCHAR2(100 CHAR)
 C                                      DATE
 D                                      TIMESTAMP(6)
declare
n number;
aa number;
ab varchar2(100);
ac date;
ad timestamp;
ee timestamp;
begin
aa :=7;
ab :='cucu';
-- ac := to_date('01-01-2007','dd-mm-yyyy');
ee := to_timestamp('01-01-2007','dd-mm-yyyy');
ad := to_timestamp('02-02-2008','dd-mm-yyyy');
insert into gabibbo (a,b,c,d) values (aa,ab,ee, ad);
end;
/

Nel trace si trova:

PARSING IN CURSOR #5 len=59 dep=1 uid=33 oct=2 lid=33 tim=5658673156 hv=2304601458 ad='2cbb5a14'
INSERT INTO GABIBBO (A,B,C,D) VALUES (:B4 ,:B3 ,:B2 , :B1 )
END OF STMT
PARSE #5:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=2,tim=5658673153
BINDS #5:
kkscoacd
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=07864400  bln=22  avl=02  flg=09
value=7
Bind#1
oacdty=01 mxl=2000(400) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=01 csi=873 siz=2000 off=0
kxsbbbfp=07864430  bln=2000  avl=04  flg=09
value="cucu"
Bind#2
oacdty=180 mxl=11(11) mxlc=00 mal=00 scl=06 pre=00
oacflg=01 fl2=206001 frm=00 csi=06 siz=24 off=0
kxsbbbfp=09e0f9f8  bln=11  avl=07  flg=05
value=
Dump of  memory from 0x09E0F9F8 to 0x09E0F9FF
9E0F9F0                   01016B78 09010101          [xk......]
 Bind#3
  oacdty=180 mxl=11(11) mxlc=00 mal=00 scl=06 pre=00
  oacflg=01 fl2=206001 frm=00 csi=06 siz=0 off=12
  kxsbbbfp=09e0fa04  bln=11  avl=07  flg=01
 value=

Modificando il programmino e mettendo correttamente il tipo nel trace la bind#2 risulta correttamente valorizzato.

2 commenti »

RSS feed for comments on this post. TrackBack URI

  1. È Oracle 10.2.0.3.0? Se sì, pare che abbiano introdotto vari problemi di questo tipo con il patchset nelle variabili di bind, errori intermittenti e problemi di memoria nella shared pool. Anch’io mi sono imbattuto in uno di questi, ma solo una volta, ed è difficile riprodurli per studiarli.

  2. riguardo nello specifico all’errore ORA-01722

    su AskTom ci sono informazioni ed esempi che magari ti possono essere utili

    Ciao
    Alessandro


Lascia un commento

Inserisci i tuoi dati qui sotto o clicca su un'icona per effettuare l'accesso:

Logo WordPress.com

Stai commentando usando il tuo account WordPress.com. Chiudi sessione / Modifica )

Foto Twitter

Stai commentando usando il tuo account Twitter. Chiudi sessione / Modifica )

Foto di Facebook

Stai commentando usando il tuo account Facebook. Chiudi sessione / Modifica )

Google+ photo

Stai commentando usando il tuo account Google+. Chiudi sessione / Modifica )

Connessione a %s...

Crea un sito o un blog gratuitamente presso WordPress.com.
Entries e commenti feeds.

%d blogger cliccano Mi Piace per questo: