T-SQL Tuesday #31 - Logging Tricks with CONTEXT_INFO
- by Most Valuable Yak (Rob Volk)
This month's T-SQL Tuesday is being hosted by Aaron Nelson [b | t], fellow Atlantan (the city in Georgia, not the famous sunken city, or the resort in the Bahamas) and covers the topic of logging (the recording of information, not the harvesting of trees) and maintains the fine T-SQL Tuesday tradition begun by Adam Machanic [b | t] (the SQL Server guru, not the guy who fixes cars, check the spelling again, there will be a quiz later). This is a trick I learned from Fernando Guerrero [b | t] waaaaaay back during the PASS Summit 2004 in sunny, hurricane-infested Orlando, during his session on Secret SQL Server (not sure if that's the correct title, and I haven't used parentheses in this paragraph yet). CONTEXT_INFO is a neat little feature that's existed since SQL Server 2000 and perhaps even earlier. It lets you assign data to the current session/connection, and maintains that data until you disconnect or change it. In addition to the CONTEXT_INFO() function, you can also query the context_info column in sys.dm_exec_sessions, or even sysprocesses if you're still running SQL Server 2000, if you need to see it for another session. While you're limited to 128 bytes, one big advantage that CONTEXT_INFO has is that it's independent of any transactions. If you've ever logged to a table in a transaction and then lost messages when it rolled back, you can understand how aggravating it can be. CONTEXT_INFO also survives across multiple SQL batches (GO separators) in the same connection, so for those of you who were going to suggest "just log to a table variable, they don't get rolled back": HA-HA, I GOT YOU! Since GO starts a new batch all variable declarations are lost. Here's a simple example I recently used at work. I had to test database mirroring configurations for disaster recovery scenarios and measure the network throughput. I also needed to log how long it took for the script to run and include the mirror settings for the database in question. I decided to use AdventureWorks as my database model, and Adam Machanic's Big Adventure script to provide a fairly large workload that's repeatable and easily scalable. My test would consist of several copies of AdventureWorks running the Big Adventure script while I mirrored the databases (or not). Since Adam's script contains several batches, I decided CONTEXT_INFO would have to be used. As it turns out, I only needed to grab the start time at the beginning, I could get the rest of the data at the end of the process. The code is pretty small: declare @time binary(128)=cast(getdate() as binary(8))
set context_info @time
... rest of Big Adventure code ...
go
use master;
insert mirror_test(server,role,partner,db,state,safety,start,duration)
select @@servername, mirroring_role_desc, mirroring_partner_instance,
db_name(database_id), mirroring_state_desc, mirroring_safety_level_desc,
cast(cast(context_info() as binary(8)) as datetime),
datediff(s,cast(cast(context_info() as binary(8)) as datetime),getdate())
from sys.database_mirroring where db_name(database_id) like 'Adv%';
I declared @time as a binary(128) since CONTEXT_INFO is defined that way. I couldn't convert GETDATE() to binary(128) as it would pad the first 120 bytes as 0x00. To keep the CAST functions simple and avoid using SUBSTRING, I decided to CAST GETDATE() as binary(8) and let SQL Server do the implicit conversion. It's not the safest way perhaps, but it works on my machine. :)
As I mentioned earlier, you can query system views for sessions and get their CONTEXT_INFO. With a little boilerplate code this can be used to monitor long-running procedures, in case you need to kill a process, or are just curious how long certain parts take. In this example, I added code to Adam's Big Adventure script to set CONTEXT_INFO messages at strategic places I want to monitor. (His code is in UPPERCASE as it was in the original, mine is all lowercase):
declare @msg binary(128)
set @msg=cast('Altering bigProduct.ProductID' as binary(128))
set context_info @msg
go
ALTER TABLE bigProduct ALTER COLUMN ProductID INT NOT NULL
GO
set context_info 0x0
go
declare @msg1 binary(128)
set @msg1=cast('Adding pk_bigProduct Constraint' as binary(128))
set context_info @msg1
go
ALTER TABLE bigProduct ADD CONSTRAINT pk_bigProduct PRIMARY KEY (ProductID)
GO
set context_info 0x0
go
declare @msg2 binary(128)
set @msg2=cast('Altering bigTransactionHistory.TransactionID' as binary(128))
set context_info @msg2
go
ALTER TABLE bigTransactionHistory ALTER COLUMN TransactionID INT NOT NULL
GO
set context_info 0x0
go
declare @msg3 binary(128)
set @msg3=cast('Adding pk_bigTransactionHistory Constraint' as binary(128))
set context_info @msg3
go
ALTER TABLE bigTransactionHistory ADD CONSTRAINT pk_bigTransactionHistory PRIMARY KEY NONCLUSTERED(TransactionID)
GO
set context_info 0x0
go
declare @msg4 binary(128)
set @msg4=cast('Creating IX_ProductId_TransactionDate Index' as binary(128))
set context_info @msg4
go
CREATE NONCLUSTERED INDEX IX_ProductId_TransactionDate
ON bigTransactionHistory(ProductId,TransactionDate) INCLUDE(Quantity,ActualCost)
GO
set context_info 0x0
This doesn't include the entire script, only those portions that altered a table or created an index.
One annoyance is that SET CONTEXT_INFO requires a literal or variable, you can't use an expression. And since GO starts a new batch I need to declare a variable in each one. And of course I have to use CAST because it won't implicitly convert varchar to binary. And even though context_info is a nullable column, you can't SET CONTEXT_INFO NULL, so I have to use SET CONTEXT_INFO 0x0 to clear the message after the statement completes. And if you're thinking of turning this into a UDF, you can't, although a stored procedure would work.
So what does all this aggravation get you? As the code runs, if I want to see which stage the session is at, I can run the following (assuming SPID 51 is the one I want):
select CAST(context_info as varchar(128)) from sys.dm_exec_sessions where session_id=51
Since SQL Server 2005 introduced the new system and dynamic management views (DMVs) there's not as much need for tagging a session with these kinds of messages. You can get the session start time and currently executing statement from them, and neatly presented if you use Adam's sp_whoisactive utility (and you absolutely should be using it).
Of course you can always use xp_cmdshell, a CLR function, or some other tricks to log information outside of a SQL transaction. All the same, I've used this trick to monitor long-running reports at a previous job, and I still think CONTEXT_INFO is a great feature, especially if you're still using SQL Server 2000 or want to supplement your instrumentation. If you'd like an exercise, consider adding the system time to the messages in the last example, and an automated job to query and parse it from the system tables. That would let you track how long each statement ran without having to run Profiler.
#TSQL2sDay
