PRINT só retorna no final da execução?

Bom dia Galera, hoje tenho uma dica rápida e vou falar sobre uma curiosidade do comando Print do SQL Server, há algum tempo atrás me surgiu uma dúvida, porém não fui pesquisar muito afundo no momento, hoje eu consegui pesquisar melhor e entender como funcionava de verdade, a dúvida era a seguinte:

As vezes precisamos depurar uma Store Procedure para identificarmos um determinado problema, para isso normalmente um dos primeiros passos da investigação é saber aonde esta ocorrendo o problema, em qual momento e qual a linha, para entendermos melhor o problema e pensar em uma solução, bom para quem já esta acostumado com a utilização de algum Debugger por exemplo do Visual Studio ou até mesmo do SQL Server sabe que podemos iniciar uma depuração e colocar alguns Breakpoints em pontos estratégicos para sabermos se o fluxo esta chegando até ali ou não, ou também podemos utilizar outra alternativa muito conhecida que é a função PRINT do SQL Server, colocar PRINTs em pontos estratégicos e acompanhar a saída durante a execução da procedure, bom é nesse ponto que queria chegar, vamos simular um ambiente e fazer alguns testes.

USE MASTER
GO
IF(SELECT DB_ID(‘DB_TESTE’)) IS NOT NULL
DROP DATABASE DB_TESTE

GO

CREATE DATABASE DB_TESTE

GO

USE DB_TESTE

GO

IF(SELECT OBJECT_ID(‘USP_TESTE’)) IS NOT NULL
DROP PROC USP_TESTE

GO

CREATE PROC USP_TESTE
AS
WAITFOR DELAY ’00:00:05′
PRINT ‘MENSAGEM DE TESTE 1 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108)
WAITFOR DELAY ’00:00:05’
PRINT ‘MENSAGEM DE TESTE 2 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108)
WAITFOR DELAY ’00:00:05’
PRINT ‘MENSAGEM DE TESTE 3 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108)

No Script acima criei uma Store Procedure que me retorna 3 Prints em um intervalo de 5 segundos entre eles, a minha ideia aqui é executar essa procedure e acompanhar as mensagens sendo escritas na saída do Management Studio, vamos la.

Execução1

O que eu quero mostrar aqui é o seguinte, minha query esta em execução a 13 segundos como mostrado no circulo em vermelho e nenhuma mensagem foi escrita ainda, aonde mostra a seta vermelha.

Execução2

Depois da execução finalizada aparece nossos 3 prints com o tempo total de 15 segundos conforme esperado, ou seja os Prints só aparecem quando finaliza a execução. Não é bem isso que eu queria, na verdade eu queria acompanhar as mensagens em tempo de execução para saber quais partes da procedure já foi executado.

O motivo para isso é que o SQL Server armazena as mensagens dessa transação em um Buffer de mensagens até que a execução tenha finalizado ou o Buffer alcance seu limite. O tamanho desse Buffer é de 8 kb, assim quando ele atinge esse tamanho ele manda todas as mensagens para o cliente e esvazia esse Buffer para continuar armazenando. Bom quer dizer então que se cada mensagem possuir 8 kb ele irá enviar cada mensagem no momento do PRINT e conseguiremos ver elas em tempo de execução?  Vamos ver isso acontecendo.

ALTER PROC USP_TESTE
AS
WAITFOR DELAY ’00:00:05′
PRINT ‘MENSAGEM DE TESTE 1 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108) + ‘ – ‘ + replicate(‘ ‘ ,8000)
PRINT replicate(CAST(‘ ‘ AS CHAR(1)),100)
WAITFOR DELAY ’00:00:05’
PRINT ‘MENSAGEM DE TESTE 2 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108) + ‘ – ‘ + replicate(‘ ‘ ,8000)
PRINT replicate(CAST(‘ ‘ AS CHAR(1)),100)
WAITFOR DELAY ’00:00:05’
PRINT ‘MENSAGEM DE TESTE 3 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108) + ‘ – ‘ + replicate(‘ ‘ ,8000)

Alterando a procedure com o Script acima, estou utilizando a função REPLICATE para preencher a mensagem com 8000 caracteres ‘ ‘ (espaço em branco) assim enchendo o Buffer, logo após eu executo mais um Print com 100 caracteres para forçar a saída das mensagens no console e a limpeza do Buffer.

 

Execução3

Como na imagem acima olhando as 3 execuções podemos ver que agora o Print é retornado em tempo de execução, porém não é uma solução muito bonita de fazer, existe uma opção melhor para esta situação, o RAISERROR!

O comando RAISERROR tem uma sintaxe um pouco mais complexa, porém ele possui uma opção que nos interessa bastante,’NOWAIT’ quando especificado junto com o RAISERROR ele retorna imediatamente as mensagens para a aplicação, então podemos utiliza-lo para nos ajudar nesse caso.

ALTER PROC USP_TESTE
AS
DECLARE @MSG VARCHAR(1000)

WAITFOR DELAY ’00:00:05′
SET @MSG = ‘MENSAGEM DE TESTE 1 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108)
RAISERROR (@MSG, 0, 1) WITH NOWAIT
WAITFOR DELAY ’00:00:05’
SET @MSG = ‘MENSAGEM DE TESTE 2 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108)
RAISERROR (@MSG, 0, 1) WITH NOWAIT
WAITFOR DELAY ’00:00:05’
SET @MSG = ‘MENSAGEM DE TESTE 3 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108)
RAISERROR (@MSG, 0, 1) WITH NOWAIT

Alterando novamente a procedure agora trocando os PRINTs por RAISERROR.

No primeiro parâmetro para o  RAISERROR passamos a mensagem a ser enviada, no segundo parâmetro a severidade do erro (se informado uma severidade abaixo de 10 é interpretado como mensagem e não como erro), no terceiro parâmetro  é o status da mensagem, bom executando novamente nossa procedure temos o resultado abaixo.

Execução4

Acima temos o resultado em tempo de execução sem precisar preencher com espaços em branco na nossa mensagem, isso é a mesma coisa quando você esta fazendo aquele WHILE e coloca PRINTs dentro dele, as mensagens só vão aparecer no final da execução ou quando encher os 8kb do Buffer que é utilizado para armazenar essas mensagens, você pode estar trocando também para RAISERROR.

Obs: o RAISERROR irá limpar o Buffer utilizado para armazenar as mensagens, ou seja se você tiver executado algum PRINT antes, provavelmente sua mensagem ainda estará no Buffer, assim que você executar o RAISERROR todas as mensagens no Buffer serão enviadas juntas, exemplo:

ALTER PROC USP_TESTE
AS
DECLARE @MSG VARCHAR(1000)

WAITFOR DELAY ’00:00:05′
SET @MSG = ‘MENSAGEM DE TESTE 1 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108)
PRINT ‘TESTE 1′
RAISERROR (@MSG, 0, 1) WITH NOWAIT
WAITFOR DELAY ’00:00:05’
SET @MSG = ‘MENSAGEM DE TESTE 2 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108)
PRINT ‘TESTE 2′
RAISERROR (@MSG, 0, 1) WITH NOWAIT
WAITFOR DELAY ’00:00:05’
SET @MSG = ‘MENSAGEM DE TESTE 3 – ‘ + CONVERT(VARCHAR(20),GETDATE(),108)
RAISERROR (@MSG, 0, 1) WITH NOWAIT

Alterei minha procedure novamente e coloquei 2 Prints, o primeiro Print antes do RAISERROR.

Execução5

Veja que meu  primeiro Print já retornou junto com o RAISERROR mesmo o Buffer não estando cheio, após o RAISERROR nosso Buffer de mensagens esta vazio.

 

Bom galera a dica era essa, espero que tenham gostado, qualquer duvida deixe seu comentário, e acompanhe os novos posts.

Referencias:

PRINT

https://msdn.microsoft.com/en-us/library/ms176047.aspx?f=255&MSPPError=-2147217396

RAISERROR

https://msdn.microsoft.com/en-us/library/ms178592.aspx?f=255&MSPPError=-2147217396

PRINT VS RAISERROR

http://www.jimmcleod.net/blog/index.php/2010/07/19/print-vs-raiserror/

 

Reginaldo Silva

Anúncios

2 comentários sobre “PRINT só retorna no final da execução?

Deixe um comentário

Preencha os seus dados abaixo ou clique em um ícone para log in:

Logotipo do WordPress.com

Você está comentando utilizando sua conta WordPress.com. Sair / Alterar )

Imagem do Twitter

Você está comentando utilizando sua conta Twitter. Sair / Alterar )

Foto do Facebook

Você está comentando utilizando sua conta Facebook. Sair / Alterar )

Foto do Google+

Você está comentando utilizando sua conta Google+. Sair / Alterar )

Conectando a %s