SQL Server 2008 R2 logging query execution times incorrect

Question

EDIT: I added all of the code for the logon trigger.

Why am I getting some incorrect results when trying to retrieve the total time it takes for a query to run? This is within the context of a logon trigger on SQL Server 2008 R2.

For testing purposes, I want to get the a rough estimate of the total time it takes for a logon trigger to run. Here is a small sample of the results:

LogonId  AppId  TotalLogonTime (in MS)
 101      1        0
 253      2        3
 289      2        3
 985      1       -3
 325      1        0

How can the total time evaluate to be negative? Out of the 2.3 million executions so far, there have been 25 that resulted in a time of -3 ms. Here is the code:

CREATE trigger [trgAudit]
on all server
with execute as 'TriggerLogonUser'
for logon
as
begin
    set nocount on
    set transaction isolation level read committed

declare
     @LoginTime datetime
    ,@IsWindowsUser bit
    ,@TotalLogonTimeMS int
    ,@ClientNetAddress varchar(48)
    ,@MacAddress nchar(12)
    ,@CurrentUserId int -- UserNames
    ,@ApplicationId int
    ,@HonId int --HostName
    ,@LogonId int --Logon
    ,@MacId int -- MacAddress
    ,@CnaId int -- ClientNetAddress

begin try
    /*
    *** Get the login time, user type, mac address, and client net address  
    */
 select
      @LoginTime = getdate(),
      @IsWindowsUser = case
                          when len(nt_domain) = 0
                             then 0
                          else 1
                       end,
      @MacAddress = p.net_address,
      @ClientNetAddress = convert(varchar(48),connectionproperty('client_net_address'))
 from sys.sysprocesses p
 where 
      p.spid = @@spid

 /*
 *** Client Net Address
 */          
      select top 1
           @CnaId = CnaId
      from master.sysmaintenance.ClientNetAddress with(index(IX_CnaAddress))
      where @ClientNetAddress = CnaAddress

      --if the ip does not exist, insert it.
      if @CnaId is null
           begin
                insert master.sysmaintenance.ClientNetAddress(CnaAddress)
                     values (@ClientNetAddress)
                select @CnaId = @@identity
           end

 /*
 *** Applications
 */     
      select top 1
           @ApplicationId = AppId
      from master.sysmaintenance.Applications with(index(IX_AppName))
      where app_name() = AppName

      if @ApplicationId is null
           begin
                insert master.sysmaintenance.Applications (AppName)
                     values (app_name())
                select @ApplicationId = @@identity
           end

 /*
 *** HostName
 */     
      select top 1
           @HonId = HonId
      from master.sysmaintenance.HostName with(index(IX_HonName))
      where HonName = host_name()

      if @HonId is null
           begin
                insert master.sysmaintenance.HostName
                     values (host_name())

                select @HonId = @@identity
           end

 /*
 *** UserNames
 */     
      select top 1
           @CurrentUserId = UsnId
      from master.sysmaintenance.Usernames with(index(IX_UsnName))
      where UsnName = original_login()

      if @CurrentUserId is null
           begin
                insert master.sysmaintenance.Usernames
                     values (original_login())

                select @CurrentUserId = @@identity
           end

 /*
 *** MacAddress
 */     
      select top 1
           @MacId = MacId
      from master.sysmaintenance.MacAddress with(index(IX_MacAddress))
      where MacAddress = @MacAddress

      -- same logic is continued as in the applications
      if @MacId is null
           begin
                insert master.sysmaintenance.MacAddress (MacAddress)
                     values (@MacAddress)

                select @MacId = @@identity
           end

 /*
 *** Get the total logon time
 */     
 select @TotalLogonTimeMS = datediff(ms,@LoginTime, getdate())

  -- insert ids of the data gathered on the logon event into the logon table.


           insert master.sysmaintenance.Logon ( LogAppId,
                                                LogHonId,
                                                IsWindowsLogon,
                                                CurrentLogonId,
                                                LogonDatetime,
                                                LogCnaId,
                                                LogMacId,
                                                LogonTimeMS )
                values ( @ApplicationId,
                         @HonId,
                         @IsWindowsUser,
                         @CurrentUserId,
                         @LoginTime,
                         @CnaId,
                         @MacId,
                         @TotalLogonTimeMS
                       )
end try

begin catch
    print cast(error_number()    as nvarchar(11))
    print cast(error_severity()  as nvarchar(11))
    print cast(error_state()     as nvarchar(11))
    print cast(error_procedure() as nvarchar(126))
    print cast(error_line()      as nvarchar(11))
    print cast(error_message()   as nvarchar(2048))
end catch
end

Here is the DDL to the Logon Table:

CREATE TABLE [sysmaintenance].[Logon](
    [LogonId] [bigint] IDENTITY(1,1) NOT NULL,
    [LogAppId] [int] NULL,
    [LogHonId] [int] NULL,
    [LogMacId] [int] NULL,
    [LogCnaId] [int] NULL,
    [IsWindowsLogon] [bit] NULL,
    [CurrentLogonId] [int] NULL,
    [LogonDatetime] [datetime] NULL,
    [LogonTimeMS] [int] NULL
) ON [PRIMARY]

CREATE UNIQUE CLUSTERED INDEX [PK_Logon] ON [sysmaintenance].[Logon] 
(
    [LogonId] ASC
)WITH (PAD_INDEX  = OFF, STATISTICS_NORECOMPUTE  = OFF, SORT_IN_TEMPDB = OFF, IGNORE_DUP_KEY = OFF, DROP_EXISTING = OFF, ONLINE = OFF, ALLOW_ROW_LOCKS  = ON, ALLOW_PAGE_LOCKS  = ON) ON [PRIMARY]

Any help or insight is appreciated.

Answer 1

GETDATE():

Returns the current database system timestamp as a datetime value without the database time zone offset. This value is derived from the operating system of the computer on which the instance of SQL Server is running.

Now, bearing in mind that computer clocks drift, I'd imagine that if the computer's time was corrected (either manually or automatically), the time reported by two successive calls to GETDATE() (that aren't part of a single query) could go backwards. All of the datetime methods ultimately rely on the computer's clock.

It's a shame you're not logging one of these GETDATE() results alongside the timing, so you could see if they all occurred at the same "time".