Reproduciendo carga SQL con tkprof
Por Nelson Calero 
Publicado en Noviembre 2016
Tkprof es un utilitario gratuito provisto por Oracle para analizar archivos de trace de sesiones. Su uso habitual es generar un resumen simple de leer cuando estamos investigando problemas de performance. Pero tkprof tiene otro uso poco conocido: generar scripts con las sentencias capturadas que pueden usarse para reproducir la carga original en otro sistema.
Antes de ver los detalles, un poco de contexto
¿Trace? ¿Testing?
¿Qué es un trace SQL? es un archivo creado en el servidor de base de datos que tiene toda la actividad que realizó una sesión. Se puede habilitar para una sesión, en toda la base o para sesiones que cumplan una combinación de servicio, módulo y acción que definamos. Si les interesa saber más sobre cómo usar SQL Trace y las diferentes formas de habilitarlo, vean este completo artículo de Arup Nanda.
¿Para qué nos puede interesar reproducir sentencias SQL? Una tarea habitual de un DBA es validar el impacto en la performance de una aplicación luego de realizar cambios. Estos pueden ser en cualquier parte de nuestra solución: hardware, configuración, datos, diseño o código de los programas.
En algunos de esos casos, cuando el código SQL que ejecuta la aplicación no cambia, una forma de evaluar el impacto es capturar las sentencias ejecutadas por la aplicación en un ambiente y luego reproducirlas en otro que tiene los cambios que queremos evaluar. De esta forma podemos comparar el uso de recursos antes y después de los cambios para la misma carga, de forma automática y sin depender de trabajo manual por parte de los usuarios de la aplicación para intentar reproducir la actividad original.
Hay muchas herramientas para esto que buscan reproducir exactamente la carga original: Oracle tiene la opción (costo extra) Real application Testing (RAT) que incluye las herramientas Oracle SQL Performance Analyzer y Oracle Database Replay.
RAT implementa varias cosas que son necesarias y difíciles de instrumentar, como reproducir la concurrencia original, escalar la carga original (para generar más o menos concurrencia), controlar los tiempos de conexión y pausa de las sesiones, y una lista larga de etcéteras muy útiles.
Si no tenemos restricciones de presupuesto, es la herramienta a utilizar.
Si estamos buscando alternativas gratuitas de hacer algo similar, con el archivo de sentencias que genera tkprof podemos hacer algo mucho más simple: ejecutar en el mismo orden en que fueron capturadas las sentencias, sin reproducir la concurrencia original ni esperar entre cada una.
Ejemplo simple
Sigue un ejemplo usando SQL*plus y datos del schema HR, que se distribuye con las instalaciones de la base, usando Oracle 12.1.0.2 en Linux x64.
Primero damos permiso al usuario HR para habilitar trace y ver datos de su sesión:
sqlplus / as sysdba
grant execute on dbms_monitor to hr;
grant select on v_$session to hr;
grant select on v_$process to hr;
Luego habilitamos trace y ejecutamos una sentencia:
HR@db12102/12.1.0.2> conn hr/hr
Connected.
HR@db12102/12.1.0.2> alter session set tracefile_identifier = 'test';
Session altered.
Elapsed: 00:00:00.00
HR@db12102/12.1.0.2> EXEC DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>TRUE);
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
HR@db12102/12.1.0.2> select count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id='US';
COUNT(1)
----------
68
Elapsed: 00:00:00.06
HR@db12102/12.1.0.2> EXEC DBMS_MONITOR.session_trace_disable;
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
Ahora tenemos un archivo de trace, falta identificarlo en el servidor. Si no sabemos dónde encontrarlo, esta es una forma simple de ver cuál es el archivo de trace de la sesión actual:
HR@db12102/12.1.0.2> select tracefile from v$process where addr=(select paddr from v$session where sid=userenv('sid'));TRACEFILE
---------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/db12102/db12102/trace/db12102_ora_7637_test.trc
Para generar nuestro script SQL tenemos que procesar el archivo de trace con tkprof usando el parámetro record:
[oracle@oraculo ~]$ cd /u01/app/oracle/diag/rdbms/db12102/db12102/trace
[oracle@oraculo trace]$ tkprof db12102_ora_7637_test.trc result.txt sys=no record=test.sql
TKPROF: Release 12.1.0.2.0 - Development on Sun Oct 23 18:18:31 2016
Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.
[oracle@oraculo trace]$ cat test.sql
BEGIN DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>TRUE); END;
/
select count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id='US' ;
BEGIN DBMS_MONITOR.session_trace_disable; END;
/
[oracle@oraculo trace]$
Como se puede ver, el script SQL incluye todo lo ejecutado desde que habilitamos el trace.
En este ejemplo simple se incluyen las sentencias que habilitan trace porque lo hicimos sobre la misma sesión. Esto no ocurriría si tomamos trace de otras sesiones.
¿Qué se captura si las consultas usan variables bind?
Los SQL capturados van a tener también binds, por lo que tendremos que sustituirlos manualmente por los valores reales cuando queramos ejecutar el script SQL en otra base.
Sigue un ejemplo usando variables de SQL*plus como binds:
SYS@db12102/12.1.0.2> conn hr/hr
Connected.
HR@db12102/12.1.0.2> variable n varchar2(2);
HR@db12102/12.1.0.2> exec :n := 'US';
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00
HR@db12102/12.1.0.2> alter session set tracefile_identifier = 'test3';
Session altered.
Elapsed: 00:00:00.00
HR@db12102/12.1.0.2> EXEC DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>TRUE);
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
HR@db12102/12.1.0.2> select count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n;
COUNT(1)
----------
68
Elapsed: 00:00:00.05
HR@db12102/12.1.0.2> exec :n := 'CA';
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00
HR@db12102/12.1.0.2> select count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n;
COUNT(1)
----------
2
Elapsed: 00:00:00.00
HR@db12102/12.1.0.2> EXEC DBMS_MONITOR.session_trace_disable;
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
HR@db12102/12.1.0.2> exit
Disconnected from Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Advanced Analytics
and Real Application Testing options
[oracle@oraculo trace]$ ls -lrt *test3*.trc | tail
-rw-rw----. 1 oracle oinstall 21088 Oct 23 18:13
/u01/app/oracle/diag/rdbms/db12102/db12102/trace/db12102_ora_4391_test3.trc
[oracle@oraculo trace]$ tkprof db12102_ora_4391_test3.trc result3.txt sys=no record=test3.sql
TKPROF: Release 12.1.0.2.0 - Development on Sun Oct 23 18:14:31 2016
Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.
[oracle@oraculo trace]$ cat test3.sql
BEGIN DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>TRUE); END;
/
select count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n ;
BEGIN :n := 'CA'; END;
/
select count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n ;
BEGIN DBMS_MONITOR.session_trace_disable; END;
/
En este caso, declaramos y asignamos la variable antes de iniciar el trace, por lo que no está en el archivo generado.
Con un poco de trabajo extra podemos tomar los valores que se deben asignar a las binds del archivo de trace (db12102_ora_4391_test3.trc), y procesar el archivo SQL generado (test3.sql) para reemplazar las variables con estos valores cuando queramos reproducir la carga:
[oracle@oraculo trace]$ grep \"US\" db12102_ora_4391_test3.trc
value="US"
value="US"
[oracle@oraculo trace]$ grep \"CA\" db12102_ora_4391_test3.trc
value="CA"
¿El script generado mantiene el orden original en que fueron ejecutadas las sentencias?
Sí, el orden original en que fueron capturadas las sentencias se mantiene en el script generado sin considerar el valor del parámetro sort de tkprof en uso - éste solo afecta el reporte generado (outputfile).
[oracle@oraculo trace]$ tkprof db12102_ora_4391_test3.trc result3.txt sys=no record=test3-sort2.sql sort=fchcnt
TKPROF: Release 12.1.0.2.0 - Development on Mon Oct 31 18:39:36 2016
Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.
[oracle@oraculo trace]$ cat test3-sort2.sql
BEGIN DBMS_MONITOR.session_trace_enable(waits=>TRUE, binds=>TRUE); END;
/
select count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n ;
BEGIN :n := 'CA'; END;
/
select count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n ;
BEGIN DBMS_MONITOR.session_trace_disable; END;
/
En el ejemplo anterior, a pesar de haber usado tkprof con el parámetro sort para que ordene las sentencias por cantidad de fetchs, se puede ver que el script SQL no cambia de orden. Esto se puede ver con cualquiera de las opciones de sort que generen un orden distinto al por defecto.
¿Cómo generamos el archivo SQL si la aplicación usa varias conexiones a la base de datos?
En este caso tenemos que habilitar trace a todas las sesiones y luego procesar todos los archivos. Para facilitar esta tarea, Oracle provee el utilitario trcsess que consolida todos los traces en un solo archivo manteniendo el orden de ejecución original.
El siguiente ejemplo usa un servicio para conectarse a la base de datos para identificar fácilmente las sesiones a las que vamos a habilitar trace. Esto afecta a todas las sesiones ya conectadas que lo hayan hecho mediante el servicio y a todas las nuevas que lo usen.
[oracle@oraculo ~]$ cat $ORACLE_HOME/network/admin/tnsnames.ora
db12102 =
(DESCRIPTION=
(ADDRESS=(PROTOCOL=tcp)(HOST=localhost)(PORT=1521))
(CONNECT_DATA=(SERVICE_NAME=db12102))
)
[oracle@oraculo ~]$ sqlplus hr/hr@db12102
SQL*Plus: Release 12.1.0.2.0 Production on Mon Oct 31 17:51:45 2016
Copyright (c) 1982, 2014, Oracle. All rights reserved.
Last Successful login time: Sun Oct 23 2016 18:36:14 -04:00
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Advanced Analytics
and Real Application Testing options
HR@db12102/12.1.0.2> select service_name, count(1) from v$session group by service_name;
SERVICE_NAME COUNT(1)
------------------------------------------ -----------
db12102 1
SYS$BACKGROUND 36
SYS$USERS 2
Elapsed: 00:00:00.01
Podemos ver una sola sesión conectada que usa el servicio, y otras que no lo están usando.
Abrimos otra terminal y nos conectamos usando el mismo servicio:
[oracle@oraculo trace]$ sqlplus hr/hr@db12102
SQL*Plus: Release 12.1.0.2.0 Production on Mon Oct 31 18:49:17 2016
Copyright (c) 1982, 2014, Oracle. All rights reserved.
Last Successful login time: Mon Oct 31 2016 17:51:46 -04:00
Connected to:
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, Oracle Label Security, OLAP, Advanced Analytics
and Real Application Testing options
HR@db12102/12.1.0.2> select service_name, count(1) from v$session group by service_name;
SERVICE_NAME COUNT(1)
------------------------------------------------ --------
db12102 2
SYS$BACKGROUND 36
SYS$USERS 1
Elapsed: 00:00:00.03
HR@db12102/12.1.0.2>
Ahora podemos habilitar SQL trace para el servicio db12102 – esto capturará la actividad de las dos sesiones ya conectadas al servicio.
HR@db12102/12.1.0.2> EXEC DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db12102', waits=>TRUE, binds=>TRUE);
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.17
HR@db12102/12.1.0.2> variable n varchar2(2);
HR@db12102/12.1.0.2> exec :n := 'CA';
PL/SQL procedure successfully completed.
Ahora volvemos a la primera sesión y ejecutamos algo también:
HR@db12102/12.1.0.2> variable n varchar2(2);
HR@db12102/12.1.0.2> exec :n := 'US';
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
De nuevo vamos a la segunda sesión para ejecutar algo:
HR@db12102/12.1.0.2> select /* first */ count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n;
COUNT(1)
----------
2
Elapsed: 00:00:00.03
Otra vez cambiamos a la primera sesión para ejecutar consultas:
HR@db12102/12.1.0.2> select /* second */ count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n;
COUNT(1)
----------
68
Elapsed: 00:00:00.00
HR@db12102/12.1.0.2> exec :n := 'UY';
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.00
HR@db12102/12.1.0.2> select /* third */ count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n;
COUNT(1)
----------
0
Elapsed: 00:00:00.00
Ya que tenemos actividad en ambas sesiones y mezclada en el tiempo, podemos terminar el trace. En este ejemplo simple alcanza con salir de SQL*Plus para que se escriban los archivos.
Pero no hay que olvidar deshabilitar trace, porque toda nueva sesión usando el servicio va a crear un archivo de trace si no lo hacemos.
HR@db12102/12.1.0.2> EXEC DBMS_MONITOR.serv_mod_act_trace_disable(service_name=>'db12102');
PL/SQL procedure successfully completed.
Elapsed: 00:00:00.01
Ahora debemos procesar los archivos de trace generados:
[oracle@oraculo trace]$ ls -lrt | tail
-rw-rw----. 1 oracle oinstall 275 Oct 31 18:54 db12102_ora_18587.trm
-rw-rw----. 1 oracle oinstall 19411 Oct 31 18:54 db12102_ora_18587.trc
-rw-rw----. 1 oracle oinstall 290 Oct 31 18:54 db12102_ora_22099.trm
-rw-rw----. 1 oracle oinstall 14493 Oct 31 18:54 db12102_ora_22099.trc
Primero veamos que se capturó, procesando cada archivo por separado con tkprof:
[oracle@oraculo trace]$ tkprof db12102_ora_18587.trc report-srv1.txt sys=no record=test-srv1.sql
TKPROF: Release 12.1.0.2.0 - Development on Mon Oct 31 18:55:56 2016
Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.
[oracle@oraculo trace]$ tkprof db12102_ora_22099.trc report-srv2.txt sys=no record=test-srv2.sql
TKPROF: Release 12.1.0.2.0 - Development on Mon Oct 31 18:56:17 2016
Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.
Para generar nuestro archive consolidado, primero usemos trcsess para procesar los archivos – vamos a indicar que solo queremos ver la actividad de nuestro servicio. El resultado es un nuevo trace file.
[oracle@oraculo trace]$ trcsess output=trace-all-srv.txt service=db12102 db12102_ora_18587.trc db12102_ora_22099.trc
El último paso es procesar el archivo generado por trcsess usando tkrpof para generar nuestro SQL final:
[oracle@oraculo trace]$ tkprof trace-all-srv.txt report-all.txt sys=no record=all.sql
TKPROF: Release 12.1.0.2.0 - Development on Mon Oct 31 19:01:19 2016
Copyright (c) 1982, 2014, Oracle and/or its affiliates. All rights reserved.
[oracle@oraculo trace]$ ls -lrt | tail
-rw-rw----. 1 oracle oinstall 19411 Oct 31 18:54 db12102_ora_18587.trc
-rw-rw----. 1 oracle oinstall 290 Oct 31 18:54 db12102_ora_22099.trm
-rw-rw----. 1 oracle oinstall 14493 Oct 31 18:54 db12102_ora_22099.trc
-rw-r--r--. 1 oracle oinstall 417 Oct 31 18:55 test-srv1.sql
-rw-r--r--. 1 oracle oinstall 8659 Oct 31 18:56 report-srv1.txt
-rw-r--r--. 1 oracle oinstall 313 Oct 31 18:56 test-srv2.sql
-rw-r--r--. 1 oracle oinstall 8659 Oct 31 18:56 report-srv2.txt
-rw-r--r--. 1 oracle oinstall 32444 Oct 31 19:00 trace-all-srv.txt
-rw-r--r--. 1 oracle oinstall 730 Oct 31 19:01 all.sql
-rw-r--r--. 1 oracle oinstall 15941 Oct 31 19:01 report-all.txt
Podemos ver en el contenido del SQL consolidado de toda la captura que el orden de ejecución de las sentencias se respeta:
[oracle@oraculo trace]$ cat all.sql
BEGIN DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db12102', waits=>TRUE, binds=>TRUE); END;
/
BEGIN :n := 'CA'; END;
/
BEGIN :n := 'US'; END;
/
select /* first */ count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n ;
select /* second */ count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n ;
BEGIN :n := 'UY'; END;
/
select /* third */ count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n ;
Lo podemos comparar con los SQL generados de cada trace file individual:
[oracle@oraculo trace]$ cat test-srv1.sql
BEGIN :n := 'US'; END;
/
select /* second */ count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n ;
BEGIN :n := 'UY'; END;
/
select /* third */ count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n ;
[oracle@oraculo trace]$ cat test-srv2.sql
BEGIN DBMS_MONITOR.serv_mod_act_trace_enable(service_name=>'db12102', waits=>TRUE, binds=>TRUE); END;
/
BEGIN :n := 'CA'; END;
/
select /* first */ count(1)
from hr.departments d, hr.locations l, hr.employees e
where d.location_id=l.location_id(+)
and e.DEPARTMENT_ID=d.DEPARTMENT_ID(+)
and country_id=:n ;
[oracle@oraculo trace]$
