March 5, 2009 at 5:53 am
I am running the supplied profiler duration trace against a database where users are complaining about slow response times. I am seeing one insert command with durations of between 30 seconds and two minutes. But the insert is so simple I don't believe it. Can profiler be fooled and get this wrong?
The app uses a lot of dynamic SQL and I see a lot sp_prepare, sp_execute, sp_cursoropen commands. Could these be making profiler give false results?
the inserts are like this:
INSERT INTO TRACKERNOTES (TRACKERID, NOTE) VALUES ( N'1095010462541158281519769633', NULL )
INSERT INTO TRACKERNOTES (TRACKERID, NOTE) VALUES ( N'1095010462535189611447883855', N'System note: Data exported' )
table def:
CREATE TABLE [TRACKERNOTES] (
[TRACKERID] [nvarchar] (35) COLLATE Latin1_General_CI_AS NOT NULL ,
[nvarchar] (1624) COLLATE Latin1_General_CI_AS NULL
) ON [PRIMARY]
GO
ALTER TABLE [TRACKERNOTES] WITH NOCHECK ADD
CONSTRAINT [TRACKERNOTES_TRACKERID_INDEX] PRIMARY KEY CLUSTERED
(
[TRACKERID]
) ON [PRIMARY]
GO
the table has 1.1 million rows, uses 113mb space and has no triggers.
I copied the table to a test database on the same server and an insert was instantaneous.
---------------------------------------------------------------------
March 5, 2009 at 6:19 am
I've never seen profiler reporting false durations. You sure there's no blocking in the prod database that could be making the insert wait?
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
March 5, 2009 at 7:17 am
How is TrackerID created? Is it sequential in nature or can it vary?
I'm just going to guess, and since Gail didn't mention it I may be way off and I'm sure she will correct me, that you may have issues with index inserts and page splitting because of the size of the Clustered Index Key and, I'm just guessing, the randomness of it as well. I think this could also be causing some blocking issues because the insert may be taking larger locks (Page vs row, etc...) or more because of the page splits.
Check out this link.
Jack Corbett
Consultant - Straight Path Solutions
Check out these links on how to get faster and more accurate answers:
Forum Etiquette: How to post data/code on a forum to get the best help
Need an Answer? Actually, No ... You Need a Question
March 5, 2009 at 7:49 am
GilaMonster (3/5/2009)
I've never seen profiler reporting false durations. You sure there's no blocking in the prod database that could be making the insert wait?
GilaMonster (3/5/2009)
I've never seen profiler reporting false durations. You sure there's no blocking in the prod database that could be making the insert wait?
you may be onto something there, its the logical conclusion. I have gone back through my blocking logs (again) and I have found an example where the command was blocked. Trouble is it was blocked behind a 'self blocking' RPC call (sp_execute;1) where sql_handle is empty, so not sure at this point what it was doing. I suspect it may be a long delete running using parallelism that tends to wait on CXPAcket.
I am going to have to run some more profilers and try and capture the SQL being run. Then with luck its over to the third party vendor.
theres a number of long duration queries so this may be the tip of the iceberg.
I have been using indexdefrag rather than reindex due to causing blocking to users and although logical fragmentation is good, scan density is poor, so I will get a slot to run a full reindex.
---------------------------------------------------------------------
March 5, 2009 at 7:57 am
Jack Corbett (3/5/2009)
How is TrackerID created? Is it sequential in nature or can it vary?I'm just going to guess, and since Gail didn't mention it I may be way off and I'm sure she will correct me, that you may have issues with index inserts and page splitting because of the size of the Clustered Index Key and, I'm just guessing, the randomness of it as well. I think this could also be causing some blocking issues because the insert may be taking larger locks (Page vs row, etc...) or more because of the page splits.
Check out this link.
ahh.........security people...access to blogs is bannned from my site. I might learn something.
I just dont know the app well enough but it looks like the id is sequential (or at least increasing) from the traces. As mentioned before logical fragmentation not bad but extents are out of order:
DBCC SHOWCONTIG (1574296668)
DBCC SHOWCONTIG scanning 'TRACKERNOTES' table...
Table: 'TRACKERNOTES' (1574296668); index ID: 1, database ID: 32
TABLE level scan performed.
- Pages Scanned................................: 13941
- Extents Scanned..............................: 1773
- Extent Switches..............................: 4708
- Avg. Pages per Extent........................: 7.9
- Scan Density [Best Count:Actual Count].......: 37.01% [1743:4709]
- Logical Scan Fragmentation ..................: 15.56%
- Extent Scan Fragmentation ...................: 84.60%
- Avg. Bytes Free per Page.....................: 1253.2
- Avg. Page Density (full).....................: 84.52%
DBCC execution completed. If DBCC printed error messages, contact your system administrator.
---------------------------------------------------------------------
March 5, 2009 at 8:08 am
That shouldn't cause a problem for inserts. Large range-scan reads yes, but not singleton inserts.
Gail Shaw
Microsoft Certified Master: SQL Server, MVP, M.Sc (Comp Sci)
SQL In The Wild: Discussions on DB performance with occasional diversions into recoverability
March 5, 2009 at 11:09 am
Depending on your through put on SQL Server you might want to try capturing the log and running it through PSSDiag? It will tell you what queries are running long and what queries are causing the blocking.
I had found a similar issue; where queries were taking long to a point where they did time-out. It turned out someone was running a report on the entire database when doing a select it acquires shared-lock. So the write was blocked because those shared-locks were released in time; it is hard to catch that kind of stuff on fly. But PSSDiag in 2000 was life safer more then once, specially catching blocking :).
Mohit K. Gupta, MCITP: Database Administrator (2005), My Blog, Twitter: @SQLCAN[/url].
Microsoft FTE - SQL Server PFE
* Some time its the search that counts, not the finding...
* I didn't think so, but if I was wrong, I was wrong. I'd rather do something, and make a mistake than be frightened and be doing nothing. :smooooth:[/font]
March 5, 2009 at 4:06 pm
Mohit,
the througput is high, also this is a consolidated server, I presume pssdiag can set filters by database as it runs profiler.?
The old pssblocker script produced mountains of output, is the output manageable from pssdiag?
---------------------------------------------------------------------
March 5, 2009 at 4:20 pm
Hmm I ran PSSDIAG on a system which was dedicated for one database so never needed to exclude other databases or filter.
I just looked at and the GUI interface doesn't provide any functionality to filter on one database. So you'll get huge dump of logs; but it dose provide a way to limit the events that are being captured. The blocking was logged in a single log file (text) file and those were even though big after an day of running were easy to search through.
But if I remeber right the analysis tool like the Read80Trace had ability to filter data. Now the new SQL Nexus (http://www.codeplex.com/sqlnexus) might be a better way to read that trace data :).
Thanks.
Mohit K. Gupta, MCITP: Database Administrator (2005), My Blog, Twitter: @SQLCAN[/url].
Microsoft FTE - SQL Server PFE
* Some time its the search that counts, not the finding...
* I didn't think so, but if I was wrong, I was wrong. I'd rather do something, and make a mistake than be frightened and be doing nothing. :smooooth:[/font]
March 6, 2009 at 7:35 am
for this particular long running query its definitely a block, so thanks Gail. It sure helps to be able to bounce things off people when your brain has stopped.
the insert above is blocked behind a delete that takes out locks on a couple of related tables and an exclusive table lock on trackernotes itself. Its almost impossible to track down the actual delete statement because there are tens of thousands of sp_cursoropen statements cluttering things up. So the app vendor can earn their support fees on this one.
BTW the reindex job did a great job compared to indexdefrag and db is now optimised to the hilt (for the indexes that are in place). I will be more circumspect in future about relying on the rule of thumb of logical fragmentation above 20% before defragging, IMHO avg. page density and scan density need to be considered too.
---------------------------------------------------------------------
Viewing 10 posts - 1 through 9 (of 9 total)
You must be logged in to reply to this topic. Login to reply