Hello GETDATE() My Old Friend...

Andy Levy

2015-06-16

So you’ve decided that your new web application needs to record some page load time metrics so you can keep tabs on performance. Terrific! You set up a couple page load/complete functions to write to a logging table when a page request comes in, and then update the record when it finishes loading.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18


INSERT INTO PageLogs (
  RequestTime
  ,ResponseTime
  ,RemoteIP
  ,UserName
  ,PageId
  ,Parameters
  ,SessionId
)
VALUES (
  GETDATE()
  ,NULL
  ,127.0.0.1
  ,'Dave'
  ,'Home'
  ,'Pd=2015Q2'
  ,'883666b1-99be-48c8-bf59-5a5739bc7d1d'
);

1
2
3
4


UPDATE PageLogs
  SET ResponseTime = GETDATE()
  WHERE
    SessionId = '883666b1-99be-48c8-bf59-5a5739bc7d1d';

You set up an hourly job to delete any logs older than 2 weeks (just to prevent information overload) and you call it a day. Each morning, you run a report to look at the previous day’s performance, watch the trends over the past week or so, and you’re pretty happy with things. Pages are loading in a fraction of a second, according to the logs. People find the application useful, word spreads around the office, and adoption takes off. The project is a success!

Then the support calls start rolling in. Users say it’s taking “forever” to load pages (they don’t have exact numbers, but it’s just too slow). This can’t be possible. The report says everything’s running just as fast as it did in test!

You walk down the hall and visit your friendly Senior DBA. He pulls up his monitoring tools and shows you that the hourly maintenance that keeps the PageLogs table fit & trim is causing a bunch of blocking while it does lots of DELETEs. And your INSERT queries are the victims.

Here’s the thing: GETDATE() (like any other function) doesn’t get evaluated until that query executes. Not when you call ExecuteNonQuery(), not even when SQL Server receives the query. So even if your INSERT isn’t holding up the execution of your page (because you’ve executed it asynchronously), it won’t accurately represent when the page load started. Instead, it tells you when your query executed. In this context that can be misleading because it won’t tell you how long it really took for your page to load.

If you need to log the time an event transpired accurately, GETDATE() isn’t your friend. You need to explicitly set the time in the query.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17


INSERT INTO PageLogs (
  RequestTime
  ,ResponseTime
  ,RemoteIP
  ,UserName
  ,PageId
  ,Parameters
  ,SessionId
) VALUES (
  '2015-05-15T09:45:00Z'
  ,NULL
  ,127.0.0.1
  ,'Dave'
  ,'Home'
  ,'Pd=2015Q2'
  ,'883666b1-99be-48c8-bf59-5a5739bc7d1d'
);

1
2
3
4


UPDATE PageLogs
  SET ResponseTime = '2015-05-15T09:45:02Z'
  WHERE
    SessionId = '883666b1-99be-48c8-bf59-5a5739bc7d1d';

If you aren’t used to seeing significant blocking in your databases, you may not have run into this. But get into this habit anyway. At some point you probably will see blocking on a table like this, and logging with GETDATE() will make the data you attempted to write during that blocking invalid. If you can’t trust all of your data, can you trust any of it?