Sql-server – Transaction log autogrowth duration

auto-growthsql-server-2012transaction-log

I am using event notifications to capture data and log file autogrowth events for all databases on my servers. I'm using the data to for analysis of database storage configuration.

In looking at the data I've noticed that the average duration for transaction log growth is well above anything I would expect which leads me to think that I'm either misinterpreting the data or overlooking something related to how transaction log autogrowth works.

This is an example of a log file growth event that was captured today:

<EVENT_INSTANCE>
  <EventType>LOG_FILE_AUTO_GROW</EventType>
  <PostTime>2013-08-29T11:14:26.447</PostTime>
  <SPID>97</SPID>
  <DatabaseID>32</DatabaseID>
  <NTDomainName />
  <HostName>[cleansed]</HostName>
  <ClientProcessID>4884</ClientProcessID>
  <ApplicationName>.Net SqlClient Data Provider</ApplicationName>
  <LoginName>[cleansed]</LoginName>
  <Duration>4173000</Duration>
  <StartTime>2013-08-29T11:14:22.263</StartTime>
  <EndTime>2013-08-29T11:14:26.437</EndTime>
  <IntegerData>64000</IntegerData>
  <ServerName>[cleansed]</ServerName>
  <DatabaseName>MyDB</DatabaseName>
  <FileName>MyDB_log</FileName>
  <LoginSid>[cleansed]</LoginSid>
  <EventSequence>14637017</EventSequence>
  <IsSystem />
  <SessionLoginName>[cleansed]</SessionLoginName>
</EVENT_INSTANCE>

Since duration is reported in miliseconds I'm reading this as it taking 69.54 minutes to grow the file. Autogrowth for this log file is set to 512MB (limited to 2TB)

SELECT
    growth AS GrowthPages,
    growth*8/1000 AS GrowthMB,
    max_size,
    is_percent_growth
FROM MyDB.sys.database_files
WHERE type=1

GrowthPages GrowthMB        max_size        is_percent_growth
64000       512             268435456       0

All of the databases log to the same volume which is connected to a SAN via fiberchannel. (I'd have to get with our SAN admin for more details on the storage config if needed).

The instance is SQL 2012 Enterprise, server is Windows 2008 R2 Enterprise.

Why would it take over an hour to grow the log by 512MB? We're not noticing a delay in operations on any of these databases (unless we're just overlooking it). There are a handful of other databases with similar duration; their autogrowth settings are the same. Other databases with smaller autogrowth settings have proportionally smaller durations.

Best Answer

You're looking at SQL Trace. Extended Events records duration in microseconds (though some data is reported in milliseconds, duration isn't affected). You can see that the event took less than 5 seconds:

<StartTime>2013-08-29T11:14:22.263</StartTime>
<EndTime>2013-08-29T11:14:26.437</EndTime>

And also just to confirm (though it's off a bit due to millisecond rounding in the datetime data type):

SELECT DATEDIFF(MICROSECOND,'2013-08-29T11:14:22.263','2013-08-29T11:14:26.437');

----------
4174000
Related Question