October 17, 2018 at 1:21 pm
Good day everyone:
An interesting case just presented to my attention: Have the same INSTANCE of a SQL Server 2016 (13.0.4446.0) , the same query is executed against two slightly different in schema databases, producing the same query plan - with the same set of objects indexes row counts (slightly different but anyway) - and executed 50 times slower:
Database A:
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Resources'. Scan count 0, logical reads 13287, physical reads 25, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ActivityInstance'. Scan count 0, logical reads 542603, physical reads 3, read-ahead reads 8, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Schedule'. Scan count 66000, logical reads 216829, physical reads 19, read-ahead reads 16, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ActivityType'. Scan count 1650, logical reads 6600, physical reads 2, read-ahead reads 8, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Location'. Scan count 1650, logical reads 57377, physical reads 3, read-ahead reads 61, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'CampaignInstance'. Scan count 0, logical reads 6875, physical reads 2, read-ahead reads 8, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Program_table'. Scan count 2, logical reads 150, physical reads 2, read-ahead reads 72, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'CampaignType'. Scan count 1, logical reads 2, physical reads 2, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'UserResourceManagement'. Scan count 1, logical reads 2, physical reads 2, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Users'. Scan count 0, logical reads 7, physical reads 7, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Licensee'. Scan count 1, logical reads 3, physical reads 3, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.(1 row(s) affected)
SQL Server Execution Times:
CPU time = 3563 ms, elapsed time = 4002 ms.
Database D:
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Resources'. Scan count 0, logical reads 13545, physical reads 25, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ActivityInstance'. Scan count 0, logical reads 49515202, physical reads 3, read-ahead reads 8, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Schedule'. Scan count 5944460, logical reads 19546150, physical reads 18, read-ahead reads 8, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ActivityType'. Scan count 1660, logical reads 104580, physical reads 2, read-ahead reads 60, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Location'. Scan count 1660, logical reads 61359, physical reads 3, read-ahead reads 65, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'CampaignInstance'. Scan count 0, logical reads 6916, physical reads 2, read-ahead reads 8, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Program_table'. Scan count 2, logical reads 152, physical reads 2, read-ahead reads 73, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'CampaignType'. Scan count 1, logical reads 2, physical reads 2, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'UserResourceManagement'. Scan count 1, logical reads 2, physical reads 2, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Users'. Scan count 0, logical reads 7, physical reads 7, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Licensee'. Scan count 1, logical reads 3, physical reads 3, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.(1 row(s) affected)
SQL Server Execution Times:
CPU time = 94063 ms, elapsed time = 114215 ms.
Both cases are executed after clean buffer and cache free
DBCC FREEPROCCACHE
DBCC DROPCLEANBUFFERS
DBCC FREESYSTEMCACHE ( 'ALL' )
GO
Why do I have 50 x elapsed time difference - no clue at all. Same box same resources used and ran out of any possible solution here . Can someone form our team possible help me with the directions of where to look at else on top of everything I already digged.
Thank you for your help
October 18, 2018 at 9:24 am
If you look at the logical reads for the following:
ActivityInstance
Schedule
ActivityType
They are much higher in database D - investigate why that is so different.
Jeffrey Williams
“We are all faced with a series of great opportunities brilliantly disguised as impossible situations.”
― Charles R. Swindoll
How to post questions to get better answers faster
Managing Transaction Logs
October 18, 2018 at 10:20 am
Many thanks SSC Guru for your reference. Yes these objects (physical tables) even they are fairly alike in number of records (49 726 = A and 53 542 = D as an example for ActivityInstance and 217 136 = A vs 219 209 = D for ActivityType) storing the data in much higher number of pages (4 = A vs 202 = D for Resources eg)
From the counters :SELECT objects.name AS "Object Name", objects.type_desc AS "Object Type",
COUNT(*) AS "Total Buffer Pages"
FROM sys.dm_os_buffer_descriptors
INNER JOIN sys.allocation_units
ON allocation_units.allocation_unit_id = dm_os_buffer_descriptors.allocation_unit_id
INNER JOIN sys.partitions
ON ((allocation_units.container_id = partitions.hobt_id AND type IN (1,3))
OR (allocation_units.container_id = partitions.partition_id AND type IN (2)))
INNER JOIN sys.objects
ON partitions.object_id = objects.object_id
WHERE allocation_units.type IN (1,2,3)
AND objects.name in ('ActivityInstance','ActivityType','Schedule','Resources')
AND objects.is_ms_shipped = 0
AND dm_os_buffer_descriptors.database_id = DB_ID()
GROUP BY objects.name, objects.type_desc
ORDER BY COUNT(*) DESC;
Database D
Resources USER_TABLE 202
Schedule USER_TABLE 152
ActivityType USER_TABLE 64
ActivityInstance USER_TABLE 27
Database A
Resources USER_TABLE 4
Schedule USER_TABLE 2
ActivityType USER_TABLE 1
ActivityInstance USER_TABLE 1
And that is not clear to me: why we have such a different assignment between similar objects? Any help would be appreciated
October 18, 2018 at 10:40 am
Can you post the actual execution plans?
Michael L John
If you assassinate a DBA, would you pull a trigger?
To properly post on a forum:
http://www.sqlservercentral.com/articles/61537/
October 18, 2018 at 10:50 am
Sure - here they are in XML
October 18, 2018 at 10:56 am
And here is the SHOWPLAN_ALL txt format
October 18, 2018 at 11:01 am
When is the last time you updated statistics on the databases and have you been using FULLSCAN or something else?
--Jeff Moden
Change is inevitable... Change for the better is not.
October 18, 2018 at 11:13 am
That is a freshly loaded DEV / STG Box all statistics are fresh and indexes are rebuilt , buffers are cleaned and cache is free before each execution since that is not a SPROC. Same box no difference in settings of the databases. No fragmentation or any of a kind. Same disk same CPU , memory , system resources - the only difference to my knowledge - some objects (not these that are listed) have been optimized for some different customers. And as you may see from the execution plan that were generated - they are the same.
MAny thanks for looking into this case
October 18, 2018 at 11:48 am
I cannot open either of the files. Or, better yet, I do not have the patience to work through .xml or a pipe separated file so that I can actually look at them.
Can you simply save them as a .sqlplan file?
Michael L John
If you assassinate a DBA, would you pull a trigger?
To properly post on a forum:
http://www.sqlservercentral.com/articles/61537/
October 18, 2018 at 11:56 am
Michael L John - Thursday, October 18, 2018 11:48 AMI cannot open either of the files. Or, better yet, I do not have the patience to work through .xml or a pipe separated file so that I can actually look at them.Can you simply save them as a .sqlplan file?
These also are estimated plans, and actual plan will be far more helpful
Michael L John
If you assassinate a DBA, would you pull a trigger?
To properly post on a forum:
http://www.sqlservercentral.com/articles/61537/
October 18, 2018 at 12:06 pm
Sure : Here is the set of actual execution plans per your request. Many thanks Michael for your time
October 18, 2018 at 12:30 pm
Quick glance, The ActivityInstance table contains many more rows.
The A query is reading 177160 rows on the index seek, the D query is reading 16168215 rows on the same seek
Michael L John
If you assassinate a DBA, would you pull a trigger?
To properly post on a forum:
http://www.sqlservercentral.com/articles/61537/
October 18, 2018 at 12:36 pm
That is another interesting observation - the actual number of rows : EXEC sp_spaceused 'ActivityInstance'
ActivityInstance 217136 59520 KB 52888 KB 6312 KB 320 KB
ActivityInstance 219209 60736 KB 53968 KB 6344 KB 424 KB
EXEC sp_spaceused 'ActivityType'
ActivityType 49726 12592 KB 8848 KB 3312 KB 432 KB
ActivityType 53542 13232 KB 9376 KB 3472 KB 384 KB
October 18, 2018 at 12:36 pm
anvegger - Thursday, October 18, 2018 12:06 PMSure : Here is the set of actual execution plans per your request. Many thanks Michael for your time
In the plans - D has 5944460 rows from the table ActivityType - compared to 66000 in plan A (both actual number and number of rows read).
Plan D has 16168215 rows from Schedule compared to 177160 in plan A with 25310508 rows read in plan D compared to 277040 rows read in plan A.
Plan D has 4515 rows in ActivityInstance compared to 4429 in plan A with 16168215 rows read in plan D compared to 177160 in plan D.
There is much more data in the APP1_Dan database compared to the App1_Alex database for these tables - which is going to take longer to process.
Jeffrey Williams
“We are all faced with a series of great opportunities brilliantly disguised as impossible situations.”
― Charles R. Swindoll
How to post questions to get better answers faster
Managing Transaction Logs
October 18, 2018 at 12:41 pm
Actual number of rows is very similar (within 10% difference) Something is the counters is giving me the feelings that buffer read is involved but what and how - no clue
Thanks for your references
Viewing 15 posts - 1 through 15 (of 48 total)
You must be logged in to reply to this topic. Login to reply