SQL Profiler 2008 and SQL Profiler 2008 R2 are subtly different, while R2 respects the datetime precision the older version does not and spuriously appended 3 decimal places which sent me down the wrong path for far too long… what a crazy waste of time that was
I know that writing a post in anger is rarely the best approach, but I’ve just lost a good hour or so of my life to this problem so I’m venting a little… forgive me. What’s annoyed me you ask? Well are you sitting comfortably… then I’ll begin.
My story starts with me trying to debug a login page, the project I’m working on has just been converted to use ASP.NET Authentication
the login works for me on my machine and on our integration server and on our production server, it even works on the client’s development and UAT servers. However when the client has been trying to login the page simply reloads – that got a great big WFT from me. So I started chucking lots of debugging output into the code, nothing fancy just Response.Write in every method and before and after every branching statement, commented out the line of code that requested the next page and tested. Unsurprisingly I saw all my debugging written out to screen. I was again surprised when the client said they didn’t get any of that. So next I cracked open SQL Server Profiler and captured the database calls.
Now it’s at this part that the story really begins; I captured all the calls and then began to replay them to try to figure this problem out. I got to one of the .Net calls and was rather shocked to see it throw an error.
exec dbo.aspnet_Membership_GetUserByName @ApplicationName=N'My App',
@UserName=N'TEST@abc.com',@UpdateLastActivity=1,
@CurrentTimeUtc='2012-04-11 09:57:35.7400000'
This threw the following error:
Msg 8114, Level 16, State 1, Procedure aspnet_Membership_GetUserByName, Line 0
Error converting data type varchar to datetime.
After I got over the fact that this was built in, untampered with code and that I had to do something about it I looked again at the @CurrentTimeUtc value – it seemed quite long, when I trimmed off the ‘.740000’ or just trimmed 3 of the ‘0’s off the sql ran fine. Ok great, maybe the failure to login was because these database calls were not returning any results.
Next I ran the login on my local machine and was not particularly surprised to see that the date was shorter '2012-04-11 10:30:28.157' and it ran without any problems. The websites were set up the same way, using the same version of .Net 2 Integrated, so what was causing the extra precision on the datetime on the client?
Nothing was, actually the sql ran fine because I tested it by writing out the results of the calls to the browser. The problem was that SQL Profiler 2008 was interpreting the call and extending the precision of the date parameter, when I’d captured the calls locally I was using SQL Profiler 2008 R2 I have both 2008 and 2008 R2 installed but only 1 instance of Profiler). What annoyed me is this difference in behaviour, as I said at the top I lost time to this. I had been sent on a wild goose chase and yes that annoyed me to write this post!
The take away from this is that while the profilers may be helpful there is no substitute for actually seeing the results that are returned to your calling code. Yes we should be able to rely on the profilers to capture this without reinterpreting it for you… but you just can’t trust them 
db71bfd1-fb82-4e19-9d41-8f4d33a47e91|0|.0
Tags: SQLProfiler |
Categories: ASP.NET | Rant | SQL