August 14, 2013 at 7:33 am
Erland Sommarskog (8/14/2013)
Ah, so you have a stored procedure. In that case, there is a somewhat simpler query:
with cte as (select substring(est.text, (qs.statement_start_offset + 2)/2,
CASE qs.statement_end_offset
WHEN -1 THEN datalength(est.text)
ELSE (qs.statement_end_offset - qs.statement_start_offset + 2) / 2
END) as stmt,
qs.* from sys.dm_exec_query_stats qs
cross apply sys.dm_exec_sql_text(qs.sql_handle) est
where objectid = object_id('your_sp')
)
select * from cte
ORDER by statement_start_offset
The idea is the same, just a little more exact. This gives you the plan information for all statements in the procedure. Since it's hanging on the first INSERt statement, that is the one of interest.
You don't need to run the query right after the fact. The interesting columns are execution_count and creation_date. Is creation_date in conjunction to the problems? Before? After?
As for why there are five, this due to that you have different SET options and a few more things. From SSIS you probably run with SET ARITHABORT OFF, while this setting is OFF in SSMS.
Does the procedure take parameters? Does the parameter values change between calls?
Thanks, I'll give that a look too.
Nope, no parameters. It grabs all the data from a table, adds some metadata and puts it in another table. The origin table is wiped 4 times a day, this job runs 22 times a day, but this is the only one that sees a regular slowdown.
--------------------------------------
When you encounter a problem, if the solution isn't readily evident go back to the start and check your assumptions.
--------------------------------------
It’s unpleasantly like being drunk.
What’s so unpleasant about being drunk?
You ask a glass of water. -- Douglas Adams
August 14, 2013 at 7:36 am
Erland Sommarskog (8/14/2013)
Ah, so you have a stored procedure. In that case, there is a somewhat simpler query:
with cte as (select substring(est.text, (qs.statement_start_offset + 2)/2,
CASE qs.statement_end_offset
WHEN -1 THEN datalength(est.text)
ELSE (qs.statement_end_offset - qs.statement_start_offset + 2) / 2
END) as stmt,
qs.* from sys.dm_exec_query_stats qs
cross apply sys.dm_exec_sql_text(qs.sql_handle) est
where objectid = object_id('your_sp')
)
select * from cte
ORDER by statement_start_offset
The idea is the same, just a little more exact. This gives you the plan information for all statements in the procedure. Since it's hanging on the first INSERt statement, that is the one of interest.
You don't need to run the query right after the fact. The interesting columns are execution_count and creation_date. Is creation_date in conjunction to the problems? Before? After?
As for why there are five, this due to that you have different SET options and a few more things. From SSIS you probably run with SET ARITHABORT OFF, while this setting is OFF in SSMS.
Does the procedure take parameters? Does the parameter values change between calls?
This only shows the data from the most recent run. I'll have to run it after the problem, but before the next run.
--------------------------------------
When you encounter a problem, if the solution isn't readily evident go back to the start and check your assumptions.
--------------------------------------
It’s unpleasantly like being drunk.
What’s so unpleasant about being drunk?
You ask a glass of water. -- Douglas Adams
August 14, 2013 at 9:23 am
I turned on logging in the SSIS package. I set it to log everything. The package took 18 minutes and 25 seconds to run for its 3:30 AM run last night. Looking at the log, 17 minutes and 49 seconds of that was in the SSIS package between the following two steps
EVENT
Diagnostic
SOURCE
Get New Transactions and Tag them
STARTTIME
2013-08-14 03:30:13.000
ENDTIME
2013-08-14 03:30:13.000
MESSAGE
ExternalRequest_pre: The object is ready to make the following external request: 'ICommand::Execute'.
EVENT
Diagnostic
SOURCE
Get New Transactions and Tag them
STARTTIME
2013-08-14 03:48:04.000
ENDTIME
2013-08-14 03:48:04.000
MESSAGE
ExternalRequest_post: 'ICommand::Execute succeeded'. The external request has completed.
As you can see, the delay is between these two events. I'm guessing this is the execution of the ExecuteSQL task. It isn't easy finding explanations of these messages
--------------------------------------
When you encounter a problem, if the solution isn't readily evident go back to the start and check your assumptions.
--------------------------------------
It’s unpleasantly like being drunk.
What’s so unpleasant about being drunk?
You ask a glass of water. -- Douglas Adams
August 14, 2013 at 1:39 pm
Stefan Krzywicki (8/14/2013)
This only shows the data from the most recent run. I'll have to run it after the problem, but before the next run.
The data you see is not really related to any run at all. What you see are cached query plans as well as statistics for the cached plans. But if your job is such that the plans are recompiled everytime, yes, then what you see is related to the most recent run. But in that case it is not particularly interesting.
What I was interested in is whether there is any compilation around this hour, as that could result in a poor plan.
An option to capture plans is to set up a trace around these wee hours at night. However, tracing actual execution plans is extremely expensive. Or more precisely: it is very expensive if you have a lot of short-running statements. If all you have is this job that only runs a few big statements, the overhead is perfectly acceptable.
[font="Times New Roman"]Erland Sommarskog, SQL Server MVP, www.sommarskog.se[/font]
August 14, 2013 at 1:54 pm
Erland Sommarskog (8/14/2013)
Stefan Krzywicki (8/14/2013)
This only shows the data from the most recent run. I'll have to run it after the problem, but before the next run.The data you see is not really related to any run at all. What you see are cached query plans as well as statistics for the cached plans. But if your job is such that the plans are recompiled everytime, yes, then what you see is related to the most recent run. But in that case it is not particularly interesting.
What I was interested in is whether there is any compilation around this hour, as that could result in a poor plan.
An option to capture plans is to set up a trace around these wee hours at night. However, tracing actual execution plans is extremely expensive. Or more precisely: it is very expensive if you have a lot of short-running statements. If all you have is this job that only runs a few big statements, the overhead is perfectly acceptable.
Ah, I figured this was just the data from the listed create time, which was the immediately previous run.
Is there a way to use the listed query_hash or query_plan_hash so I can see the plan?
--------------------------------------
When you encounter a problem, if the solution isn't readily evident go back to the start and check your assumptions.
--------------------------------------
It’s unpleasantly like being drunk.
What’s so unpleasant about being drunk?
You ask a glass of water. -- Douglas Adams
August 14, 2013 at 1:58 pm
Stefan Krzywicki (8/14/2013)
Is there a way to use the listed query_hash or query_plan_hash so I can see the plan?
The hashes are just hashes.
To see the plan for a specific statement do
SELECT convert(xml, query_plan)
FROM sys.dm_exec_text_query_plan(plan_handle, statement_start_offset, statement_end_offset)
The parameters are columns from the query. Note that this is only the estimated plan - in many case you need to see the actual values in the plan to see what went wrong.
[font="Times New Roman"]Erland Sommarskog, SQL Server MVP, www.sommarskog.se[/font]
Viewing 6 posts - 46 through 50 (of 50 total)
You must be logged in to reply to this topic. Login to reply