I’ve always been fascinated by DBCC INPUTBUFFER and DBCC OUTPUTBUFFER for some reason. In data warehousing, if you don’t create control tables and you have a run of 400 stored procedures in succession, it’s sort of nice to know where the batch is quickly, but sometimes hard to find. Usually I’ve seen (from consulting over the past 8 years) that a lot of clients use some sort of “driver” proc, such as EXEC dbo.driver, which calls all of the 400 stored procedures. Unfortunately, most of the tools and DBCC INPUTBUFFER only show that dbo.driver is running; they don’t show which sub-proc is running, let alone what line was just executed by the SQL Engine.
Although far from perfect, DBCC OUTPUTBUFFER can assist a bit. Too bad Books Online doesn’t give us squat about the thing. Run the following to set up the tables, procedures, and data:
DROP TABLE test1, test2, test3
GO
CREATE TABLE test1
(id1 int, col1 char)
GO
CREATE TABLE test2
(id2 int, col2 char)
GO
CREATE TABLE test3
(id3 int, col3 char)
GO
INSERT test1 --test2 test3
SELECT ROW_NUMBER() over (order by X.id), ' '
FROM sys.syscolumns X
GO
DROP PROC p1
GO
CREATE PROC p1
AS
DELETE test1
WHERE id1 = (SELECT MIN(id1) FROM test1)
SELECT COUNT(1) AS Count1 FROM test1
PRINT 'Print delete1'
RAISERROR ('delete1', 10,2)
SELECT 'pffft1'
GO
DROP PROC p2
GO
CREATE PROC p2
AS
DELETE test2
WHERE id2 = (SELECT MIN(id2) FROM test2)
SELECT COUNT(1) AS Count2 FROM test2
PRINT 'Print delete2'
RAISERROR ('delete2', 10,2)
SELECT 'pffft2'
GO
DROP PROC p3
GO
CREATE PROC p3
AS
DELETE test3
WHERE id3 = (SELECT MIN(id3) FROM test3)
SELECT COUNT(1) AS Count3 FROM test3
PRINT 'Print delete3'
RAISERROR ('delete3', 10,2)
SELECT 'pffft3'
GO
DROP PROC driver
GO
CREATE PROC dbo.driver
AS
EXEC dbo.p1
EXEC dbo.p2
EXEC dbo.p3
GO
Go ahead and execute the procedure – I run in spid 54:
Here’s what you get, abbreviated a bit after running DBCC OUTPUTBUFFER (54)
Output Buffer
-----------------------------------------------------------------------------
00000000 04 01 02 ed 00 36 01 00 ff 11 00 c4 00 01 00 00 ...í.6..ÿ..Ä....
00000010 00 00 00 00 00 81 01 00 00 00 00 00 01 00 26 04 ..............&.
00000020 06 43 00 6f 00 75 00 6e 00 74 00 31 00 d1 04 ef .C.o.u.n.t.1.Ñ.ï
00000030 01 00 00 ff 11 00 c1 00 01 00 00 00 00 00 00 00 ...ÿ..Á.........
00000040 ab 38 00 00 00 00 00 01 00 0d 00 50 00 72 00 69 «8.........P.r.i
00000050 00 6e 00 74 00 20 00 64 00 65 00 6c 00 65 00 74 .n.t. .d.e.l.e.t
00000060 00 65 00 31 00 06 4c 00 4f 00 55 00 49 00 53 00 .e.1..L.O.U.I.S.
00000070 45 00 02 70 00 31 00 07 00 00 00 ff 01 00 f7 00 E..p.1.....ÿ..÷.
00000080 00 00 00 00 00 00 00 00 ab 2c 00 50 c3 00 00 02 ........«,.PÃ...
00000090 00 07 00 64 00 65 00 6c 00 65 00 74 00 65 00 31 ...d.e.l.e.t.e.1
000000a0 00 06 4c 00 4f 00 55 00 49 00 53 00 45 00 02 70 ..L.O.U.I.S.E..p
000000b0 00 31 00 08 00 00 00 ff 01 00 f6 00 00 00 00 00 .1.....ÿ..ö.....
000000c0 00 00 00 00 81 01 00 00 00 00 00 20 00 a7 06 00 ........... .§..
000000d0 09 04 d0 00 34 00 d1 06 00 70 66 66 66 74 31 ff .Ð.4.Ñ..pffft1ÿ
000000e0 11 00 c1 00 01 00 00 00 00 00 00 00 ff 01 00 e0 ..Á.........ÿ..à
000000f0 00 00 00 00 00 00 00 00 00 ff 11 00 c4 00 00 00 .........ÿ..Ä...
00000100 00 00 00 00 00 00 81 01 00 00 00 00 00 01 00 26 ...............&
00000110 04 06 43 00 6f 00 75 00 6e 00 74 00 32 00 d1 04 ..C.o.u.n.t.2.Ñ.
00000120 00 00 00 00 ff 11 00 c1 00 01 00 00 00 00 00 00 ....ÿ..Á........
00000130 00 ab 38 00 00 00 00 00 01 00 0d 00 50 00 72 00 .«8.........P.r.
00000140 69 00 6e 00 74 00 20 00 64 00 65 00 6c 00 65 00 i.n.t. .d.e.l.e.
00000150 74 00 65 00 32 00 06 4c 00 4f 00 55 00 49 00 53 t.e.2..L.O.U.I.S
00000160 00 45 00 02 70 00 32 00 07 00 00 00 ff 01 00 f7 .E..p.2.....ÿ..÷
00000170 00 00 00 00 00 00 00 00 00 ab 2c 00 50 c3 00 00 .........«,.PÃ..
00000180 02 00 07 00 64 00 65 00 6c 00 65 00 74 00 65 00 ....d.e.l.e.t.e.
00000190 32 00 06 4c 00 4f 00 55 00 49 00 53 00 45 00 02 2..L.O.U.I.S.E..
000001a0 70 00 32 00 08 00 00 00 ff 01 00 f6 00 00 00 00 p.2.....ÿ..ö....
000001b0 00 00 00 00 00 81 01 00 00 00 00 00 20 00 a7 06 ............ .§.
000001c0 00 09 04 d0 00 34 00 d1 06 00 70 66 66 66 74 32 . .Ð.4.Ñ..pffft2
000001d0 ff 11 00 c1 00 01 00 00 00 00 00 00 00 ff 01 00 ÿ..Á.........ÿ..
000001e0 e0 00 00 00 00 00 00 00 00 00 ff 11 00 c4 00 00 à.........ÿ..Ä..
000001f0 00 00 00 00 00 00 00 81 01 00 00 00 00 00 01 00 ................
00000200 26 04 06 43 00 6f 00 75 00 6e 00 74 00 33 00 d1 &..C.o.u.n.t.3.Ñ
00000210 04 00 00 00 00 ff 11 00 c1 00 01 00 00 00 00 00 .....ÿ..Á.......
00000220 00 00 ab 38 00 00 00 00 00 01 00 0d 00 50 00 72 ..«8.........P.r
00000230 00 69 00 6e 00 74 00 20 00 64 00 65 00 6c 00 65 .i.n.t. .d.e.l.e
00000240 00 74 00 65 00 33 00 06 4c 00 4f 00 55 00 49 00 .t.e.3..L.O.U.I.
00000250 53 00 45 00 02 70 00 33 00 07 00 00 00 ff 01 00 S.E..p.3.....ÿ..
00000260 f7 00 00 00 00 00 00 00 00 00 ab 2c 00 50 c3 00 ÷.........«,.PÃ.
00000270 00 02 00 07 00 64 00 65 00 6c 00 65 00 74 00 65 .....d.e.l.e.t.e
00000280 00 33 00 06 4c 00 4f 00 55 00 49 00 53 00 45 00 .3..L.O.U.I.S.E.
00000290 02 70 00 33 00 08 00 00 00 ff 01 00 f6 00 00 00 .p.3.....ÿ..ö...
000002a0 00 00 00 00 00 00 81 01 00 00 00 00 00 20 00 a7 ............. .§
000002b0 06 00 09 04 d0 00 34 00 d1 06 00 70 66 66 66 74 .. .Ð.4.Ñ..pffft
000002c0 33 ff 11 00 c1 00 01 00 00 00 00 00 00 00 ff 01 3ÿ..Á.........ÿ.
000002d0 00 e0 00 00 00 00 00 00 00 00 00 79 00 00 00 00 .à.........y....
000002e0 fe 00 00 e0 00 00 00 00 00 00 00 00 00 00 00 00 þ..à............
000002f0 00 00 00 00 00 00 79 00 00 00 00 fe 00 00 e0 00 ......y....þ..à.
00000300 00 00 00 00 00 00 00 00 4f 00 46 00 46 00 20 00 ........O.F.F. .
00000310 53 00 45 00 54 00 20 00 51 00 55 00 4f 00 54 00 S.E.T. .Q.U.O.T.
00000320 45 00 44 00 5f 00 49 00 44 00 45 00 4e 00 54 00 E.D._.I.D.E.N.T.
Notice that our sequence count, print delete, delete, and ‘pffft’ show up if you look closely. Pretty nice eh? You can see that we know that these lines executed and search your list of procedures to see what just executed. A little practice and you can follow closely, especially if the procedure runs for a bit so you have time to search.
One thing that will help – back in the day, SQL Server Magazine had another publication called TSQL Solutions, which I subscribed to. I think it ran from 1999-2001 give or take. Anyway, one of the issues had an article by a guy by the name of Andrew Zanevsky (1) and he took the time to clean up the spaces and garbage out of the output, so you could read it a bit better. Here’s the proc and result set, and I’ve highlighted the first procedure output. Again, not great, but not too bad either:
DBCC execution completed. If DBCC printed error messages, contact your system administrator.
6 &Count1 8Print delete1LOUISEp1 ,P delete1LOUISEp1 4 pffft1 &Count2
8Print delete2LOUISEp2 ,P delete2LOUISEp2 4 pffft2 &Count3 8Print dele
te3LOUISEp3 ,P delete3LOUISEp3 4 pffft3 y y OFF SET QUOTED_IDENTIFIER ON
dleCpuPercentage &IdleCpuDuration &LoginTimeout 4HostLoginName 4LocalHos
tAlias!hSqlAgentAutoStart!hReplaceAlertTokensEnabled 4DatabaseMailProf
ile 8AgentMailType!hSysAdminOnly!&ServiceStartMode 4ServiceAccount
4AgentDomainGroup LOUISE d C:\Program Files\Microsoft SQL Server\M
SSQL10_50.MSSQLSERVER\MSSQL\Log\SQLAGENT.OUT
XLocalSystem^LOUISE\SQLS
Notice that in DBCC OUTPUTBUFFER the most current results seem to be listed towards the end of the statement. You might think that it would go 3,2,1, but looks to be the opposite. This is interesting, because in a long list of procedures, you will have to look at the vey end of the output to see what just ran. Here we had only three procedures, so all of the other garbage is at the bottom. Here’s the proc (1):
CREATE PROC [dbo].[sp_outputbuffer]
-- Produce cleaned-up DBCC OUTPUTBUFFER report for a given SPID.
-- Author: Andrew Zanevsky, 2001-06-29
@spid smallint
AS
SET NOCOUNT ON
SET ANSI_PADDING ON
DECLARE @outputbuffer varchar(80),
@clean varchar(16),
@pos smallint
CREATE TABLE #out (
-- Primary key on IDENTITY column prevents rows
-- from changing order when you update them later.
line int IDENTITY PRIMARY KEY CLUSTERED,
dirty varchar(255) NULL,
clean varchar(16) NULL
)
INSERT #out ( dirty )
EXEC( 'DBCC OUTPUTBUFFER(' + @spid + ')' )
SET @pos = 0
WHILE @pos < 16 BEGIN
SET @pos = @pos + 1
-- 1. Eliminate 0x00 symbols.
-- 2. Keep line breaks.
-- 3. Eliminate dots substituted by DBCC OUTPUTBUFFER
-- for nonprintable symbols, but keep real dots.
-- 4. Keep all printable characters.
-- 5. Convert anything else to blank,
-- but compress multiple blanks to one.
UPDATE #out
SET clean = ISNULL( clean, '' ) +
CASE WHEN SUBSTRING( dirty, 9 + @pos * 3, 2 ) =
'0a' THEN char(10)
WHEN SUBSTRING( dirty, 9 + @pos * 3, 2 )
BETWEEN '20' AND '7e'
THEN SUBSTRING( dirty, 61 + @pos, 1 )
ELSE ' '
END
WHERE CASE WHEN SUBSTRING( dirty, 9 + @pos * 3, 2 ) =
'0a' THEN 1
WHEN SUBSTRING( dirty, 61 + @pos, 1 ) = '.'
AND SUBSTRING( dirty, 9 + @pos * 3, 2 ) <>
'2e' THEN 0
WHEN SUBSTRING( dirty, 9 + @pos * 3, 2 )
BETWEEN '20' AND '7e' THEN 1
WHEN SUBSTRING( dirty, 9 + @pos * 3, 2 ) =
'00' THEN 0
WHEN RIGHT( 'x' + clean, 1 )
IN ( ' ', char(10) ) THEN 0
ELSE 1
END = 1
END
DECLARE c_output CURSOR FOR SELECT clean FROM #out
OPEN c_output
FETCH c_output INTO @clean
SET @outputbuffer = ''
WHILE @@FETCH_STATUS = 0 BEGIN
SET @outputbuffer = @outputbuffer +
CASE WHEN RIGHT( @outputbuffer, 1 ) = ' '
OR @outputbuffer = ''
THEN LTRIM( ISNULL( @clean, '' ) )
ELSE ISNULL( @clean, '' )
END
IF DATALENGTH( @outputbuffer ) > 64 BEGIN
PRINT @outputbuffer
SET @outputbuffer = ''
END
FETCH c_output INTO @clean
END
PRINT @outputbuffer
CLOSE c_output
DEALLOCATE c_output
DROP TABLE #out
Thanks for visiting,
Lee
-----------------------
Wow. UFC 129 sucked last night.
(1) Zanevsky, Andrew (2001). A Cool Way to Spy on the OUTPUTBUFFER. TSQL Solutions. October 2001.