Reads/Duration Higher on ADO vs. QA

Hello.
I have an odd scenario. I just swapped out database servers today for a
heavily-hit web server. Everything went smoothly for the most part, except
I'm having sporadic queries that are taking an excessive amount of time to
execute. Excessive, as in, before the swap, these queries would take < 2
seconds, and now they are timing out (> 30 seconds). Also, this is only
happening for a very small percentage of cases.
To make things more confusing, I had it happening to me consistently for
about 20 minutes, but when I ran the exact same stored proc in Query
Analyzer, it would run just fine.
So I try to trace it in Profiler. The results were very odd. As expected,
when hit from the website (ADO), my query was timing out (Duration ~30000),
while the trace results from QA were 1-2 seconds. But my reads from ADO
were HUGE -- like in the millions -- whereas the reads from QA were only in
the thousdands.
What in the world would cause my reads to get so high, just by hitting it
from ADO? As I said, it's the exact same stored procedure and parameters (I
actually copied the TextData from Profiler and pasted it into QA).
I'm assuming that the execution plan between the two is different, but I
have no idea how to capture the execution plan from my particular
problem-causing query from the web (without getting flooded w/ all the other
queries running). I was able to capture my QA execution plan in Profile by
filtering on SPID, but my SPID from ADO changes constantly.
Oh, by the way, after beating my head against the wall trying to figure this
out, my query from the web started behaving normally, so my troubleshooting
had to come to an end.
I'm very confused. Please, any suggestions would be appreciated.
Thanks.
Jerad
Jerad
Capture an execution plan from the Profiler and compare it to the execution
plan that was generated by QA.
Can you indentify a stored procedure in the Profiler that caused to the
problem?
"Jerad Rose" <no@.spam.com> wrote in message
news:e2KdzyQhFHA.2644@.TK2MSFTNGP09.phx.gbl...
> Hello.
> I have an odd scenario. I just swapped out database servers today for a
> heavily-hit web server. Everything went smoothly for the most part,
except
> I'm having sporadic queries that are taking an excessive amount of time to
> execute. Excessive, as in, before the swap, these queries would take < 2
> seconds, and now they are timing out (> 30 seconds). Also, this is only
> happening for a very small percentage of cases.
> To make things more confusing, I had it happening to me consistently for
> about 20 minutes, but when I ran the exact same stored proc in Query
> Analyzer, it would run just fine.
> So I try to trace it in Profiler. The results were very odd. As
expected,
> when hit from the website (ADO), my query was timing out (Duration
~30000),
> while the trace results from QA were 1-2 seconds. But my reads from ADO
> were HUGE -- like in the millions -- whereas the reads from QA were only
in
> the thousdands.
> What in the world would cause my reads to get so high, just by hitting it
> from ADO? As I said, it's the exact same stored procedure and parameters
(I
> actually copied the TextData from Profiler and pasted it into QA).
> I'm assuming that the execution plan between the two is different, but I
> have no idea how to capture the execution plan from my particular
> problem-causing query from the web (without getting flooded w/ all the
other
> queries running). I was able to capture my QA execution plan in Profile
by
> filtering on SPID, but my SPID from ADO changes constantly.
> Oh, by the way, after beating my head against the wall trying to figure
this
> out, my query from the web started behaving normally, so my
troubleshooting
> had to come to an end.
> I'm very confused. Please, any suggestions would be appreciated.
> Thanks.
> Jerad
>
|||Hi
You may want to look at SP:recompile events.
You may want to try scripting the trace output as a SQL script and running
that.
It could be that you are passing atypical parameter values, so read up on
parameter sniffing such as in Ken Henderson's "The Guru's Guide to SQL
Server Architecture and Internals" ISBN 0-201-70047-6
John
"Jerad Rose" <no@.spam.com> wrote in message
news:e2KdzyQhFHA.2644@.TK2MSFTNGP09.phx.gbl...
> Hello.
> I have an odd scenario. I just swapped out database servers today for a
> heavily-hit web server. Everything went smoothly for the most part,
> except I'm having sporadic queries that are taking an excessive amount of
> time to execute. Excessive, as in, before the swap, these queries would
> take < 2 seconds, and now they are timing out (> 30 seconds). Also, this
> is only happening for a very small percentage of cases.
> To make things more confusing, I had it happening to me consistently for
> about 20 minutes, but when I ran the exact same stored proc in Query
> Analyzer, it would run just fine.
> So I try to trace it in Profiler. The results were very odd. As
> expected, when hit from the website (ADO), my query was timing out
> (Duration ~30000), while the trace results from QA were 1-2 seconds. But
> my reads from ADO were HUGE -- like in the millions -- whereas the reads
> from QA were only in the thousdands.
> What in the world would cause my reads to get so high, just by hitting it
> from ADO? As I said, it's the exact same stored procedure and parameters
> (I actually copied the TextData from Profiler and pasted it into QA).
> I'm assuming that the execution plan between the two is different, but I
> have no idea how to capture the execution plan from my particular
> problem-causing query from the web (without getting flooded w/ all the
> other queries running). I was able to capture my QA execution plan in
> Profile by filtering on SPID, but my SPID from ADO changes constantly.
> Oh, by the way, after beating my head against the wall trying to figure
> this out, my query from the web started behaving normally, so my
> troubleshooting had to come to an end.
> I'm very confused. Please, any suggestions would be appreciated.
> Thanks.
> Jerad
>
|||"Jerad Rose" <no@.spam.com> wrote in message
news:e2KdzyQhFHA.2644@.TK2MSFTNGP09.phx.gbl...
> Hello.
> I have an odd scenario. I just swapped out database servers today for a
> heavily-hit web server. Everything went smoothly for the most part,
> except I'm having sporadic queries that are taking an excessive amount of
> time to execute. Excessive, as in, before the swap, these queries would
> take < 2 seconds, and now they are timing out (> 30 seconds). Also, this
> is only happening for a very small percentage of cases.
> To make things more confusing, I had it happening to me consistently for
> about 20 minutes, but when I ran the exact same stored proc in Query
> Analyzer, it would run just fine.
> So I try to trace it in Profiler. The results were very odd. As
> expected, when hit from the website (ADO), my query was timing out
> (Duration ~30000), while the trace results from QA were 1-2 seconds. But
> my reads from ADO were HUGE -- like in the millions -- whereas the reads
> from QA were only in the thousdands.
> What in the world would cause my reads to get so high, just by hitting it
> from ADO? As I said, it's the exact same stored procedure and parameters
> (I actually copied the TextData from Profiler and pasted it into QA).
> I'm assuming that the execution plan between the two is different, but I
> have no idea how to capture the execution plan from my particular
> problem-causing query from the web (without getting flooded w/ all the
> other queries running). I was able to capture my QA execution plan in
> Profile by filtering on SPID, but my SPID from ADO changes constantly.
> Oh, by the way, after beating my head against the wall trying to figure
> this out, my query from the web started behaving normally, so my
> troubleshooting had to come to an end.
> I'm very confused. Please, any suggestions would be appreciated.
>
I agree that the problem is that your executions are getting a different
plan in QA and ADO.
Typically stored procedure invocations will use a saved query plan, but SQL
Client connections have a number of settings which can affect the results of
queries, and so query plans cannot be shared between clients with different
settings. This might account for why you got a different plan in QA than
from ADO.
First, How to reproduce the bad behavor in QA? Open up profiler and you
will see the connection settings for the existing ADO connections in the
Existing Connection event. Copy those out into QA and run them before you
run the query again. This should give you the best shot at reproducting the
query exactly.
Alternatively, you can use ADO. Just paste this into a file on the server
with a .VBS extension
RunCommand.vbs listing
sub RunCommand(sql)
dim con
set con = CreateObject("ADODB.Connection")
con.Open "Provider=sqloledb;" & _
"Data Source=(local);" & _
"Initial Catalog=master;" & _
"User ID=stan;Password=lee"
dim rst
set rst = con.Execute(sql)
dim rc
rc = 0
Do While not rst.eof
rc = rc + 1
rst.MoveNext
loop
msgbox "got " & rc & " rows"
end sub
Dim sql
sql = InputBox("Enter SQL")
RunCommand(sql)
General fixes include:
Update statistics. Out of date statistics are the number one cause of poor
query performance. Having "swapped out database servers" is a big red flag
here.
Supress Parameter sniffing in your stored procedure by not binding query
where-clause parameters directlly to input parameters. Instead bind the
query to a local variable set to the value of the input parameter.
Run the stored procedure WITH RECOMPILE, you will get better query plans,
for the cost of recompiling the procedure on every invocation.
David
|||Are you using a client side or server side cursor from ADO? This can have a
huge impact on the number of reads and the duration, even where the same
execution plan is used as the Query Analyser. Why? Extra reads can come from
the cursoring operations & extra duration from the overall time lapsed to
cursor over the resultset.
If you want to confirm the runtime execution plan, you can inject a SQL
Trace script into the actual command to log execution plans for the current
SPID. This isn't code you'd want to leave permanently in production, just
something you'd add temporarily to get the precise plans during run-time. To
do this, you'd create the trace in profiler & use the File / Script Trace
menu to generate the script. You'd have to manually add the SPID filter via
a parameter you'd pick up at runtime.. If your SQL's embedded into an ASP
page or Win32 app, you might extract it to a stored proc first so that you
can add the trace codemore easily. Sure, this is jumping through a lot of
hoops (it regularly annoys me that this is so hard to do) but at least there
is a way to get the job done.
Regards,
Greg Linwood
SQL Server MVP
"Jerad Rose" <no@.spam.com> wrote in message
news:e2KdzyQhFHA.2644@.TK2MSFTNGP09.phx.gbl...
> Hello.
> I have an odd scenario. I just swapped out database servers today for a
> heavily-hit web server. Everything went smoothly for the most part,
> except I'm having sporadic queries that are taking an excessive amount of
> time to execute. Excessive, as in, before the swap, these queries would
> take < 2 seconds, and now they are timing out (> 30 seconds). Also, this
> is only happening for a very small percentage of cases.
> To make things more confusing, I had it happening to me consistently for
> about 20 minutes, but when I ran the exact same stored proc in Query
> Analyzer, it would run just fine.
> So I try to trace it in Profiler. The results were very odd. As
> expected, when hit from the website (ADO), my query was timing out
> (Duration ~30000), while the trace results from QA were 1-2 seconds. But
> my reads from ADO were HUGE -- like in the millions -- whereas the reads
> from QA were only in the thousdands.
> What in the world would cause my reads to get so high, just by hitting it
> from ADO? As I said, it's the exact same stored procedure and parameters
> (I actually copied the TextData from Profiler and pasted it into QA).
> I'm assuming that the execution plan between the two is different, but I
> have no idea how to capture the execution plan from my particular
> problem-causing query from the web (without getting flooded w/ all the
> other queries running). I was able to capture my QA execution plan in
> Profile by filtering on SPID, but my SPID from ADO changes constantly.
> Oh, by the way, after beating my head against the wall trying to figure
> this out, my query from the web started behaving normally, so my
> troubleshooting had to come to an end.
> I'm very confused. Please, any suggestions would be appreciated.
> Thanks.
> Jerad
>
|||How can you tell if its a client or server side cursor ? Whats the
difference between the two ?
"Greg Linwood" <g_linwoodQhotmail.com> wrote in message
news:%23BfqHwZhFHA.3316@.TK2MSFTNGP14.phx.gbl...
> Are you using a client side or server side cursor from ADO? This can have
a
> huge impact on the number of reads and the duration, even where the same
> execution plan is used as the Query Analyser. Why? Extra reads can come
from
> the cursoring operations & extra duration from the overall time lapsed to
> cursor over the resultset.
> If you want to confirm the runtime execution plan, you can inject a SQL
> Trace script into the actual command to log execution plans for the
current
> SPID. This isn't code you'd want to leave permanently in production, just
> something you'd add temporarily to get the precise plans during run-time.
To
> do this, you'd create the trace in profiler & use the File / Script Trace
> menu to generate the script. You'd have to manually add the SPID filter
via
> a parameter you'd pick up at runtime.. If your SQL's embedded into an ASP
> page or Win32 app, you might extract it to a stored proc first so that you
> can add the trace codemore easily. Sure, this is jumping through a lot of
> hoops (it regularly annoys me that this is so hard to do) but at least
there[vbcol=seagreen]
> is a way to get the job done.
> Regards,
> Greg Linwood
> SQL Server MVP
> "Jerad Rose" <no@.spam.com> wrote in message
> news:e2KdzyQhFHA.2644@.TK2MSFTNGP09.phx.gbl...
of[vbcol=seagreen]
this[vbcol=seagreen]
But[vbcol=seagreen]
it[vbcol=seagreen]
parameters
>
|||A client cursor means that the client application downloads the entire
resultset before moving (eg rs.movenext or dr.read) over the rows. With a
server-side cursor, the client application brings dow rows one at a time
during rs.movenext or dr.read operations.
You can tell the difference by checking ADO's CursorLocation properties on
the resultset or command objects.
btw, queries executed over a client-side cursor can still have much longer
duration than the same queries executed directly on the server via Query
Analyser because the resultset needs to be sent back over the network to the
client application. If the application stalls the process of reading the
resultset for any reason (the cliient pc might be busy running multiple
applications for example), this reflects in the duration value..
HTH
Regards,
Greg Linwood
SQL Server MVP
"Hassan" <fatima_ja@.hotmail.com> wrote in message
news:%23eRt9AdhFHA.1252@.TK2MSFTNGP09.phx.gbl...
> How can you tell if its a client or server side cursor ? Whats the
> difference between the two ?
> "Greg Linwood" <g_linwoodQhotmail.com> wrote in message
> news:%23BfqHwZhFHA.3316@.TK2MSFTNGP14.phx.gbl...
> a
> from
> current
> To
> via
> there
> of
> this
> But
> it
> parameters
>
|||Thanks so much for all the great replies.
It's late, so I have to make this quick.
.. I was able to reproduce the slow execution through QA, so I don't think
it's necessarily a QA vs. ADO thing. Sometimes it runs ok in ADO and in QA.
Sometimes it's slow in both (or one or the other). I think this may also
rule out client-side vs. server-side cursors.
.. I did run sp_updatestats, but that didn't seem to help much
.. I tried WITH RECOMPILE, but didn't seem to help much
.. I managed to capture the execution plan for when it runs fast (< 2
seconds) vs. when it times out (> 30 seconds).
Here are the links to those (top lists stats):
http://www.animalcrossingcommunity.com/slowplan.txt
http://www.animalcrossingcommunity.com/fastplan.txt
Here is the actual stored proc that is run (this is actually a snippet --
some stuff runs afterwards, but I'm 99% this part is what is causing the
problems):
http://www.animalcrossingcommunity.com/query.txt
Thanks again for all your help.
Jerad
"Jerad Rose" <no@.spam.com> wrote in message
news:e2KdzyQhFHA.2644@.TK2MSFTNGP09.phx.gbl...
> Hello.
> I have an odd scenario. I just swapped out database servers today for a
> heavily-hit web server. Everything went smoothly for the most part,
> except I'm having sporadic queries that are taking an excessive amount of
> time to execute. Excessive, as in, before the swap, these queries would
> take < 2 seconds, and now they are timing out (> 30 seconds). Also, this
> is only happening for a very small percentage of cases.
> To make things more confusing, I had it happening to me consistently for
> about 20 minutes, but when I ran the exact same stored proc in Query
> Analyzer, it would run just fine.
> So I try to trace it in Profiler. The results were very odd. As
> expected, when hit from the website (ADO), my query was timing out
> (Duration ~30000), while the trace results from QA were 1-2 seconds. But
> my reads from ADO were HUGE -- like in the millions -- whereas the reads
> from QA were only in the thousdands.
> What in the world would cause my reads to get so high, just by hitting it
> from ADO? As I said, it's the exact same stored procedure and parameters
> (I actually copied the TextData from Profiler and pasted it into QA).
> I'm assuming that the execution plan between the two is different, but I
> have no idea how to capture the execution plan from my particular
> problem-causing query from the web (without getting flooded w/ all the
> other queries running). I was able to capture my QA execution plan in
> Profile by filtering on SPID, but my SPID from ADO changes constantly.
> Oh, by the way, after beating my head against the wall trying to figure
> this out, my query from the web started behaving normally, so my
> troubleshooting had to come to an end.
> I'm very confused. Please, any suggestions would be appreciated.
> Thanks.
> Jerad
>
|||"Jerad Rose" <no@.spam.com> wrote in message
news:%23l200yehFHA.328@.tk2msftngp13.phx.gbl...
> Thanks so much for all the great replies.
> It's late, so I have to make this quick.
> . I was able to reproduce the slow execution through QA, so I don't think
> it's necessarily a QA vs. ADO thing. Sometimes it runs ok in ADO and in
> QA. Sometimes it's slow in both (or one or the other). I think this may
> also rule out client-side vs. server-side cursors.
> . I did run sp_updatestats, but that didn't seem to help much
> . I tried WITH RECOMPILE, but didn't seem to help much
> . I managed to capture the execution plan for when it runs fast (< 2
> seconds) vs. when it times out (> 30 seconds).
> Here are the links to those (top lists stats):
> http://www.animalcrossingcommunity.com/slowplan.txt
> http://www.animalcrossingcommunity.com/fastplan.txt
> Here is the actual stored proc that is run (this is actually a snippet --
> some stuff runs afterwards, but I'm 99% this part is what is causing the
> problems):
> http://www.animalcrossingcommunity.com/query.txt
> Thanks again for all your help.
>
Good. Now post the table DDL with indexes and a an estimate of the number
of rows in each table.
This is a hard one, and the best plan in cases like this is often to look
beyond these two plans and see if changes to the indexing structure or query
formulation can result in a much cheaper (and therefore more stable) plan.
David
David
|||Ok, here you go:
http://www.animalcrossingcommunity.com/ddl.txt
Here are some more clues. Before I swapped servers (basically same specs,
but new has Raid1 configuration and old just had one HD), this particular
query gave me virtually no problems. It typically ran in under a second,
seemingly averaging about 0.5 seconds. Now, even at best, I'm getting 1-2
or more seconds -- at worst, 30+ seconds.
Thanks again for taking time to help. If there's any other info I can
provide to help diagnosis, let me know.
Jerad
"David Browne" <davidbaxterbrowne no potted meat@.hotmail.com> wrote in
message news:urYuhAjhFHA.1048@.tk2msftngp13.phx.gbl...
> "Jerad Rose" <no@.spam.com> wrote in message
> news:%23l200yehFHA.328@.tk2msftngp13.phx.gbl...
> Good. Now post the table DDL with indexes and a an estimate of the number
> of rows in each table.
> This is a hard one, and the best plan in cases like this is often to look
> beyond these two plans and see if changes to the indexing structure or
> query formulation can result in a much cheaper (and therefore more stable)
> plan.
> David
> David
>