OLEDB waits in #SQLServer checktable Part I - Disappearing Act

Let's finally start looking at behavior surrounding the OLEDB wait type during checktable operations.  These tests, as previously, are running on an 8 vcpu Windows server 2012 R2 vm (VMware) with SQL Server 2016 SP1.

Since I plan to do a lot of testing, create a table to store some test definitions and results.

DROP TABLE IF EXISTS oledb_wait_test;

CREATE TABLE oledb_wait_test
(test_id      INT,
 captured     NVARCHAR(256),
 capture_time DATETIME,
 spid         INT,
 tableName    NVARCHAR(256), 
 [maxdop]     INT,
 physicalonly NVARCHAR(1),
 [tablock]    NVARCHAR(1),
 wait_type    NVARCHAR(256),
 ows_wait_ct  BIGINT,
 ows_wait_ms  BIGINT,
 sws_wait_ct  BIGINT,
 sws_wait_ms  BIGINT
 CONSTRAINT pk_oledb_wait_test PRIMARY KEY CLUSTERED (test_id, captured))
 WITH (data_compression = page);

OK. Let's create a very basic heap to submit to checktable operations.

CREATE TABLE OLEDB_TEST_HEAP
([num] BIGINT,
 [str] NVARCHAR(4000));


DECLARE @str NVARCHAR(max);
SET @str = REPLICATE ('A', 4000);

/*for 80 * 80 = 6400 rows OLEDB_TEST_HEAP will allow parallel checktable with physical_only
  for 79 * 79 = 6249 rows OLEDB_TEST_HEAP will only run checktable with physical_only in serial
*/
;WITH cnum(num) AS
(SELECT TOP (80) 1 FROM sys.columns)
INSERT INTO OLEDB_TEST_HEAP
SELECT row_number() OVER (ORDER BY (SELECT NULL)),
@str
FROM cnum c1
CROSS JOIN cnum c2;

Its really, really easy for me to skip a detail like coalescing NULL values in wait tables to zero in order to get valid deltas... so lets encapsulate the test and results capture in a stored procedure.

Here's my simple stored procedure:

• take parameters for a checktable operation
• record the parameters and tare OLEDB wait values from system and session levels
• execute dynamic SQL for checktable operation
• record system and session level OLEDB wait values after checktable completion

CREATE OR ALTER PROCEDURE CHECKTABLE_OLEDB_WAIT_TEST 
(@tableName NVARCHAR(256), @MAXDOP INT = 8, 
 @PhysicalOnly NVARCHAR(1) = 'Y', @TABLOCK NVARCHAR(1) = 'N')
AS

DECLARE @dynSQL NVARCHAR(1000);
DECLARE @testID INT;

SELECT @testID = COALESCE(max(test_Id), 0) + 1
FROM   oledb_wait_test;

SET @dynSQL = N'DBCC CHECKTABLE ([' + @tableName + ']) WITH MAXDOP = ' 
              + CONVERT(NVARCHAR(2), @MAXDOP) 
              + CASE WHEN @PhysicalOnly = N'Y' THEN N', PHYSICAL_ONLY' ELSE '' END
              + CASE WHEN @TABLOCK = N'Y' THEN N', TABLOCK' ELSE '' END
     + ';';

INSERT INTO oledb_wait_test
SELECT @testId       AS test_Id,
       'BEFORE'      AS captured,
       getdate()     AS capture_time,
       @@spid        AS spid,
       @tableName    AS tableName, 
       @MAXDOP       AS [maxdop],
       @PhysicalOnly AS physicalonly,
       @TABLOCK      AS [tablock],
       ows.wait_type AS wait_type,
       COALESCE(ows.waiting_tasks_count, 0) AS ows_wait_ct,
       COALESCE(ows.wait_time_ms, 0)        AS ows_wait_ms,
       COALESCE(sws.waiting_tasks_count, 0) AS sws_wait_ct,
       COALESCE(sws.wait_time_ms, 0)        AS sws_wait_ms
FROM   sys.dm_os_wait_stats ows
LEFT OUTER JOIN
       sys.dm_exec_session_wait_stats sws
ON     sws.wait_type  = ows.wait_type
AND    sws.session_id = @@spid
WHERE  ows.wait_type  = 'OLEDB';

EXEC (@dynSQL);

INSERT INTO oledb_wait_test
SELECT @testId       AS test_Id,
       'AFTER'       AS captured,
       getdate()     AS capture_time,
       @@spid        AS spid,
       @tableName    AS tableName, 
       @MAXDOP       AS [maxdop],
       @PhysicalOnly AS physicalonly,
       @TABLOCK      AS [tablock],
       ows.wait_type AS wait_type,
       COALESCE(ows.waiting_tasks_count, 0) AS ows_wait_ct,
       COALESCE(ows.wait_time_ms, 0)        AS ows_wait_ms,
       COALESCE(sws.waiting_tasks_count, 0) AS sws_wait_ct,
       COALESCE(sws.wait_time_ms, 0)        AS sws_wait_ms
FROM   sys.dm_os_wait_stats ows
LEFT OUTER JOIN
       sys.dm_exec_session_wait_stats sws
ON     sws.wait_type = ows.wait_type
AND    sws.session_id = @@spid
WHERE  ows.wait_type = 'OLEDB';

All right.  Let's run 8 tests - from MAXDOP 8 in decreasing order to MAXDOP 1.

EXEC CHECKTABLE_OLEDB_WAIT_TEST @tableName = N'OLEDB_TEST_HEAP', @MAXDOP = 8, @PhysicalOnly = 'Y', @TABLOCK = 'N';
EXEC CHECKTABLE_OLEDB_WAIT_TEST @tableName = N'OLEDB_TEST_HEAP', @MAXDOP = 7, @PhysicalOnly = 'Y', @TABLOCK = 'N';
EXEC CHECKTABLE_OLEDB_WAIT_TEST @tableName = N'OLEDB_TEST_HEAP', @MAXDOP = 6, @PhysicalOnly = 'Y', @TABLOCK = 'N';
EXEC CHECKTABLE_OLEDB_WAIT_TEST @tableName = N'OLEDB_TEST_HEAP', @MAXDOP = 5, @PhysicalOnly = 'Y', @TABLOCK = 'N';
EXEC CHECKTABLE_OLEDB_WAIT_TEST @tableName = N'OLEDB_TEST_HEAP', @MAXDOP = 4, @PhysicalOnly = 'Y', @TABLOCK = 'N';
EXEC CHECKTABLE_OLEDB_WAIT_TEST @tableName = N'OLEDB_TEST_HEAP', @MAXDOP = 3, @PhysicalOnly = 'Y', @TABLOCK = 'N';
EXEC CHECKTABLE_OLEDB_WAIT_TEST @tableName = N'OLEDB_TEST_HEAP', @MAXDOP = 2, @PhysicalOnly = 'Y', @TABLOCK = 'N';
EXEC CHECKTABLE_OLEDB_WAIT_TEST @tableName = N'OLEDB_TEST_HEAP', @MAXDOP = 1, @PhysicalOnly = 'Y', @TABLOCK = 'N';

And what was captured for OLEDB wait stats during each checktable?

They say a picture is worth a thousand words...

OLEDB wait count at the system level ranged from 6428 at maxdop 1 and maxdop 2 up to 6435 at maxdop 8.  Interesting.  The table OLEDB_TEST_HEAP was constructed with 80 * 80 = 6400 rows, each of which are expected to consume an 8k block (because of the 4000 character NVARCHAR and the lack of compression on the table).  Since these results are from physical_only tests, could the number of waits be related to the number of blocks in the heap?

That seems plausible.

Let's resize OLEDB_TEST_HEAP to 10000 rows and see what happens.

TRUNCATE TABLE OLEDB_TEST_HEAP;
DECLARE @str NVARCHAR(max);
SET @str = REPLICATE ('A', 4000);

;WITH cnum(num) AS
(SELECT TOP (100) 1 FROM sys.columns)
INSERT INTO OLEDB_TEST_HEAP
SELECT row_number() OVER (ORDER BY (SELECT NULL)),
@str
FROM cnum c1
CROSS JOIN cnum c2;

Now run the same tests as above, with maxdop decreasing from 8 to 1, and display the results captured.  Interesting.  Very interesting.

So... yeah.  Definitely a relationship between the number of pages in the heap and the number of OLEDB waits.  Something(s) increase the number of OLEDB waits beyond the number of data pages, the number of used pages and the number of reserved pages in a way that I haven't deciphered yet, though.

One thing is clear - above maxdop 2, one OLEDB wait is added for each incremental increase in maxdop.  That's interesting.  Another interesting point: at maxdop 2 and maxdop 1 the number of OLEDB system waits are equal rather than decreasing again by 1.  Hmmm.

And the most interesting thing: at maxdop 2 and maxdop 1, the session OLEDB waits seem not to update.

I created a connect item for the OLEDB wait disappearing act in the session wait DMV sys.dm_exec_session_wait_stats.  The repro in this blog post is better than the one I put in the details of that connect item :-)  I'll update the connect item later.

OLEDB waits not always updating in sys.dm_exec_session_waits
https://connect.microsoft.com/SQLServer/feedback/details/3135073

There's more to come as I continue to look at OLEDB wait behavior in checktable operations...


[
carry on with this epic saga here...

OLEDB waits in #SQLServer Checktable Part II - the song remains very nearly the same

http://sql-sasquatch.blogspot.com/2017/06/oledb-waits-in-sqlserver-checktable_5.html



]