Let's start from a distance.

We support a busy database for a customer. Customer's requirement (in fact, state's requirement)  is that the database should have audit logs. This means that all important requests should be logged. These logs help both for the offline security analysis, and for the database health monitoring.

Before the end of the last year we used SQL Server 2005, and then customer has upgraded to SQL Server 2008 R2.

As by design the database is accessed through Stored Procedures only, so the logging was done using a small SP that traced input parameters and execution time. The call to that SP was inserted throughout the code of other SPs.

We expected SQL Server 2008 R2 to simplify the task, and to allow us to switch the audit on and off on a fine grained level without the need to change a SP in the production (see Understanding SQL Server Audit for details).

Unfortunatelly, we have almost immediately found that the current audit implementation traces SP calls but does not store parameter values. This way, you can see that there was a call "execute X @param1, @param2", but you have no idea what values were passed. Internet search shows that this a known problem (see SQL Server 2008 Database Audit on INSERT UPDATE and DELETE actual SQL and not parameter values), which renders SQL Server Audit useless.

But nevertheless, looking at how can we simplify our hand-made audit we have found a brilliant solution: "Light weight SQL Server procedure auditing without using SQL Server auditing". It's so simple, that it's a shame that we did not invent it ourselves! The approach is to insert or remove tracing code automatically. Indeed, there is nothing but data in the database, even the text of SP is only a data.

To automate it even more, we have defined a small table with names of procedures and their log levels, and have defined a procedure "Log.SetLevel @level" to configure all logging in one go. In addition we have simplified logging procedures and tables, and started to store parameters in xml columns rather than in a pipe-concatenated strings.

Now, to the negative SP execution times.

The logging code among other things measures current_timestamp at the begin and at the end of the execution of SP. This helps us (as developers) to monitor how database performs on a day to day basis, and to build many useful statistics.

For example we can see that the duration of about 10% of untrivial selects is 0ms (execution time is under 1ms). This means that SQL Server is good at data caching. But what is most interesting is that about 0.1% of requests have negative duration!

You could speculate on parallel or on out of order execution, but the paradox is resolved when you look closely on a value of duration. It's always around of -7,200,000ms. No one will assume that execution has ended two hours before it has started. So, what does it mean -2 hours? Well, we live in (UTC+02:00) Jerusalem time zone. We think that UTC offset crawls somehow into the result. To prove our hypothesis we would like to change time zone on sql servers, but customer won't agree on such an experiment.

This effect probably means that there is some hidden bug in SQL Server 2008 R2 that we cannot reliably reproduce, but we can see that the datediff(ms, start_timestamp, end_timestamp) may return negative value when it's known that start_timestamp is acquired before end_timestamp.

Update: What a shame. During tunning of the original logging procedures we have changed type from datetime to datetime2, and calls from GETUTCDATE() to current_timestamp, except one place (default value in the table definition) where it remained with GETUTCDATE().

So, negative durations meant operation timeout (in our case duration is greater than 30 secs).