Could not figure out the profiler meaning for SP

I have a SP which is as simple as
create procedure SPName @.Para
-- Query 1
select field1, ...
from view1
where field1 = @.para
-- Query 2
select field1, ...
from view2
where field1 = @.para
Go
But the view1 is a little bit complex. It nests 3 sub-views.
Usually SP takes 1s to execute. But one day the end user reports the SP was
slow. Then I run the SP on QA. And I found strange things.
For the first time to execute, it takes longer time to execute, like 7s.
Then if I continue to execute the SP(change the parameter or not) it runs
fast, 1s. Then I use the profiler check the details. I traced the
SP:completed, SQL:stmtcompleted, etc.
Duration:
in event SP:StmtCompleted, the query 1: 1688, query 2: 234
SP:Completed 1922. That makes sense since it's 1688+ 234
But following up the SQL:StmtCompleted : 5625, SQL:BatchComplted:5626. All
the text data is executing the SP, like exec SPName @.para.
When the SP execute 1s, I see the duration of SQL:StmtCompleted and
SQL:BatchComplted is very close to SP:Completed. So total time is close to
1s. But for long run SP, I don't kown what else the SQL Engine have to do
under the hood. And why it's different for the execution time.
Additionaly, in the trace file, I saw a lot of SQLTransaction going on. The
objectName is sort_init, TextData: begin, commit. In the SP, only has
query. I don't know why there is SQLTransaction and what the transaction
does. Can any body explain what does that mean?
I saw the trace start with SQL:BatchStarting; -->SQL:StmtStarting;
-->SP:Starting with same Textdata ane end with SP:Completed -->
SQL:StmtCompleted-->SQL:BatchComplted with same Textdata. The duration of
SP:Completed is always correct. But duration of SQL:StmtCompleted and
SQL:BatchComplted are various. what's the meaning of duration of
SQL:BatchCompleted?
Any help?
Robertrobert
When you first time run the SP , query optimizer is created an execution
plan to produce the query and cached the plan into the memory (buffer pool).
It does not happen (it might recompile under some circumstances) when you
run the SP for the second,third times . The execution plan is taken from the
cache which seep up the query
Try investigate an execution plan , see any differences. It is possible
that a 'bad' query plan is chosen.
Also run SET STATISTICS IO ON to see what is going on
"robert" <robert@.discussions.microsoft.com> wrote in message
news:962BE2E5-1B80-4470-BB95-D28846F55B8A@.microsoft.com...
> I have a SP which is as simple as
> create procedure SPName @.Para
> -- Query 1
> select field1, ...
> from view1
> where field1 = @.para
> -- Query 2
> select field1, ...
> from view2
> where field1 = @.para
> Go
> But the view1 is a little bit complex. It nests 3 sub-views.
> Usually SP takes 1s to execute. But one day the end user reports the SP
was
> slow. Then I run the SP on QA. And I found strange things.
> For the first time to execute, it takes longer time to execute, like 7s.
> Then if I continue to execute the SP(change the parameter or not) it runs
> fast, 1s. Then I use the profiler check the details. I traced the
> SP:completed, SQL:stmtcompleted, etc.
> Duration:
> in event SP:StmtCompleted, the query 1: 1688, query 2: 234
> SP:Completed 1922. That makes sense since it's 1688+ 234
> But following up the SQL:StmtCompleted : 5625, SQL:BatchComplted:5626. All
> the text data is executing the SP, like exec SPName @.para.
> When the SP execute 1s, I see the duration of SQL:StmtCompleted and
> SQL:BatchComplted is very close to SP:Completed. So total time is close to
> 1s. But for long run SP, I don't kown what else the SQL Engine have to do
> under the hood. And why it's different for the execution time.
> Additionaly, in the trace file, I saw a lot of SQLTransaction going on.
The
> objectName is sort_init, TextData: begin, commit. In the SP, only has
> query. I don't know why there is SQLTransaction and what the transaction
> does. Can any body explain what does that mean?
> I saw the trace start with SQL:BatchStarting; -->SQL:StmtStarting;
> -->SP:Starting with same Textdata ane end with SP:Completed -->
> SQL:StmtCompleted-->SQL:BatchComplted with same Textdata. The duration of
> SP:Completed is always correct. But duration of SQL:StmtCompleted and
> SQL:BatchComplted are various. what's the meaning of duration of
> SQL:BatchCompleted?
> Any help?
> Robert
>
>
>
>
>|||Thx for reply.
But I'm not sure it's the problem related with execution plan. Even in the
bad case, the duration of SP:Complated is 1s from the trace. So you mean the
extra time SQL engine use to generate the execution plan?
Also it's difficult to reproduct the bad case. If I run the SP after10
mins/20 mins later, It might happen. But not always.
Any other suggestion?
"Uri Dimant" wrote:

> robert
> When you first time run the SP , query optimizer is created an execution
> plan to produce the query and cached the plan into the memory (buffer pool
).
> It does not happen (it might recompile under some circumstances) when you
> run the SP for the second,third times . The execution plan is taken from t
he
> cache which seep up the query
> Try investigate an execution plan , see any differences. It is possible
> that a 'bad' query plan is chosen.
> Also run SET STATISTICS IO ON to see what is going on
>
>
> "robert" <robert@.discussions.microsoft.com> wrote in message
> news:962BE2E5-1B80-4470-BB95-D28846F55B8A@.microsoft.com...
> was
> The
>
>|||Hi
You may want to profile SP:CacheMiss and SP:Recompile. You have not posted
your code or DDL, but if it contains conditional execution or statements
then you may want to separate it into smaller sub-procedures.
John
"robert" <robert@.discussions.microsoft.com> wrote in message
news:C8A4EE2A-3CFD-4FC7-BED7-21AD0302728D@.microsoft.com...
> Thx for reply.
> But I'm not sure it's the problem related with execution plan. Even in the
> bad case, the duration of SP:Complated is 1s from the trace. So you mean
> the
> extra time SQL engine use to generate the execution plan?
> Also it's difficult to reproduct the bad case. If I run the SP after10
> mins/20 mins later, It might happen. But not always.
> Any other suggestion?
> "Uri Dimant" wrote:
>|||No SP:Recompile. And all CacheMiss columns are blank. My code is
View1 is like select field11, field12, ... from view11
View2 is like select field21, field22, ... from view21
And view1, view2 nested 3 level sub views.
"John Bell" wrote:
> Hi
> You may want to profile SP:CacheMiss and SP:Recompile. You have not posted
> your code or DDL, but if it contains conditional execution or statements
> then you may want to separate it into smaller sub-procedures.
> John
> "robert" <robert@.discussions.microsoft.com> wrote in message
> news:C8A4EE2A-3CFD-4FC7-BED7-21AD0302728D@.microsoft.com...
>
>|||Hi
If the code is:
create procedure SPName @.Para
-- Query 1
IF @.para = 1
select field1, ...
from view1
where field1 = @.para
ELSE
-- Query 2
select field1, ...
from view2
where field1 = @.para
Go
Then try to split each of the queries into two separate procedures. If you
mainly use one query then the execution plan may not be optimal for the
second query.
create procedure SPName_1 @.Para
select field1, ...
from view1
where field1 = @.para
create procedure SPName_2 @.Para
select field1, ...
from view2
where field1 = @.para
create procedure SPName @.Para
IF @.para = 1
EXEC spName_1 @.Para
ELSE
EXEC spName_2 @.Para
John
"robert" <robert@.discussions.microsoft.com> wrote in message
news:5CA451CB-4956-4DA1-9466-85C0854506C8@.microsoft.com...
> No SP:Recompile. And all CacheMiss columns are blank. My code is
> View1 is like select field11, field12, ... from view11
> View2 is like select field21, field22, ... from view21
> And view1, view2 nested 3 level sub views.
>
> "John Bell" wrote:
>|||The SP have to execute two querys. I think the SQL engine use the correct
execution plan from the duration of the SP:Completed event. But the SQL
engine takes additional times to do sth else.
Robert
"John Bell" wrote:

> Hi
> If the code is:
> create procedure SPName @.Para
> -- Query 1
> IF @.para = 1
> select field1, ...
> from view1
> where field1 = @.para
> ELSE
> -- Query 2
> select field1, ...
> from view2
> where field1 = @.para
> Go
> Then try to split each of the queries into two separate procedures. If you
> mainly use one query then the execution plan may not be optimal for the
> second query.
> create procedure SPName_1 @.Para
> select field1, ...
> from view1
> where field1 = @.para
> create procedure SPName_2 @.Para
> select field1, ...
> from view2
> where field1 = @.para
> create procedure SPName @.Para
> IF @.para = 1
> EXEC spName_1 @.Para
> ELSE
> EXEC spName_2 @.Para
> John
> "robert" <robert@.discussions.microsoft.com> wrote in message
> news:5CA451CB-4956-4DA1-9466-85C0854506C8@.microsoft.com...
>
>|||Could a reason for this be that the additional time is taken to load an
index on the first execution and later runs use the loaded index ?
"Uri Dimant" <urid@.iscar.co.il> wrote in message
news:%2315qfq6UFHA.628@.tk2msftngp13.phx.gbl...
> robert
> When you first time run the SP , query optimizer is created an execution
> plan to produce the query and cached the plan into the memory (buffer
> pool).
> It does not happen (it might recompile under some circumstances) when you
> run the SP for the second,third times . The execution plan is taken from
> the
> cache which seep up the query
> Try investigate an execution plan , see any differences. It is possible
> that a 'bad' query plan is chosen.
> Also run SET STATISTICS IO ON to see what is going on
>
>
> "robert" <robert@.discussions.microsoft.com> wrote in message
> news:962BE2E5-1B80-4470-BB95-D28846F55B8A@.microsoft.com...
> was
> The
>|||Hi
If you have conditional execution then it is most likely that the plan
is inappropriate. You would be able work out which path was being
executed by analysing the parameters. Splitting the procedure into
sub-procedures means that a plan for each sub-procedure can be created
and therefore the situation would not arise.
John|||Hi
You don't say if there is any other activity going on on the server at
this time?
What is the RPC:Completed value?
Are you logging to a database table/screen/file?
You may want to monitor the Lock events and Database Events!
John