Poking around SQL Server's Transaction Log

I recently had the opportunity to try and figure out why SQL Server was doing certain things in one of my applications. This application was using CursorAdapters and for some strange reason, data was being cleared out (for no apparent reason, of course).

But in my searches, I started looking for a tool that would let me read SQL Server's Transaction Log. Sure, you can always restore it to a certain point - but when your customer has run their system for several days and then comes back and says "there was a problem a few days ago", you really don't want to suggest they re-enter all their data. I just wanted to know what the heck was going on with those SQL statements.

Now, you might expect (as I did), that Microsoft would offer such a tool directly within the SQL Server 2005 Manager but no - their "logs" are all about "Login Failed" or "Starting the service". Useless if you really want to see what's going on.

Now, if you Google SQL Server Transaction Logs, you'll see all kinds of tools available. Red-Gate and Apex were two that I looked at. Unfortunately, even though it's 2007, only one of them has access to the SQL 2005 logs and that was Apex. Red-Gate even has a funny story as to why they don't have SQL 2005 support. Red-Gate's product is only $195 while Apex's is considerably more but both offered eval versions which I thought would be enough to see what was going on.

I tried using Apex's and while it looked like it was showing me tons of information, it didn't actually show me the SQL that was being executed. Every now and then, I would see a record with a bit of data but for the most part, the log was empty. I've kept on trying to look at it to see if there's anything I can pull out - but for the most part, when looking at the way SQL tables are updated with VFP Cursor adapters , it wasn't very useful. (I don't know if it works better with direct SQL Pass through).

So today, I had the scenario where a field in a table was blanked out on the 5th even though it had been filled in earlier in the day. How could this have happened? I took a look in the ApexLog and it shed no information. I played with database backups and was able to identify exactly when the problem took place but without access to the log, how could I see what happened?

As luck would have it, I did another google search and came across an undocumented command and function that's been around since SQL 7.0 (so why it's not documented is beyond me except this posting explains that MS won't support it). DBCC LOG or more importantly

SELECT * FROM ::fn_dblog(null,null)

which returns a cursor that is the essence of the transaction log.

It's not very readable but let me share a few things I did learn about it and how I was able to use it (if someone has more information, please let me know) - I tried googling for more details but in the end , it was simpler to find it myself).

The table has a messy structure - and it's changed from SQL 2000 to SQL 2005 so I won't bother putting it in here.

The OPERATION field tells you what it was trying to do. The key entries here are LOP_BEGIN_XACT (which tells you when the transaction was started - and fills in a valuable field named begin_time). There's also a LOP_COMMIT_XACT which fills in end_time.
In between those two records is the actual work which unfortunately doesn't have its own begin_time or end_time. So you can actually fill it in by doing a quick little program like this:

curls = "X"
ldb='x'
scan
if operation='LOP_BEGIN_XACT                 '
ldB = begin_time
curls = current_ls
else
if previous_l=curls and ISNULL(begin_time)
replace begin_time with ldb
endif
endif

endscan 

The current_ls is a unique identifier for the transactions. The Preview_l is really previous_ls but when you copy it to a table, you'll lose all of the nice field names.

At any rate, another key field I found was allocunitn which if you STRTRAN(allocunitn,CHR(0)), you'll find the name of the table that is being updated.

Then you can look specifically for rows with an Operation field of LOP_MODIFY_ROWS, LOP_INSERT_ROWS or LOP_DELETE_ROWS.

The final field that I found useful was at the end of the field list and is named log_recor3. This field has a bunch of binary data in it but when you look at it, you can see the data that is being modified or added.

I couldn't really figure out the best way to determine which field was being updated, except by looking at the data that was in there. If a field is being updated, it will show the OLD value and then the new value. For deletes, it shows the data it is deleting and for inserts, it shows the actual field values.

It would be great if it was documented somewhere - but I imagine this is one of those proprietary things for Microsoft. The strange thing for me though is why I was able to find it in the Transaction Logs but ApexLog couldn't. Go figure.

If you are working with SQL Server and have a need to look at the log, I hope this post helps - if you have some more ideas as to how to figure out what the heck is going on in there, let me know.

At the end of the day, it turned out it wasn't the SQL Update at all - the user had blanked out the value by accident and we weren't trapping for it. Four hours of trying read the gibberish of the SQL log - but hey! I found out I don't really need to spend the money on a log tool persay (Apex is about $600) because I could find it all with one little "undocumented" feature, that definitely deserves more page ranks because the noise when you search for Transaction log reading makes it harder to find the things you need.

Simple-Talk - transaction log

powered by performancing firefox