Introduction

One of the challenges of logging SQL processes is to obtain a complete list of calling and called SPs/UDFs at any given phase of the process. CONTEXT_INFO() comes handy in this case. It is a function returning 128 bytes which are persistent throughout the connection and resistant to rollbacks.

Let's consider the following scenario. A SQL job which loads a datawarehouse consists of chain of stored procedures. Every action is logged into a table and it would be great if we can also log the whole calling chain of SPs and see where the process currently is. CONTEXT_INFO() can be used as shared data between SPs.

The first two stored procedures bellow use CONTEXT_INFO() as a string for storing SPs identifiers. They perform the save (push) and remove(pop) functionality using @@procid which identifies the SP and can be translated into the SPs name. The output is the new CONTEXT_INFO() value. The third procedure converts the binary @@procid into the object name and outputs the CONTEXT_INFO() in a readable form.

1. Push the @@proc_id into CONTEXT_INFO()

Every SP stores their @@procid in CONTEXT_INFO() after being called:

create procedure log_PushContextInfoInt (@procid int,@b varbinary(128) output)
as
begin
set @b=convert(binary(4),@procid)+isnull(context_info(),0x0)
set context_info @b
return 
end
go

2. Pop the @@procid from the CONTEXT_INFO()

After the call returns, the caller will remove the top 4 bytes as it represents the @procid as int stored in 4 bytes.

create procedure log_PopContextInfoInt (@b varbinary(128) output)
as
begin
set @b=substring(isnull(context_info(),0x0),5,len(context_info()))
set context_info @b
return 
end
go

3. Read the CONTEXT_INFO() and convert it into a string containing SP' s names delimited by '/'

create proc log_ReadContextInfoSP (@b varbinary(128),@call_str varchar(2048) output)
as
set @call_str=''
while @b<>0x0
 begin
 set @call_str=object_name(convert(int,substring(@b,1,4)))+'/'+@call_str
 set @b=substring(@b,5,len(@b))
 end
return

Usage example

These three SPs demonstrate the usage. Procedure a calls procedure b, which calls procedure c. Every SP call is preceded by saving it's @@procid in CONTEXT_INFO() using log_PushContextInfoInt. After the call returns, the top @@procid is removed by log_PopContextInfoInt. The content of CONTEXT_INFO(), which represents the current calling stack is available through log_ReadContextInfoSP.

create proc a
as
print '---- in a ----'
declare @b varbinary(128),@call_str varchar(2048)
exec log_PushContextInfoInt @@procid,@b output
print 'before call'
exec log_ReadContextInfoSP @b,@call_str output
print @call_str
exec b
exec log_PopContextInfoInt @b output
print 'after call'
exec log_ReadContextInfoSP @b,@call_str output
print @call_str
print '------------'
return
go
create proc b
as
print '---- in b ----'
declare @b varbinary(128),@call_str varchar(2048)
exec log_PushContextInfoInt @@procid,@b output
print 'before call'
exec log_ReadContextInfoSP @b,@call_str output
print @call_str
exec c
exec log_PopContextInfoInt @b output
print 'after call'
exec log_ReadContextInfoSP @b,@call_str output
print @call_str
print '-------------'
return
go
create proc c
as
print '---- in c ----'
declare @b varbinary(128),@call_str varchar(2048)
exec log_PushContextInfoInt @@procid,@b output
exec log_ReadContextInfoSP @b,@call_str output
print @call_str
print '------------'
return

Don't forget to reset the CONTEXT_INFO()

set context_info 0x0
exec a

Result:

---- in a ----

before call

a/

---- in b ----

before call

a/b/

---- in c ----

a/b/c/

------------

after call

a/b/

-------------

after call

a/

------------

Conclusion

CONTEXT_INFO() with its 128 bytes is a lightweight method for passing info within the session without getting too heavy into service broker queues.