dans Oracle SQL-Trace: comment regrouper un ensemble d'exécutions SQL lorsque le code n'est pas instrumenté?

Question

J'ai un oracle-10046-aka. SQLTrace fichier similaire à cette structure:

Oracle Release 11.2 
PARSING IN CURSOR #1 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=1 ad='1' sqlid='A' 
insert 
END OF STMT 
PARSING IN CURSOR #2 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=2 ad='2' sqlid='r' 
update next_step 
END OF STMT 
PARSING IN CURSOR #3 len=20 dep=0 uid=7 oct=6 lid=7 tim=2 hv=3 ad='3' sqlid='B' 
update complete 
END OF STMT 
PARSING IN CURSOR #4 len=20 dep=0 uid=7 oct=3 lid=7 tim=2 hv=4 ad='4' sqlid='X' 
select X 
END OF STMT 
PARSING IN CURSOR #5 len=20 dep=0 uid=7 oct=3 lid=7 tim=2 hv=5 ad='5' sqlid='Y' 
select Y 
END OF STMT 

EXEC#1:c=1,e=1,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=100 
EXEC#2:c=2,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=200 
EXEC#3:c=4,e=4,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=300 

EXEC#4:c=5,e=5,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=310 
EXEC#5:c=6,e=6,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=320 

EXEC#1:c=8,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=400 
EXEC#2:c=16,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=416 
EXEC#3:c=32,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=3,tim=448 

J'identifié SQLID « A » comme le début d'une séquence spécifique et SQLID « B » comme il est fin. Entre les deux, il n'y a que sqlid 'r' dans mon exemple, mais ça pourrait être beaucoup plus, même pas les mêmes SQLs ou une suite de SQLs. D'autres SQL comme sqlid 'X' et 'Y' ne sont pas dans ma séquence d'intérêt et devraient être visibles en tant que tels.

Mon outil de prédilection est mrskew du produit Method R Tools de methodr. Comme il peut être étendu avec du code Perl, je suis sûr que cela peut être fait, mais mes compétences Perl sont limitées en tant que ma compréhension des internes de mrskew.

J'apprécie hautement n'importe quel conseil ou aide ici.

Answer 1

En utilisant vos données de test, martin1.trc, j'ai créé le fichier rc, martin1.rc.

--init=' 
    my $xfrm_id; 
    sub xfrm { 
     $xfrm_id = $exec_id if ($sqlid//"") eq "A"; 
     return $xfrm_id//$exec_id; 
    } 
' 
--group='xfrm()' 

J'exécuté mrskew --rc martin1.rc martin1.trc et je me suis cette sortie:

'xfrm()' DURATION  % CALLS  MEAN  MIN  MAX 
--------- -------- ------ ----- -------- -------- -------- 
     25 0.000056 75.7%  3 0.000019 0.000008 0.000032 
     18 0.000018 24.3%  5 0.000004 0.000001 0.000006 
--------- -------- ------ ----- -------- -------- -------- 
TOTAL (2) 0.000074 100.0%  8 0.000009 0.000001 0.000032 

Ce rapport montre deux exécutions de la transaction intéressante. L'exécution de transaction la plus intéressante (le plus grand temps de réponse) a débuté sur la ligne de fichier de trace 25 et a contribué 0,000056 secondes (75,7% du total) sur 3 dbcalls au temps de réponse total. L'autre exécution la plus intéressante a commencé à la ligne 18 et a contribué l'autre 24,3% au total. Nous savons que les lignes 22-23 sont sans intérêt, mais la méthode simple ne les distingue pas. Et c'est pourquoi le rapport indique que l'exécution commençant à la ligne 18 a 5 dbcalls pour 0.000018 secondes au lieu de 3 dbcalls pour 0.000007 secondes.

Si nous changeons de manière significative la fonction de transformation alors nous pouvons gérer la transaction se termine à la déclaration B (même si B est un EXEC suivi par d'autres B dbcalls (par exemple, fetch) Voici martin2.rc:.

--init=' 
    my $sawB; 
    my $xfrm_id; 
    sub xfrm { 
     if (($sqlid//"") eq "A") { 
      $xfrm_id = $exec_id; # global scope maintains state 
     } else { 
      if (($sqlid//"") eq "B") { 
       $sawB = 1; 
      } else { 
       if ($sawB) { 
        $sawB = undef; 
        $xfrm_id = undef; 
       } 
      } 
     } 
     return $xfrm_id//0; 
    } 
' 
--group='xfrm()' 

Conformément à la notion de profil (où le total représente le total pour l'ensemble de l'expérience), j'ai décidé de transformer tous les dbcalls de transaction non intéressants en 0, un numéro de ligne qui ne peut pas apparaître dans un fichier. peut voir comment les transactions intéressantes se classent par rapport à l'ensemble de l'expérience

$ mrskew --rc martin2.rc martin1.trc 

'xfrm()' DURATION  % CALLS  MEAN  MIN  MAX 
--------- -------- ------ ----- -------- -------- -------- 
     25 0.000056 75.7%  3 0.000019 0.000008 0.000032 
     0 0.000011 14.9%  2 0.000005 0.000005 0.000006 
     18 0.000007 9.5%  3 0.000002 0.000001 0.000004 
--------- -------- ------ ----- -------- -------- -------- 
TOTAL (3) 0.000074 100.0%  8 0.000009 0.000001 0.000032 

Si je dupliquer la ligne 20 (qui prend 4 μsecs), la sortie dit ceci:

'xfrm()' DURATION  % CALLS  MEAN  MIN  MAX 
--------- -------- ------ ----- -------- -------- -------- 
     26 0.000056 71.8%  3 0.000019 0.000008 0.000032 
     18 0.000011 14.1%  4 0.000003 0.000001 0.000004 
     0 0.000011 14.1%  2 0.000005 0.000005 0.000006 
--------- -------- ------ ----- -------- -------- -------- 
TOTAL (3) 0.000078 100.0%  9 0.000009 0.000001 0.000032 

Vous pouvez voir que la transaction intéressante à partir de la ligne 18 contribue maintenant 11 μsecs sur 4 dbcalls. Cela semble être un test plus complet confirmant la pertinence de martin2.rc.

Dans le dernier rapport, vous pouvez voir que la transaction intéressante représente 71,8% + 14,1% = 85,9% du temps de réponse total dans le fichier. Si vous modifiez davantage la fonction de transformation (exercice laissé au lecteur), alors vous pouvez agréger en "intéressant" et "pas intéressant" plutôt que ce que j'ai fait, qui était d'ajouter deux pourcentages.