April 11, 2013 at 7:24 am
We have a overnight agent job and one of the steps runs particular slow recently. The step calls a stored procedure. I used sql server profiler to capture the trace for that proc into a table. I captured sp:StmtCompleted and sp:Completed events. And in column filter, I set ApplicationName to be like %step 6%, where step 6 is the step in question. And I set ObjectName to be like sp_xxx, where sp_xxx is the proc called by step 6.
I got the trace next morning and found the duration for sp:StmtCompleted is 1.87 hour (calculated), which is similar to the job history for that step. But when I sum up duration of all sp:StmtCompleted events, the total is about 8 seconds. I rerun the proc on a test environment with production data and got similar result (several seconds). I went through the text data of all sp:StmtCompleted events ordered by starttime and found it's a correct execution of all relevant statements in the proc.
I am wondering why the sum of duration of all sp:StmtCompleted events are not equal to that of sp:Completed ?
A side question: I already set ObjectName to be like sp_xxx in column filter but still got lot of records with objectname 'null'. What should I do?
April 12, 2013 at 4:00 am
I got the trace this morning again. The total time from all statements in the stored procedure is about 8 seconds. But the sp:Completed shows the duration is about 1 hour and half, which is the same as in job history.
Should I capture more events maybe?
April 12, 2013 at 8:24 am
What is the proc doing? Can you post the code?
There are no special teachers of virtue, because virtue is taught by the whole community.
--Plato
April 12, 2013 at 10:28 am
Here is the code. The code was done long time ago by someone left. It's not very well written and maybe can be improved. But now the issue seems to be not relevant to the code because when I manually run the code it runs pretty quick.
set ANSI_NULLS ON
set QUOTED_IDENTIFIER ON
go
ALTER PROC [dbo].[sp_xxx]
AS
/*=====================
Begin TRANSACTION
=====================*/
BEGIN TRANSACTION
DECLARE @error_txt VARCHAR(4000)
/*===========================================
CREATE # TABLE/s TO STORE CHANGED RECORDS
===========================================*/
CREATE TABLE #tmp1(...)
CREATE TABLE #tmp2(...)
/*===========================================
INSERT CHANGED RECORDS INTO # TABLE/s
===========================================*/
SET NOCOUNT ON
INSERT INTO #tmp1
SELECT * FROM r.dbo.product_master_1
EXCEPT
SELECT * FROM r.dbo.g_product_master_1
INSERT INTO #tmp2
SELECT * FROM r.dbo.product_detail_1
EXCEPT
SELECT * FROM r.dbo.g_product_detail_1
SET NOCOUNT OFF
BEGIN TRY
/*===========================================
EXISTING RECORDS - g_product_master_1
===========================================*/
IF EXISTS(SELECT *
FROM #tmp1 pm
JOIN r.dbo.g_product_master_1 gbpm ON pm.prod_id = gbpm.prod_id)
BEGIN
SELECT *
FROM #tmp1
UPDATE gbpm
SET gbpm.level1_id = pm.level1_id,
gbpm.level2_id = pm.level2_id,
...
FROM r.dbo.g_product_master_1 gbpm
JOIN #tmp1 pm ON gbpm.prod_id = pm.prod_id
END
IF @@ROWCOUNT = 0
PRINT 'No new rows updated into r.dbo.g_product_master_1'
ELSE PRINT 'Row/s updated into r.dbo.g_product_master_1'
/*===========================================
NEW RECORDS - g_product_master_1
===========================================*/
IF EXISTS (SELECT *
FROM #tmp1 pm
JOIN r.dbo.g_product_master_1 gbpm ON pm.prod_id <> gbpm.prod_id)
BEGIN
SET IDENTITY_INSERT r.dbo.g_product_master_1 ON
INSERT INTO r.dbo.g_product_master_1
(...)
SELECT
pm.prod_id
,pm.level1_id
...
FROM #tmp1 pm
WHERE NOT EXISTS (SELECT * FROM r.dbo.g_product_master_1 gbpm WHERE pm.prod_id = gbpm.prod_id)
END
IF @@ROWCOUNT = 0
PRINT 'No new rows inserted into r.dbo.g_product_master_1'
ELSE PRINT 'New row/s inserted into r.dbo.g_product_master_1'
SET IDENTITY_INSERT r.dbo.g_product_master_1 OFF
/*===========================================
EXISTING RECORDS - g_product_detail_1
===========================================*/
IF EXISTS (SELECT *
FROM #tmp2 pd
JOIN r.dbo.g_product_detail_1 gbpd ON pd.sku_id = gbpd.sku_id)
BEGIN
SELECT *
FROM #tmp2
UPDATE gbpd
SET gbpd.product_id = pd.product_id,
gbpd.colour_id = pd.colour_id,
...
FROM r.dbo.g_product_detail_1 gbpd
JOIN #tmp2 pd ON gbpd.sku_id = pd.sku_id
END
IF @@ROWCOUNT = 0
PRINT 'No new rows updated into r.dbo.g_product_detail_1'
ELSE PRINT 'Row/s updated into r.dbo.g_product_detail_1'
/*===========================================
NEW RECORDS - g_product_detail_1
===========================================*/
IF EXISTS (SELECT *
FROM #tmp2 pd
JOIN r.dbo.g_product_detail_1 gbpd ON pd.sku_id <> gbpd.sku_id)
BEGIN
SET IDENTITY_INSERT r.dbo.g_product_detail_1 ON
INSERT INTO r.dbo.g_product_detail_1
(...)
SELECT
pd.sku_id
,pd.product_id
...
FROM #tmp2 pd
WHERE NOT EXISTS (SELECT * FROM r.dbo.g_product_detail_1 gbpd WHERE pd.sku_id = gbpd.sku_id)
END
IF @@ROWCOUNT = 0
PRINT 'No new rows inserted into r.dbo.g_product_detail_1'
ELSE PRINT 'New row/s inserted into r.dbo.g_product_detail_1'
--SET IDENTITY_INSERT r.dbo.g_product_detail_1 OFF
END TRY
BEGIN CATCH
SELECT @error_txt = CONVERT(VARCHAR(20),ERROR_SEVERITY()) + '= ' + ERROR_MESSAGE()
RAISERROR(@error_txt,16,1)
ROLLBACK TRANSACTION
RETURN
END CATCH
COMMIT TRANSACTION
/*===========================================
DROP # TABLES
===========================================*/
DROP TABLE #tmp1
DROP TABLE #tmp2
April 12, 2013 at 11:27 am
I was hoping to see some Dynamic SQL or external calls to Linked Servers or something else that might help explain the difference, but no luck.
There are no special teachers of virtue, because virtue is taught by the whole community.
--Plato
Viewing 5 posts - 1 through 4 (of 4 total)
You must be logged in to reply to this topic. Login to reply