Quiero mostrarles una simple prueba de Stress que hice para que vean qué tan importante es realizarla y qué tan mortal puede ser evitarla.
Ejemplo:
Vamos a crear una tabla llamada TEST que vamos a utilizar en el Stress para cargar datos.
SQL_9iR2> CREATE TABLE test (id NUMBER);
Tabla creada.
Bien, yo tengo creados unos Shell Scripts propios para realizar el Stress Test. Los más importantes son los siguientes:
- iniciar_stress.sh --> Iniciamos el Stress Test.
- reporte.sh --> Genera el reporte con el detalle sobre el Stress Test.
Lo que vamos a realizar es un Stress Test simulando una concurrencia de 100 conexiones simultáneas ejecutando el siguiente bloque PL/SQL anónimo:
BEGIN
FOR x IN 1 .. 100 LOOP
INSERT INTO test VALUES (x);
END LOOP;
END;
/
Como pueden observar, el INSERT que vamos a realizar es muy sencillo y debería ejecutarse rápido, cierto? Veamos cuánto demora si lo ejecuto sin concurrencia:
SQL_9iR2> BEGIN
2 FOR x IN 1 .. 100 LOOP
3 INSERT INTO test VALUES (x);
4 END LOOP;
5 END;
6 /
Procedimiento PL/SQL terminado correctamente.
Transcurrido: 00:00:01.25
Bien, vemos que demoró 1.25 segundos. El bloque se ejecutó bastante rápido y esperamos que se comporte de la misma manera cuando realicemos el Stress Test... asi que hagamos la prueba para comprobarlo!
Para comenzar el Stress Test, vamos a ejecutar el Shell Script llamado iniciar_stress.sh
$ ./iniciar_stress.sh
=================================================================
====================== STRESS TEST ==============================
=================================================================
Autor: Leonardo Horikian - Oracle Argentina
Descripción: Programa que inicia un StressTest
Apretar ENTER para continuar...
=================================================================
Ingresar la password del usuario STRESS_TEST:
TNS alias (para local dejar en blanco):
Esta instancia se encuentra configurada para soportar 769 conexiones concurrentes!
Cuántas conexiones concurrentes querés ejecutar [1-769]?
100
=================================================================
StressTest listo para ser ejecutado.
Para comenzar, apretar ENTER
=================================================================
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
nohup: appending output to `nohup.out'
Como pueden ver, se iniciaron 100 conexiones a la base de datos. Las mismas se ejecutan con el comando nohup realizando la conexión a la instancia vía SQL*PLUS.
Ahora vamos a ejecutar el Shell Script llamado reporte.sh para generar el reporte con la información resultante de la prueba.
$ ./reporte.sh
=================================================================
====================== STRESS TEST ==============================
=================================================================
Autor: Leonardo Horikian - Oracle Argentina
Descripción: Programa que genera el reporte con la información
sobre la ejecución del StressTest
Apretar ENTER para continuar...
=================================================================
Ingresar la password del usuario STRESS_TEST:
TNS alias (para local dejar en blanco):
NOTA: Este script generará un archivo con la información del reporte en el directorio /reportes/.
Ingresar el nombre del archivo de salida:
stress_test.txt
Elegir el TEST_ID con el cual se quiere generar el reporte...
TEST_ID TEST_DATE COMMENTS
********** ****************************** ****************************************
37 06/25/2009 08:46 100 conexiones concurrentes.
Ingresá el TEST_ID: 37
El archivo fue generado satisfactoriamente!
Abrimos el reporte y vemos lo siguiente...
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------- INFORMACION SOBRE EL STRESS_TEST -------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
ID: 37 - FECHA: 06/25/2009 08:46 - COMENTARIOS: 100 conexiones concurrentes.
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------- RESULTADO INDIVIDUAL DEL STRESS_TEST (para cada una de las sesiones) -------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
SID: 248 - SPID: 11065
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
TOTAL_TIME_IN_SEC: 1.51 - TOTAL_TIME_IN_MIN: .03 - TOTAL_TIME_IN_HO: 0
-------------------------------------------------------------------------------------------------------------
- EVENTOS ---------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
EVENT: buffer busy waits --> WAITS: 47 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 1.3
EVENT: library cache pin --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .52
EVENT: enqueue --> WAITS: 8 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .31
EVENT: latch free --> WAITS: 6 - TIMEOUTS: 2 - TIME_WAITED_IN_SEC: .03
EVENT: row cache lock --> WAITS: 11 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .03
EVENT: SQL*Net message from client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .01
EVENT: control file sequential read --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: SQL*Net message to client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: db file sequential read --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
SID: 808 - SPID: 11143
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
TOTAL_TIME_IN_SEC: 1.5 - TOTAL_TIME_IN_MIN: .03 - TOTAL_TIME_IN_HO: 0
-------------------------------------------------------------------------------------------------------------
- EVENTOS ---------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
EVENT: buffer busy waits --> WAITS: 47 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 1.3
EVENT: enqueue --> WAITS: 7 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .3
EVENT: library cache pin --> WAITS: 3 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .16
EVENT: latch free --> WAITS: 1 - TIMEOUTS: 1 - TIME_WAITED_IN_SEC: .01
EVENT: SQL*Net message from client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .01
EVENT: control file sequential read --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: SQL*Net message to client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
SID: 714 - SPID: 11116
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
TOTAL_TIME_IN_SEC: 1.48 - TOTAL_TIME_IN_MIN: .02 - TOTAL_TIME_IN_HO: 0
-------------------------------------------------------------------------------------------------------------
- EVENTOS ---------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
EVENT: buffer busy waits --> WAITS: 35 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 1.3
EVENT: library cache pin --> WAITS: 3 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .31
EVENT: enqueue --> WAITS: 2 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .24
EVENT: SQL*Net message from client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .01
EVENT: latch free --> WAITS: 2 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: control file sequential read --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: SQL*Net message to client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
SID: 204 - SPID: 11110
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
TOTAL_TIME_IN_SEC: 1.48 - TOTAL_TIME_IN_MIN: .02 - TOTAL_TIME_IN_HO: 0
-------------------------------------------------------------------------------------------------------------
- EVENTOS ---------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
EVENT: buffer busy waits --> WAITS: 38 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 1.2
EVENT: library cache pin --> WAITS: 3 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .36
EVENT: enqueue --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .3
EVENT: db file sequential read --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .09
EVENT: row cache lock --> WAITS: 7 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .03
EVENT: SQL*Net message from client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .02
EVENT: latch free --> WAITS: 2 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: SQL*Net message to client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: control file sequential read --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
...
...
CONTINUA ...
...
...
Como podemos observar, el comportamiento para cada sesión fue el mismo que cuando ejecutamos la prueba sin concurrencia. El bloque se ejecutó en un promedio de 1.5 segundos por sesión.
Qué sucede si repetimos la prueba con 300 usuarios concurrentes? El resultado seguirá siendo el mismo? Veamos el reporte de la ejecución...
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------- INFORMACION SOBRE EL STRESS_TEST -------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
ID: 38 - FECHA: 06/25/2009 09:07 - COMENTARIOS: 300 conexiones concurrentes.
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------- RESULTADO INDIVIDUAL DEL STRESS_TEST (para cada una de las sesiones) -------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
SID: 607 - SPID: 15310
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
TOTAL_TIME_IN_SEC: 5.47 - TOTAL_TIME_IN_MIN: .09 - TOTAL_TIME_IN_HO: 0
-------------------------------------------------------------------------------------------------------------
- EVENTOS ---------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
EVENT: enqueue --> WAITS: 12 - TIMEOUTS: 1 - TIME_WAITED_IN_SEC: 4.8
EVENT: row cache lock --> WAITS: 12 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 2.9
EVENT: latch free --> WAITS: 15 - TIMEOUTS: 1 - TIME_WAITED_IN_SEC: 1.2
EVENT: buffer busy waits --> WAITS: 11 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .77
EVENT: SQL*Net message from client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .06
EVENT: db file sequential read --> WAITS: 3 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .04
EVENT: log file sync --> WAITS: 1 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .03
EVENT: control file sequential read --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: SQL*Net message to client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
SID: 286 - SPID: 15362
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
TOTAL_TIME_IN_SEC: 5.19 - TOTAL_TIME_IN_MIN: .09 - TOTAL_TIME_IN_HO: 0
-------------------------------------------------------------------------------------------------------------
- EVENTOS ---------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
EVENT: enqueue --> WAITS: 13 - TIMEOUTS: 1 - TIME_WAITED_IN_SEC: 4.9
EVENT: row cache lock --> WAITS: 11 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 2.9
EVENT: latch free --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 1.1
EVENT: buffer busy waits --> WAITS: 5 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .45
EVENT: SQL*Net message from client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .12
EVENT: db file sequential read --> WAITS: 3 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .02
EVENT: control file sequential read --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: SQL*Net message to client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
SID: 435 - SPID: 15329
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
TOTAL_TIME_IN_SEC: 4.97 - TOTAL_TIME_IN_MIN: .08 - TOTAL_TIME_IN_HO: 0
-------------------------------------------------------------------------------------------------------------
- EVENTOS ---------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
EVENT: enqueue --> WAITS: 9 - TIMEOUTS: 1 - TIME_WAITED_IN_SEC: 3.5
EVENT: row cache lock --> WAITS: 8 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 2.7
EVENT: latch free --> WAITS: 37 - TIMEOUTS: 1 - TIME_WAITED_IN_SEC: 2.5
EVENT: buffer busy waits --> WAITS: 7 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .58
EVENT: db file sequential read --> WAITS: 17 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .18
EVENT: SQL*Net message from client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .07
EVENT: library cache pin --> WAITS: 1 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .01
EVENT: control file sequential read --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: SQL*Net message to client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
SID: 202 - SPID: 15746
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
TOTAL_TIME_IN_SEC: 4.63 - TOTAL_TIME_IN_MIN: .08 - TOTAL_TIME_IN_HO: 0
-------------------------------------------------------------------------------------------------------------
- EVENTOS ---------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
EVENT: enqueue --> WAITS: 76 - TIMEOUTS: 1 - TIME_WAITED_IN_SEC: 5.5
EVENT: row cache lock --> WAITS: 181 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 2.1
EVENT: latch free --> WAITS: 47 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 2.0
EVENT: buffer busy waits --> WAITS: 5 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .16
EVENT: SQL*Net message from client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .07
EVENT: wait list latch free --> WAITS: 1 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: .01
EVENT: control file sequential read --> WAITS: 4 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: SQL*Net message to client --> WAITS: 19 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
EVENT: db file sequential read --> WAITS: 2 - TIMEOUTS: 0 - TIME_WAITED_IN_SEC: 0
-------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------
...
...
CONTINUA ...
...
...
Como observamos, cuando incrementamos la cantidad de conexiones concurrentes, aumentó casi un 400 porciento el tiempo de ejecución de cada conexión!!! Este es un ejemplo muy claro del porqué es TAN importante hacer ésta clase de pruebas de Stress para evitar problemas futuros cuando pasemos nuestro sistema a producción!
