Category Archives: Did you know

Get your log shipping restore to run faster

Posted on by

Recently I was working on a customer environment where the requirement was to use a log shipped secondary database for reporting purposes. The catch here was that the restore of all the transaction log backups needed to complete within a fixed time.

Right at the outset, I would like to point out that the restore of transaction logs are dependent on a number of parameters like disk subsystem performance, number of transactions present in the log backup, resource availability on the server where the restore is occurring. Considering that all the factors remain constant, there is a basic difference between a secondary log shipped database in No Recovery and in Standby mode. In Standby mode, a partial recovery is done with the help of a transaction undo file to get the database into a read-only state. This partial recovery operation and undo that occurs while performing the next log restore (with the use of the transaction undo file) requires time and resources and can slow down the time of restore for each transaction log backup that is restored on the secondary database, especially if there are resource contention issues on the server. In this blog post, I shall outline how you can workaround the same in case you have to meet strict restore time SLAs.

Continue reading →

Advertisement

Hello Analytic Functions

Posted on by

SQL Server 2012 CTP 3, formerly known as SQL Server Code Name “Denali”, introduces a new set of T-SQL functions called Analytic functions. Analytic functions now open up a new vista for business intelligence where in you can calculate moving averages, running totals, percentages or top-N results within a group. I find this very useful while analyzing performance issues while traversing information present in a SQL Server trace file.

I was looking into a performance issue where in an application module executing a series of T-SQL functions was taking a long time to complete it’s operation. When I looked into the total duration of the T-SQL queries executed by the application, I couldn’t account for the total duration that the application was reporting. On tracking some of the statement executions done by the SPID which was being used by the application to execute the queries, I found a difference between the start time of a batch and the completed time of the previous batch. Now I needed to see the complete time difference between two subsequent query completion and start accounted for the difference in duration that I was seeing between the duration reported by the application and sum of duration of all the queries executed by the application. And BINGO… I was finally able to make the co-relation. Till SQL Server 2008 R2, I would have to write a query which involved a self-join to get the comparative analysis that I required:

;WITH cte AS
(SELECT b.name, a.starttime, a.endtime, a.transactionid, a.EventSequence, ROW_NUMBER() OVER(ORDER BY eventsequence) AS RowIDs
FROM trace a
INNER JOIN sys.trace_events b
ON a.eventclass = b.trace_event_id
WHERE spid = 83
AND b.name IN ('RPC:Starting','RPC:Completed','SQL:BatchStarting','SQL:BatchCompleted'))
SELECT TOP 1000 b.name, b.starttime, b.endtime, b.transactionid, DATEDIFF(S,a.endtime,b.starttime) as time_diff_seconds
FROM cte a
LEFT OUTER cte b
ON a.RowIDs = b.RowIDs-1

The output of the above query is shown in the screen shot below:

image

As you can see that there is a 4-second delay between the endtime of the statement in Row# 783 and the next execution shown in Row# 784. With the help of Analytic functions, I can simply use the LEAD function to get the above result and avoid a self-join.

SELECT  TOP 1000 a.name,b.StartTime,b.EndTime,b.TransactionID,
DATEDIFF(s,(LEAD(b.EndTime,1,0) OVER (ORDER BY EventSequence DESC)),b.StartTime) as TimeDiff
FROM sys.trace_events a
INNER JOIN dbo.trace b
on a.trace_event_id = b.EventClass
WHERE b.SPID = 83
and a.name in ('RPC:Starting','RPC:Completed','SQL:BatchStarting','SQL:BatchCompleted')

The output as you can see is the same the previous query:

image

I had imported the data from the profiler trace into a SQL Server database table using the function: fn_trace_gettable. Let’s see what the query plans look like. For the first query which uses the common table expression and a self-join, the graphical query plan is as follows:

image

Now let’s see what the query plan looks like with the new LEAD function in action:

image

As you can see above a new Window Spool operator is the one which performs the analytical operation to calculate the time difference between the subsequent rows using the EventSequence number. As you can see that I have eliminated the need for a self-join with a temporary table or a common table expression and therefore simplifying my query in the process.

In the above example I am using the LEAD function to get value that I am interested in the following row. If you are interested in the values from a preceding row then you can use LAG function.

One gotcha that you need to remember here is that if you don’t take care of the start and end values of the dataset which you are grouping, you could run into the following error due to an overflow or underflow condition.

Msg 535, Level 16, State 0, Line 1
The datediff function resulted in an overflow. The number of dateparts separating two date/time instances is too large. Try to use datediff with a less precise datepart.

This is a small example of how analytic functions can help reduce T-SQL complexity when calculating averages, percentiles for grouped data. Happy coding!!

Disclaimer: This information is based on the SQL Server 2012 CTP 3 (Build 11.0.1440), formerly known as SQL Server Code Name “Denali” documentation provided on MSDN which is subject to change in later releases.

Performance benchmarking: Explicit vs Implicit Transactions

Posted on by
imageBenchmarking… The single most important word in Performance Tuning. Without an established benchmark, you really don’t know when to actually call it a day!

If you have ever worked in testing on database projects, you would have probably done testing by trying to narrow down the data set involved which is nearly representative of the actual production data set or used a sub-set of the queries which are representative of the workload which is expected or is active on the production environment.

Now this brings me to the reason of this post. It is quite often during testing that we forget that SQL Server executes all DML operations by default in autocommit mode. This means that all individual statements are committed if they complete successfully. If you want to avoid this behavior, then you either need to set IMPLICIT_TRANSACTIONS setting to ON for your database connection or use a BEGIN TRANSACTION command before you execute your query.

SQL Server follows Write Ahead Logging protocol which means no data modifications are written to disk before the associated log record is written to disk. This maintains the ACID properties for a transaction. (when you involve disk-caching, that opens up another can of worms but that discussion is outside the scope of this blog post)

My belief is that if you are comparing execution times between two different environments, then you should be doing that on exactly the same hardware configuration and if that is not feasible, you should at-least match the CPU, physical RAM and disk sub-system on both sides. I had already documented in an earlier blog post why RAM/CPU configurations are important when comparison execution statistics between two different SQL Server environments. Ideally, you should have the same exact environment as your test environment including the workload (i.e. number of users, connections etc.). However, we all know that Utopia is not a place where we live in and hence the toned down test scripts, scaled down/up environments, shared resources and I could keep lamenting!!

In the last month, I dealt with two such issues where in a T-SQL batch performing a large number of inserts on a database table was being used to compare the performance between two different environments. Since I get called in to fix a problem and no-one generally calls CSS to tell us that their server is running as expected… the problem invariably happened to be that a bigger, beefier server was taking a longer time to execute the same batch. I shall demonstrate where not knowing about the WAL protocol can cause such test mechanisms to be skewed and take you down the proverbial rabbit-hole!

The script that I shall be using for demonstrating the pitfalls of this behavior is pretty simple:

declare @cntr int = 1
while @cntr <= 1000000
begin
insert into tblInserts (SNo,RowVal) values(@cntr,’Record ID ‘ +CAST(@cntr as varchar(7)))
set @cntr += 1
end

The script inserts 1 million rows into a database table (a heap table) using a while loop. During the time of the insert, I shall capture various performance counter values during the execution along with wait statistics for the query.

Modification: September 9th, 2011: Based on Kendra’s (Twitter) feedback, changing the sub-headings. Test 1 makes use of auto-commit mode of SQL Server which is the default and Test 2 can be achieved either by using implicit transaction mode or performing an explicit transaction (BEGIN…COMMIT).

Test 1: With AutoCommit mode

For two iterations the above script on an average took 8 minutes and 30 seconds to complete. When I looked into the wait statistics captured (at 5 second intervals), I don’t see anything standing out other than a few non-zero wait durations for WRITELOGs during certain periods. The non-zero wait times (in milli-seconds) are shown below with the highest value being captured being 10 milli-seconds. The Average Disk Secs/(Read/Write) don’t show me any outstanding values during the data capture to indicate that the disk was a bottleneck, then why does the data below show so many WRITELOG waits. Keep in mind that the total amount of time waited for as indicated by the data below is also not a significantly large amount. So why is it taking over eight minutes to insert the data??image

Runtime Session_id Status Wait_type Wait_time Last_Wait_Type
12:46 AM 51 suspended WRITELOG 10 WRITELOG
12:46 AM 51 suspended WRITELOG 7 WRITELOG
12:47 AM 51 suspended WRITELOG 1 WRITELOG
12:47 AM 51 suspended WRITELOG 2 WRITELOG
12:47 AM 51 suspended WRITELOG 3 WRITELOG
12:47 AM 51 suspended WRITELOG 2 WRITELOG
12:48 AM 51 suspended WRITELOG 7 WRITELOG
12:49 AM 51 suspended WRITELOG 8 WRITELOG
12:49 AM 51 suspended WRITELOG 1 WRITELOG
12:49 AM 51 suspended WRITELOG 10 WRITELOG
12:49 AM 51 suspended WRITELOG 6 WRITELOG
12:50 AM 51 suspended WRITELOG 2 WRITELOG
12:51 AM 51 suspended WRITELOG 3 WRITELOG
12:51 AM 51 suspended WRITELOG 4 WRITELOG
12:51 AM 51 suspended WRITELOG 1 WRITELOG
12:51 AM 51 suspended WRITELOG 2 WRITELOG
12:52 AM 51 suspended WRITELOG 5 WRITELOG
12:52 AM 51 suspended WRITELOG 7 WRITELOG
12:53 AM 51 suspended WRITELOG 1 WRITELOG
12:53 AM 51 suspended WRITELOG 8 WRITELOG

To explain the query, I would need to fall back of SQL Server Performance Monitor counters (sampled at 5 second intervals). On analysis of the performance monitor counters, I found the following:
a. SQLServer:Databases: Log Bytes Flushed/sec showed that on an average 3.1 MB of log bytes were being flushed every 5 seconds for the database on which I was performing the inserts.
b. SQLServer:DatabasesLog Flushes/sec showed that about 6000 log flushes were occurring for this database every 5 seconds on an average.
c. SQLServer:Wait Statistics: Log write waits shows me that on an average there were about 9000+ waits started per second. However, the Cumulative wait time (ms) per second for the same counter shows me negligible values and the Average wait time (ms) value is nearly zero through the data collection period.

So how can I explain where the time is being spent?? Now I decided to run another test using implicit transactions.

imageTest 2: Without AutoCommit mode

I ran two iterations of the above T-SQL batch within BEGIN TRANSACTION…COMMIT block and the average duration was 14 seconds! Whattttt!??!?! Yes.. And all this can be simply explained using the same counters that I looked above. This time around the performance monitor data told me the following story:
a. SQLServer:Databases: Log Bytes Flushed/sec showed that on an average 26 MB of log bytes were being flushed every 5 seconds for the database on which I was performing the inserts.
b. SQLServer:DatabasesLog Flushes/sec showed that about 468 log flushes were occurring for this database every 5 seconds on an average.
c. SQLServer:Wait Statistics: Log write waits shows me that on an average there were about 23(approx.)+ waits started per second.

If you look at the Performance Monitor graphs for the disk statistics that I captured for a single run for Test 1 (screenshot above) and Test 2 (screenshot on the left), you will see that the %Idle Time for the disk, on which the database files resided on (in my case F: drive), shows was busy 50% of the time (see blue squiggly above) during the test and the value climbed back to ~100% after the test completed. On the contrary, the %Idle Time for the same disk has a very zig-zag pattern (see black squiggly on left) during Test 2 which indicates that the disk was sporadically busy and it was not a continuous pattern as observed in Test 1.

The Avg. Disk Sec/Write counter shows absolutely no latency which means that the there is no problem in terms of latency on the disks.

During Test 1, data was being written to the disk at the rate of 907 KB/s where as during Test 2, the write rate was 5MB/s which was determined by monitoring the Disk Write Bytes/sec counter.

The reason for this difference is that for every insert in Test 1 is followed by an autocommit. This means that you need to flush the log buffer for each insert. However in Test 2, the log buffer was being flushed much lesser but at the same time more data was being written to the disk for each log flush. Since SQL Server follows a WAL protocol, till the earlier log flush is completed, it cannot commit/move onto the next transaction.

If you are running a similar system with two different sets of hardware, then you would start having to chase down disk speeds/RPMs between the two servers. For servers which have disks performing optimally, this behavior is quite difficult to gather without the right set of data.

With SQL Server 2008, tracking down the waits for a single session is much, much easier with the help of XEvents. But that shall be a story for another day… errrr.. post!!

Moral of the story: If you are using a test query similar to the one shown above to test/benchmark performance and the query batch is not indicative of your actual workload, then you would probably not be able to gauge or establish an accurate performance benchmark for the queries executing on your system. And REMEMBER that SQL Server runs in auto-commit mode by default!

HAPPY TESTING! Smile

PREEMPTIVE_OS_GETPROCADDRESS: Are you confusing me?

Posted on by

PREEMPTIVE_OS_GETPROCADDRESS is a new wait type that was introduced in SQL Server 2008 to track time taken by GetProcAddress to load the entrypoint in the DLL when Extended Stored Procedure calls are made by the SQL Server instance. However, the way the wait time is tracked by this wait type has a little quirk which Rob Dorr had documented in a blog post.

Based on a discussion on #sqlhelp thread on Twitter, I found the need to demonstrate this unique quirk with the help of an example. I am using the following command to list you the sub-directories on my C: drive using the command:

exec master..xp_dirtree ‘C:\’

Next I monitored the wait statistics for the session executing this Extended Stored procedure using the T-SQL script below with a 1 second delay:

SET NOCOUNT ON
WHILE (1=1)
BEGIN
SELECT [session_id], [status], [command], [start_time], [cpu_time], [reads], [writes], [wait_resource], [wait_time], [last_wait_type], [wait_type]
FROM sys.dm_exec_requests
WHERE [session_id] = 53 -- Session ID that is executing the Extended Stored Procedure

WAITFOR DELAY '00:00:01'
RAISERROR ('', 10, 1, N'Waits');

END

The output of this script was as follows:

session_id status        command          start_time              cpu_time    reads    writes      wait_time   last_wait_type                        wait_type

53         runnable      EXECUTE          2011-07-20 00:59:44.330 62          0        0           712         PREEMPTIVE_OS_GETPROCADDRESS          PREEMPTIVE_OS_GETPROCADDRESS

53         running       EXECUTE          2011-07-20 00:59:44.330 234         0        0           1713        PREEMPTIVE_OS_GETPROCADDRESS          PREEMPTIVE_OS_GETPROCADDRESS

53         runnable      EXECUTE          2011-07-20 00:59:44.330 452         0        0           2714        PREEMPTIVE_OS_GETPROCADDRESS          PREEMPTIVE_OS_GETPROCADDRESS

As you can see above the wait time keeps increasing even though I can see that the session is performing work due to the following results:
a. The results window in SSMS for the session executing the extended stored procedure was churning out results
b. Using a Process Monitor, I could trace the filesystem activity on the C: drive for the SQL Server process

You could run into this issue while using any Extended Stored Procedure (system or user) for a SQL Server 2008 or SQL Server 2008 R2 instance. Since I know that the session is performing work, the only two other things that I would check if there are resource bottlenecks w.r.t. memory or I/O if some filesystem related activity is being performed by the extended stored procedure. Most of the issues where I have see this wait type causing confusion is when the extended stored procedure is performing disk related activity. At that time, Process Monitor will put your doubts to rest along with the information that I mentioned above to confirm that that the procedure is actually doing some work and not stuck or perceived as “hung”.

Statistics Auto Update may not be automatically the best choice

Posted on by

I had written a post a while back stating how DBREINDEX and ALTER INDEX treat the statistics update differently for user and auto-created statistics on a database table. In this post, I shall talk about how auto-update statistics which normally is left ON on most databases that I have worked on can sometimes choose to play “spoil sport” for the all important cardinality estimation during the plan generation phase. The auto-update statistics option of a database affects all table statistics: index, user created and auto-created.

As usual, my favorite way to illustrating a SQL Server behavior is to use an example. I created a table with two integer columns and inserted a million rows in the table. There are two indexes on the table: a clustered index on the primary key (column a) and a non-clustered index on the second column (column b). The DBCC SHOW_STATISTICS output for the index on column b has the following output:

Name         Updated              Rows                 Rows Sampled
idx_b        Jul  8 2011  6:34AM  1000000              482999              

If you look at the data above, you will notice that the rows and rows sampled have a difference which means that the statistics were updated with a less than a 100% sampling. There are only 3 distinct values for this particular column. The following query returned 26,000 rows but the estimated rows was way off.

select a,b from dbo.tblStats where b = 4

Plan snippet:

Rows      EstimateRows
26000     2952.387

Now when I updated the statistics with a fullscan on the table and generated a new plan for the same query and…. voila…. I have the correct estimate rows and the histogram also shows me the correct data distribution. In my scenario, I had 400,000 records in the table after which I ran a WHILE loop to insert 600,000 additional records in the table. Till then the statistics were updated with a fullscan. After that an auto-update statistics messed up the sampling rate. This is because when auto update statistics kicks in it uses a very small percent as the default sampling rate used is a function of table size. This means that larger the table, the lower the sampling percentage will be. Now this is not necessarily a bad thing. Eg. If an auto stats operation kicks in during a query execution and auto update stats asynchronously is not set for the database, you don’t want the statistics update operation to sample the entire table, update the statistics histogram and then execute the query. So the default sampling functionality allows for quick statistics gathering even for large tables. The default sampling is used even when a CREATE STATISTICS command is executed on the table.

Now why is this important to be aware when designing your statistics update strategy for VLDBs or OLTP environments. The queries in production environments can involve JOIN operations and other complex constructs which means that the cardinality estimation of the rows to be fetched will determine which operator is to be used. Over and under estimating can prove detrimental to the performance of query plan.

Moral of the story: Statistics for a table need to be updated with a fullscan if there have been a significant number of changes made to the table data.

The frequency of statistics update would have to be determined based on the number of updates that your frequently used tables receive and when the instance has some free time to handle the statistics update operations. This is the famous “It Depends” answer. Even though it is an online, it does consume resources and can potentially cause blocking when the scan is being done on the table to figure out the data distribution. It is not always required to rebuild indexes to update statistics. Read the Books Online article “Using Statistics to Improve Query Performance” for multiple options like Asynchronous Statistics Update, NoRecompute option etc. and how they can be pertinent to your situation in case you have large databases where statistics update cannot be done very frequently.

Do not go by the row modification counter value starting from SQL Server 2005 as the statistics updates are handled based on column modification counters than row modifications.

There are edge-case scenarios where a 100% sampling might not be best choice because of a skew in data distribution, but that is a story for another day!

My colleague Jack wrote some posts on interesting issues that he ran into with data distribution in table and the statistics sampling:
Parallel Index Creation performance issue
http://blogs.msdn.com/b/psssql/archive/2009/03/18/be-aware-of-parallel-index-creation-performance-issues.aspx
Why does this query consumes so much CPU?
http://blogs.msdn.com/b/psssql/archive/2011/04/29/why-does-this-query-consumes-so-much-cpu.aspx
Sampling can produce less accurate statistics if the data is not evenly distributed
http://blogs.msdn.com/b/psssql/archive/2010/07/09/sampling-can-produce-less-accurate-statistics-if-the-data-is-not-evenly-distributed.aspx

Reference:
Statistics used by the Query Optimizer in SQL Server 2005
http://technet.microsoft.com/en-us/library/cc966419.aspx