Como medir el tiempo de ejecucion de una consulta SQL

Importante: Debo dejar claro que NINGUNO de los métodos, procesos, procedimientos e invenciones aquí expuestas fueron creadas, ideadas o hechas en el trascurso de mi trabajo ni con el uso de los alguno de recursos que me provee la empresa que me emplea, los nombres, tablas, código y ejemplos NO son sacados de ninguna porción de código creada en alguno de los objetos de trabajo de alguno de mis empleadores ya que estos son propiedad del empleador correspondiente.

Este es mi primer post en serio desde que los de byethost tumbaron mi antiguo blog, cuando tenga tiempo iré rescatando los post mas interesantes de ese antiguo blog...

Hay ciertas situaciones en las que uno tiende a crear procedimientos almacenados(stored procedures) un poco extensos y son:

• Cuando la logica del negocio es muy compleja.
• Cuando la empresa en la que trabajas quiere que le entregues todo para ayer.
• Cuando uno es muy novato en la programación de sql(mas exactamente Transact-sql).

El segundo punto se los puedo sustentar porque cuando se programa a las carreras, especialmente en transact-sql se tiende a NO modularizar el código, entonces uno hace todo el codigo de manera secuencial y por esto los procedures quedan un poco extensos.
Siendo este mi caso de ya hace unas semanas, tuve que hacer un procedimiento un poco complicado y lo terminé quedando de 1000 y pico lineas, obviamente con uno que otro comentario, entonces pensando en el rendimiento de este me dije: "tengo que medir el tiempo de ejecución de este mamotrete porque sino cuando lo vayan a usar los usuarios se van a poner alzados...", de esta situacion se ha inspirado este post, por eso estoy aqui expliandoles como hice para medir el rendimiento de esta piedra...

Tuve tres posibles soluciones para medir esto...
La primera se las resumo facilmente con las siguientes lineas de codigo: 

CREATE PROCEDURE dbo.PruebaDeRendimiento
    @PARAMS BIGINT,
    ....
AS
BEGIN
    DECLARE @InicioTiempo DATETIME
    SET @InicioTiempo = GETDATE()
   
    --------------------------------------------
    -- El codigo del procedimiento va aqui
    --------------------------------------------
   
    IF @DuracionEjecucion = 1
    BEGIN
        SELECT 'Duracion aproximada de la ejecucion: ' +
               CAST(DATEDIFF(MS,@InicioTiempo,GETDATE()) AS VARCHAR(20)) + '[ms]'
        RETURN
    END
END
GO

Como pueden observar se crea una variable tipo DATETIME para asignarle la fecha y hora actual(podemos tambien usar CURRENT_TIMESTAMP), para que al final podamos restarle la fecha y hora en ese instante(cuando termine) usando la función DATEDIFF con el parametro MS para que nos entregue los milisegundos de duración de la ejecución, como pueden ver es muy facil y creeria yo que da un tiempo aproximado de duración.

La segunda opción es usar las DMVs en ingles "Dynamic Management Views" ó en español "Vistas Dinamicas de Administración" que tiene el SQL Server y que usan los verdaderos DBAs xD, algunas de estas vistas requieren permisos en el servidor, una de las que vamos a manejar requiere el permiso VIEW SERVER STATE, mas especificamente me refiero a sys.dm_exec_query_stats que como dice la documentación ofrece información acerca del rendimiento de las consultas o comandos agregadas a la caché para los planes de ejecución, es muy util esta DMV porque nos muestra por ejemplo cuantas veces se ejecutó una determinada consulta, cuando se demoró, cuando fue la ultima vez que se ejecutó, el número de lecturas fisicas y logicas que se necesitaron, el número de escrituras fisicas y logicas, en fin, hay bastante información sobre la ejecución.Normalmente esta DMV nos permite ver la suficiente información, pero las instrucciones ejecutadas no nos las muestra, es por ello que nos toca utilizar una funcion llamada sys.dm_exec_sql_text que nos retorna una tabla, la cual nos muesta las batchs de SQL que hemos ejecutado, por medio de un manejador o handle, podemos buscar una determinada consulta, para mostrar las ultimas consultas hechas podemos utilizar algo como lo siguiente (basado en ejemplo MSDN):

SELECT query_stats.query_hash AS HashConsulta,
    query_stats.statement_text AS ConsultaSQL,
    (CAST(query_stats.total_worker_time AS FLOAT) / 1000) /
    query_stats.execution_count AS DuracionPromedioEjecucionMS,
    query_stats.last_execution_time AS HoraUltimaEjecucion,
    query_stats.execution_count AS NumeroVecesEjecutado
FROM
    (SELECT QS.*,
    SUBSTRING(ST.text, (QS.statement_start_offset/2) + 1,
    ((CASE statement_end_offset
        WHEN -1 THEN DATALENGTH(ST.text)
        ELSE QS.statement_end_offset END
            - QS.statement_start_offset)/2) + 1) AS statement_text
     FROM sys.dm_exec_query_stats AS QS
     CROSS APPLY sys.dm_exec_sql_text(QS.sql_handle) as ST) as query_stats
WHERE  query_stats.last_execution_time > DATEADD(MI,-20,GETDATE())
    AND query_stats.execution_count > 0
ORDER BY HoraUltimaEjecucion DESC

Lo cual nos muestra las ultimas consultas hechas desde hace 20 minutos, con esto podemos ver algo como:

Este metodo es mas preciso ya que obtiene la duracion de las ejecuciones en microsegundos por esta razon vemos valores con coma decimal, ademas podemos agregar mas filtros en el where por si tenemos muchos registros o incluso incluir el plan de ejecución usado en cada consulta "enganchando" otra funcion (sys.dm_exec_query_plan), en fin, hay muchas posibilidades.

Recomiendo antes de hacer las pruebas de ejcucion que corran el siguiente comando:

DBCC FREEPROCCACHE

Esto para limpiar la cache de ejecucion y poder consultar mas facil y rapidamente...

La tercera opcion es tambien muy sencilla, utilizando una de los parametros del SQL server llamado STATISTICS TIME podemos ver casi que directamente el tiempo de analisis, compilacion y ejecucion de alguna de las consultas que queramos, por ejemplo: 

SET STATISTICS TIME ON
GO
-- Esta es mi consulta de prueba
SELECT TerceroId
FROM Tercero
WHERE TipoTerceroId = 13
GO
SET STATISTICS TIME OFF
GO

como pueden ver es sencillamente activar el parametro, luego realizar la consulta y si desean lo pueden volver a desactivar, mostrandonos lo siguiente:

Conclusiones

• En SQL Server es muy facil obtener información acerca de la ejecución y del rendimiento de una consulta.
• Hay otros metodos para obtener esta información que no se vieron en este post.
• Estos tiempos son aproximados por obvias razones, asi que no van a ver el tiempo real de las consultas ya que es casi imposible, pero la aproximación que nos muestra es muy acertada, no obstante pueden ver diferencias entre la primera ejecución y las posteriores de una misma consulta, esto debido a diversos factores, asi que no se confundan.