Oracle Live

02/04/2016

Parsea 10046 para 11g

Filed under: Debugger,Scripts — mogukiller @ 1:28 am
Tags:

Todos nos hemos encontrado con el problema de saber que esta haciendo una sesion y donde esta invirtiendo el tiempo. Con las vistas de base de datos y la frecuencia de sampleo (1 seg para la v$action_session_history, 1 min para la dba_hist_activ_sess_hist y 1 hora para las vistas del repositorio de awr) seguramente estemos perdiendo información de lo que esta pasando. Una posible solución es habilitar las trazas 10046 y luego analizar con tkprof. El problema del tkprof es que te agrupa las queries perdiendo la vision de la secuencialidad de las queries. Para solucionar esto esta este script en perl.
Este script es valido para versiones 11g.

Una consideracion a tener en cuenta con los tiempos de Elapsed time proporcionados es que no se han eliminado los tiempos de idle.

Version de Oracle testada: 11.2.0.4


./parsea_10046.pl PRUEBA_ora_10424.trc

/*ej. SALIDA
[09:28:41] Num query: 1     --> sqlid: dum7xca7h8vwc Total time (msec): 51194.90 
SELECT COUNT(*) FROM CF_TABLE WHERE ID_VALOR <10

[09:28:47] Num query: 2     --> sqlid: gm38789vqza0z Total time (msec): 5720.99 
DELETE CF_TABLE WHERE ID_VALOR<10

[09:29:11] Num query: 3     --> sqlid: 23wm3kz7rps5y Total time (msec): 24700.41 
commit

[09:29:14] Num query: 4     --> sqlid: 3j1k1n5m0h5xx Total time (msec): 2857.63 
INSERT INTO CF_TABLE VALUES (1,'AA')
*/

#!/usr/bin/perl

use Data::Dumper;
use Time::Local;

my $InSQL = 0;
my $InBIND = 0;
my $InTime = 0;
my $BIND_num = 0;
my $SQL_TEXT="";
my $InTime = 0;
my $cursor_actual;
my $date_inicio;
my $NumQuery = 0;
my $time_total_msec = 0;
my $initial_time = 0;
my $deep_level = 0;
my $DEEP_allowed = "off";
my $DEBUG ="off";
my %hash_cursor_ad =();
my %hash_cursor_deep =();
my %hash_sqlid_sqltext;
my %hash_cursor_bind;
my %hash_cursor_time;
my @sql_parsed;
my @bin_variables;

#---------------------------------------------------
# Funcion:debuglog 
# 
# Genera trazas atendiendo a la variable DEBUG = "on|off"
#---------------------------------------------------
sub debuglog
{
	if($DEBUG eq "on")
	{		
		print "$_[0]";
	}
}
#---------------------------------------------------
#
# INPUT PARAMETER TYPE: (string)
# INPUT PARAMETERS:
#	1) HASH -> sqltext sin parsear
#
# OUTPUT PARAMETER TYPE: (Array)
# OUTPUT PARAMETERS:
#	1) Array -> SQL en el primer elemento y nombre de las bind varialbes en el resto.
#
#---------------------------------------------------
sub parsea_sqltext
{
	#debuglog("Entra parsea_sqltext(): $_[0] \n");
	my @_sql_parsed;
	my $_sqltext = $_[0];
	#debuglog("DEBUG parsea_sqltext $_sqltext \n");
	$_sql_parsed[0] = $_sqltext;
	#print "$_sqltext \n";
	#debuglog("Entra parsea_sqltext(): $_sqltext \n");
	while ( $_sqltext =~ /(:\"?\w+"?)/g ) 
	{
		#debuglog("Parsea sqltext sqltext: $_sqltext \n");
		push @_sql_parsed, $1;
		
	}
	return (@_sql_parsed);
	undef @_sql_parsed;
	undef $_sqltext;
}


# -------------------------------
#   MAIN   
# -------------------------------

system("clear");
print "\n\n\n";

ITERACION:
while (<>) {
$MyLine = $_;
#debuglog("LINE: $MyLine \n");
$LineNum = $LineNum + 1;
if (($InTime == 0) && ($MyLine =~ /^\*\*\*/))
{
	$InTime=1;
	$MyLine =~ s/^\*\*\*//;
	$year = (split(/-/, $MyLine))[0];
	$month = (split(/-/, $MyLine))[1];
	$resto = (split(/-/, $MyLine))[2];
	$day   = (split(/ /, $resto))[0];
	$resto = (split(/ /, $resto))[1];
	$hour  = (split(/:/, $resto))[0];
	$min   = (split(/:/, $resto))[1];
	$resto = (split(/:/, $resto))[2];
	$sec    = (split(/\./, $resto))[0];
	$date_inicio = timelocal($sec,$min,$hour,$day,$month,$year);	
}

if ($MyLine =~ /====/) {
	$InBIND = 0;
	$InSQL = 0;
	$BIND_num = 0;
	$cursor=0;
	$SQL_TEXT="";
	#print "$MyLine\n";
}
# If END OF STMT found, stop printing
if (($InSQL==1) && ($MyLine =~ /END OF STMT/ )) {
	@sql_parsed =();
	@sql_parsed = parsea_sqltext($sqltext);
	$sqltext ="";	
	#%hash_ad_sqltext=hash_add_ad_sqltext(%hash_ad_sqltext,$ad,\@sql_parsed);
	debuglog("Add sqlid: $sqlid  sqltext: @sql_parsed \n");
	$hash_ad_sqltext{$sqlid}=[@sql_parsed];
	$DB::single = 2;
	$InSQL = 0;	
}
# In matching pattern, continue printing
if ($InSQL == 1) {
	$sqltext = $sqltext . $MyLine; 
}

# If PARSING IN CURSOR found, start printing
if ($MyLine =~ /PARSING IN CURSOR/) 
{
	#$DB::single = 2;	
	#debuglog( $MyLine."\n");
	$MyLine =~ s/^.*PARSING IN CURSOR #//;
	$cursor = (split(/\s+/, $MyLine))[0];
	debuglog("OPEN cursor: $cursor \n");
	@cursor_info = split (/ +/,$MyLine);
	foreach $item (@cursor_info)
	{
		if ($item =~ /dep=/) {
			$deep_level=(split(/=/, $item))[1];
			chomp($deep_level);			
		}
		if ($item =~ /tim=/) {
			$time=(split(/=/, $item))[1];
			chomp($time);
			if ( $InTime == 1 ) { 
				$initial_time = $time;
				$InTime = 2;
			}
		}
		elsif ($item =~ /hv=/) {
			$hv=(split(/=/, $item))[1];
			chomp($hv);
		}
		
		elsif ($item =~ /ad=/) {
			$ad=(split(/=/, $item))[1];
			$ad =~ s/\'//g;
			chomp($ad);
		}
		
		elsif ($item =~ /sqlid=/) {			
			$sqlid=(split(/=/, $item))[1];
			$sqlid =~ s/\'//g;
			chomp($sqlid);
			#debuglog("sqlid: $sqlid \n");	
		}
	}
	
	#%hash_cursor_ad=hash_add_cur_ad(%hash_cursor_ad,$cursor,$ad);
	debuglog("Add hash_cursor_ad cursor: $cursor sqlid: $sqlid  \n");	
	$hash_cursor_ad{$cursor}=$sqlid;
	$hash_cursor_deep{$cursor}=$deep_level;	
	#print Dumper(\%hash_cursor_ad);
	$InSQL = 1;
}
 
if ($MyLine =~ /BINDS #/) {
	$InBIND = 1;
	$MyLine =~ s/^.*BINDS #//;
	$MyLine =~ s/://;
	$cursor_actual = (split(/\s+/, $MyLine))[0];
	#print "DEBUG: BINDS# Cusor actula $cursor_actual \n";
	# Limpiamos el array anterior
	@bin_variables = ();
	
}
if (($InBIND==1) && ($MyLine =~ /value=/ )) {
	if ( $MyLine =~ /(value=\"?\w+"?)/g )
	{
		$valor_bind = (split(/=/, $1))[1];
		#print "DEBUG: Bind Value: $valor_bind \n";
		push(@bin_variables, $valor_bind);
	}
	else
	{
		#print "DEBUG: Bind Value: ######## \n";
		push(@bin_variables, "######");
	}			
}

# Imprimimos las queries sin bind varialbes
if ( $MyLine =~ /EXEC/ ) {
	
	$MyLine =~ s/^.*EXEC #//;
	$cursor_actual = (split(/:/, $MyLine))[0];
	@cursor_info = split (/,/,$MyLine);
	foreach $item (@cursor_info)
	{
		if ($item =~ /tim=/) {			
			$time=(split(/=/, $item))[1];
			chomp($time);	
			$hash_cursor_time{$cursor_actual} = $time;
		}		
	}
	if ( $InBIND==1 ) 
	{
		$InBIND = 0;		
		$hash_cursor_bind{$cursor_actual} = [ @bin_variables ];	
	}
}	

if ( $MyLine =~ /CLOSE/ ) {
	#$DB::single = 2;	
	#Extraemos el valor del cursor
	$MyLine =~ s/^.*CLOSE #//;
	$cursor_actual = (split(/:/, $MyLine))[0];
	#print "Cursor: $cursor_actual \n";
	#Sacamos el sqltext y sustituimos las bind
	$sqlid = $hash_cursor_ad{$cursor_actual};
	$deep_level= $hash_cursor_deep{$cursor_actual};
    debuglog("CLOSE Phase: Find hash_cursor_ad cursor: $cursor_actual sqlid: $sqlid  \n");
	debuglog("CLOSE Phase: Deep Level: $deep_level \n");
	if ( $sqlid eq "")	
	{ 
		debuglog("CLOSE Phase: sqlid vacio.\n");
		next ITERACION; 
	}
	if (($deep_level > 0) && ($DEEP_allowed	eq "off"))
	{
		debuglog("CLOSE Phase: Deep > 1 not allowed.\n");
		next ITERACION;
	}
	@sql_array = @{$hash_ad_sqltext{$sqlid}};	
	$sql_text = $sql_array[0];	
	debuglog("CLOSE phase cursor: $cursor_actual sqlid: $sqlid sqltext: $sql_text \n");
	for ( my $contador=1; $contador<@sql_array; $contador++ )
	{
		$bind_name = $sql_array[$contador];
		$bind_value = $bin_variables [ $contador -1 ];
		$sql_text =~ s/$bind_name/$bind_value/;		
	}
	
	#Sacamos información de tiempo.
	$time_start = $hash_cursor_time{$cursor_actual};
	@cursor_info = split (/,/,$MyLine);
	foreach $item (@cursor_info)
	{
		if ($item =~ /tim=/) {
			$time_end=(split(/=/, $item))[1];
			chomp($time_end);
			$time_total_msec = ($time_end - $time_start)/1000;
			if ( $time_start == "" ) {  $time_total_msec = 0; } 
		}		
	}
	#Formateamos la salida.
	$NumQuery ++;
	
	($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) = localtime($date_inicio + int(($time_end - $initial_time)/1000000));		
	printf ("\n[%02d:%02d:%02d] Num query: %-5d --> sqlid: %-10s Total time (msec): %.2f \n",$hour,$min,$sec,$NumQuery, $sqlid, $time_total_msec);
	printf ("%s",$sql_text);	 
}
}

Dejar un comentario »

Aún no hay comentarios.

RSS feed for comments on this post. TrackBack URI

Responder

Introduce tus datos o haz clic en un icono para iniciar sesión:

Logo de WordPress.com

Estás comentando usando tu cuenta de WordPress.com. Cerrar sesión / Cambiar )

Imagen de Twitter

Estás comentando usando tu cuenta de Twitter. Cerrar sesión / Cambiar )

Foto de Facebook

Estás comentando usando tu cuenta de Facebook. Cerrar sesión / Cambiar )

Google+ photo

Estás comentando usando tu cuenta de Google+. Cerrar sesión / Cambiar )

Conectando a %s

Blog de WordPress.com.

A %d blogueros les gusta esto: