Click here to monitor SSC
SQLServerCentral is supported by Red Gate Software Ltd.
 
Log in  ::  Register  ::  Not logged in
 
 
 
        
Home       Members    Calendar    Who's On


Add to briefcase

sql server 2005 profiler Expand / Collapse
Author
Message
Posted Thursday, April 11, 2013 7:24 AM
SSC Rookie

SSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC Rookie

Group: General Forum Members
Last Login: Monday, September 8, 2014 3:23 AM
Points: 48, Visits: 236
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?
Post #1441237
Posted Friday, April 12, 2013 4:00 AM
SSC Rookie

SSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC Rookie

Group: General Forum Members
Last Login: Monday, September 8, 2014 3:23 AM
Points: 48, Visits: 236
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?
Post #1441626
Posted Friday, April 12, 2013 8:24 AM


SSCertifiable

SSCertifiableSSCertifiableSSCertifiableSSCertifiableSSCertifiableSSCertifiableSSCertifiableSSCertifiableSSCertifiable

Group: General Forum Members
Last Login: Monday, September 15, 2014 7:19 PM
Points: 7,127, Visits: 12,655
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
Post #1441734
Posted Friday, April 12, 2013 10:28 AM
SSC Rookie

SSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC RookieSSC Rookie

Group: General Forum Members
Last Login: Monday, September 8, 2014 3:23 AM
Points: 48, Visits: 236
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
Post #1441792
Posted Friday, April 12, 2013 11:27 AM


SSCertifiable

SSCertifiableSSCertifiableSSCertifiableSSCertifiableSSCertifiableSSCertifiableSSCertifiableSSCertifiableSSCertifiable

Group: General Forum Members
Last Login: Monday, September 15, 2014 7:19 PM
Points: 7,127, Visits: 12,655
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
Post #1441811
« Prev Topic | Next Topic »

Add to briefcase

Permissions Expand / Collapse