May 19, 2009 at 10:51 am
I am building a dynamic query string inside of a stored procedure.
I am looking for a way to calculate how much time it takes to build the string.
When I SET STATISTICS TIME ON, I can see the time in SSMS, but I want to calculate the time inside my stored procedure.
I tried using GetDate(), but it doesn't seem to be working properly.
DECLARE @StartTime DATETIME
SET @StartTime = GetDate()
... a lot of code ....
SELECT DATEDIFF(ms, @StartTime, GetDate())
May 19, 2009 at 11:09 am
Are you getting any error or something? I have tried the same code and it is working as expected. See the changed code:-
declare @i int
set @i=1
DECLARE @StartTime DATETIME
SET @StartTime = GetDate()
while @i < 4000000
begin
set @i = @i + 1
end
SELECT DATEDIFF(ms, @StartTime, GetDate())
May 19, 2009 at 11:36 am
Hi Goldie
Try sys.dm_exec_requests view:
SET NOCOUNT ON
SELECT cpu_time, total_elapsed_time, reads, writes, logical_reads
FROM sys.dm_exec_requests
WHERE session_id = @@SPID
DECLARE @i INT
SELECT @i = object_id FROM sys.all_columns
SELECT cpu_time, total_elapsed_time, reads, writes, logical_reads
FROM sys.dm_exec_requests
WHERE session_id = @@SPID
Greets
Flo
May 19, 2009 at 12:34 pm
Hi Goldie
Do you have a Dual/Quad Core environment?
Greets
Flo
May 19, 2009 at 1:45 pm
Florian Reischl (5/19/2009)
Hi GoldieDo you have a Dual/Quad Core environment?
Greets
Flo
Yup, sure do.
Do you mean to say that the CPU time is total of ALL processors?
If so, I guess I should be tracking elapsed time.
May 19, 2009 at 1:54 pm
Goldie Graber (5/19/2009)
Florian Reischl (5/19/2009)
Hi GoldieDo you have a Dual/Quad Core environment?
Greets
Flo
Yup, sure do.
Do you mean to say that the CPU time is total of ALL processors?
If so, I guess I should be tracking elapsed time.
Yes, it's the overall CPU usage. I guess the CPU time is more important while development because the queries have to perform good for more than one user 😉 but it depends on the current case.
May 19, 2009 at 2:08 pm
Florian Reischl (5/19/2009)
Goldie Graber (5/19/2009)
Florian Reischl (5/19/2009)
Hi GoldieDo you have a Dual/Quad Core environment?
Greets
Flo
Yup, sure do.
Do you mean to say that the CPU time is total of ALL processors?
If so, I guess I should be tracking elapsed time.
Yes, it's the overall CPU usage. I guess the CPU time is more important while development because the queries have to perform good for more than one user 😉 but it depends on the current case.
Right now I want to log query times in the field.
I have a stored procedure which creates a dynamic query and then executes it.
I want to save off the query, how much time it took to create it, and how long it took to execute.
So, I was thinking that I really want to track the elapsed time because that will reflect actual user times. Does that make sense?
May 19, 2009 at 2:35 pm
For usual tests I prefer the SQL Profiler for more special tests I use some procedures I wrote. I can post them if you want.
Sure, the elapsed time is the first thing the user notices. Just keep in mind that a procedure may perform very different when it is called in load tests.
May 19, 2009 at 5:50 pm
I'd love to see your procedures, even though I don't know that they'll be useful in this case.
Sure, the elapsed time is the first thing the user notices. Just keep in mind that a procedure may perform very different when it is called in load tests.
I know 🙂
May 19, 2009 at 10:14 pm
Florian Reischl (5/19/2009)
Hi GoldieTry sys.dm_exec_requests view:
SET NOCOUNT ON
SELECT cpu_time, total_elapsed_time, reads, writes, logical_reads
FROM sys.dm_exec_requests
WHERE session_id = @@SPID
DECLARE @i INT
SELECT @i = object_id FROM sys.all_columns
SELECT cpu_time, total_elapsed_time, reads, writes, logical_reads
FROM sys.dm_exec_requests
WHERE session_id = @@SPID
Greets
Flo
Florian: This looks similar to the performance measurement code that I posted in my last article (here[/url]). Unfortunately I just, found out last week that the elapsed time measurements on the sys.dm_exec_requests/sessions/connections views are incorrect for parallelized requests. Apparently it adds them together, which is correct for resouce consumption metrics, like CPU, but is incorrect for concurrent interval spanning like elapsed time.
The best solution is to just measure the interval directly, as madhu suggested earlier. Here is an example the demonstrates the problem on servers with multiple cores and the solution:
Declare @cpu_ int, @lreads_ int, @eMsec_ int, @tim_ datetime
Declare @reads_ int, @writes_ int, @rowcnt_ int
Select @cpu_ = cpu_time
, @lreads_ = logical_reads
, @eMsec_ = total_elapsed_time--note: this is inaccurate for parallel plans
, @tim_ = getdate()-- use this instead
, @reads_ = reads
, @writes_ = writes
, @rowcnt_ = row_count
From sys.dm_exec_requests
Where session_id = @@spid
--======
-- Test serial/parallel query that takes a few seconds
select max(t1.c2 + t2.c2) from tab7 t1 cross join tab7 t2 --option (maxdop 1)
--======
Select cpu_time-@cpu_ as CpuMs
, logical_reads- @lreads_ as LogRds
, (total_elapsed_time - @eMsec_) as SysDmElap
, datediff(ms, @tim_, getdate()) as TrueElapsed
, reads - @reads_ as Reads
, writes - @writes_ as Writes
, row_count - @rowcnt_ as RowCnt
, sq.text as SqlText
, Datalength(sq.text) as SqlLen
, query_plan as QueryPlanXML
, datalength(query_plan) as QPLen
From sys.dm_exec_requests
Outer Apply sys.dm_exec_query_plan(plan_handle) as qp
Outer Apply sys.dm_exec_sql_text(sql_handle) as sq
Where session_id = @@spid
[font="Times New Roman"]-- RBarryYoung[/font], [font="Times New Roman"] (302)375-0451[/font] blog: MovingSQL.com, Twitter: @RBarryYoung[font="Arial Black"]
Proactive Performance Solutions, Inc. [/font][font="Verdana"] "Performance is our middle name."[/font]
May 20, 2009 at 2:02 am
Goldie Graber (5/19/2009)
I'd love to see your procedures, even though I don't know that they'll be useful in this case.Sure, the elapsed time is the first thing the user notices. Just keep in mind that a procedure may perform very different when it is called in load tests.
I know 🙂
Good morning 🙂
... was a little late for me yesterday.
Here are two procedures and a table I use for those performance tests. The third procedure (usp_PerfMon_Test) is just a pseudo test. It's not a big deal but it works.
[font="Courier New"]--CREATE SCHEMA Tools AUTHORIZATION dbo
--GO
IF (OBJECT_ID('Tools.PerfMon') IS NULL)
CREATE TABLE Tools.PerfMon
(
Id INT IDENTITY(1,1) NOT NULL,
Description VARCHAR(100) NULL,
CreationDate DATETIME NULL,
ElapsedTime INT NULL,
CpuTime INT NULL,
PhysicalReads INT NULL,
PhysicalWrites INT NULL,
LogicalReads INT NULL,
Sorting VARCHAR(100) NULL,
IsInit bit NULL,
SPID smallint NULL,
CONSTRAINT PK_Tools_PerfMon
PRIMARY KEY CLUSTERED
(Id ASC)
)
GO
/**********************************************************************************
Summary
=======
Procedure to write an initial entry into table Tools.PerfMon
Parameters
==========
none
Remarks
=======
This module just writes an initial entry into performance counting table. After
the test statement you have to call Tools.usp_PerfMon_Write.
Version
=======
V01.00.00.00 (2009-03-10)
Initial version
V01.00.01.00 (2009-04-15)
Added SPID for multi threading tests
**********************************************************************************/
ALTER PROCEDURE Tools.usp_PerfMon_Init
AS
SET NOCOUNT ON
INSERT INTO PerfMon (
CreationDate,
ElapsedTime,
CpuTime,
PhysicalReads,
PhysicalWrites,
LogicalReads,
IsInit,
SPID
)
SELECT
GETDATE(),
r.total_elapsed_time,
r.cpu_time,
r.reads,
r.writes,
r.logical_reads,
1,
@@SPID
FROM sys.dm_exec_requests r --sys.dm_exec_sessions r
WHERE
r.session_id = @@SPID
GO
/**********************************************************************************
Summary
=======
Procedure to write a performance entry into table Tools.PerfMon
Parameters
==========
@Description
A description for the performance counting entry
@Sorting
Any optional information which can be used to sort results
Remarks
=======
To get real performance information the Tools.PerfMon needs a previous entry which
was written before the statement which has to be tested. This is usually done by
another procedure Tools.usp_PerfMon_Init
Version
=======
V01.00.00.00 (2009-03-10)
Initial version
V01.00.01.00 (2009-04-15)
Added SPID for multi threading tests
**********************************************************************************/
ALTER PROCEDURE Tools.usp_PerfMon_Write
@Description VARCHAR(100),
@Sorting VARCHAR(100) = NULL
AS
SET NOCOUNT ON
INSERT INTO PerfMon (
Description,
CreationDate,
ElapsedTime,
CpuTime,
PhysicalReads,
PhysicalWrites,
LogicalReads,
Sorting,
IsInit,
SPID
)
SELECT
@Description,
GETDATE(),
r.total_elapsed_time,
r.cpu_time,
r.reads,
r.writes,
r.logical_reads,
ISNULL(@Sorting, 0),
0,
@@SPID
FROM sys.dm_exec_requests r -- sys.dm_exec_sessions r
WHERE
r.session_id = @@SPID
GO
/**********************************************************************************
Summary
=======
Procedure test the performance monitoring procedures Tools.usp_PerfMon_Init and
Tools.usp_PerfMon_Write.
Parameters
==========
none
Remarks
=======
This procedure is a test gadget.
Version
=======
V01.00.01.00 (2009-04-15)
Added SPID for multi threading tests
**********************************************************************************/
ALTER PROCEDURE Tools.usp_PerfMon_Test
AS
DECLARE @i INT
DECLARE @v VARCHAR(MAAX)
DECLARE @n NVARCHAR(MAX)
---===============================================
-- Initialize the test
DELETE FROM Tools.PerfMon
---===============================================
-- Test without sorting
EXECUTE Tools.usp_PerfMon_Init
SELECT @i = COUNT(*) FROM sys.all_columns
EXECUTE Tools.usp_PerfMon_Write 'Count of sys.all_columns'
---===============================================
-- Test with sorting
EXECUTE Tools.usp_PerfMon_Init
SELECT @v = ''
SELECT @v = @v + name FROM MASTER.sys.all_objects
EXECUTE Tools.usp_PerfMon_Write 'VARCHAR', 'master.sys.all_objects'
SELECT @n = ''
SELECT @n = @n + name FROM MASTER.sys.all_objects
EXECUTE Tools.usp_PerfMon_Write 'NVARCHAR', 'master.sys.all_objects'
SELECT @v = ''
SELECT @v = @v + name FROM MASTER.sys.all_columns
EXECUTE Tools.usp_PerfMon_Write 'VARCHAR', 'master.sys.all_columns'
SELECT @n = ''
SELECT @n = @n + name FROM MASTER.sys.all_columns
EXECUTE Tools.usp_PerfMon_Write 'NVARCHAR', 'master.sys.all_columns'
---==========================================================
-- Results
SELECT
--SPID = p1.SPID,
Sorting = p1.Sorting,
Ranking = ROW_NUMBER() OVER (PARTITION BY p1.Sorting ORDER BY (DATEDIFF(MILLISECOND, p2.CreationDate, p1.CreationDate))),
Module = p1.Description,
Duration = RIGHT(
CONVERT(VARCHAR(30),
DATEADD(
MILLISECOND,
DATEDIFF(
MILLISECOND,
p2.CreationDate,
p1.CreationDate
),
0),
126),
12),
CpuTime = p1.CpuTime - p2.CpuTime,
LogicalReads = p1.LogicalReads - p2.LogicalReads,
PhysicalReads = p1.PhysicalReads - p2.PhysicalReads,
PhysicalWrites = p1.PhysicalWrites - p2.PhysicalWrites
FROM Tools.PerfMon p1
CROSS APPLY (
SELECT TOP(1)
p3.*
FROM Tools.PerfMon p3
WHERE p3.Id < p1.Id AND p3.SPID = p1.SPID
ORDER BY p3.Id DESC) p2
WHERE p1.IsInit != 1
ORDER BY
p1.Sorting,
Duration
GO
EXECUTE Tools.usp_PerfMon_Test
[/font]
Greets
Flo
May 20, 2009 at 2:13 am
RBarryYoung (5/19/2009)
Florian: This looks similar to the performance measurement code that I posted in my last article (here[/url]). Unfortunately I just, found out last week that the elapsed time measurements on the sys.dm_exec_requests/sessions/connections views are incorrect for parallelized requests. Apparently it adds them together, which is correct for resouce consumption metrics, like CPU, but is incorrect for concurrent interval spanning like elapsed time.The best solution is to just measure the interval directly, as madhu suggested earlier. Here is an example the demonstrates the problem on servers with multiple cores and the solution:
Barry,
I introduced the above posted procedures with my performance tests for the string splitting thread and article. I noticed some problems with the elapsed time and switched to GETDATE() some weeks ago.
Thanks for the hint! I forgot to tell it Goldie because I only use the procedures and don't think about what they do...
Greets
Flo
May 22, 2009 at 7:09 am
For some reason when I use GetDate() I always get zero.
When I use the view I get some value, usually under 100 ms.
I'm thinking that's because SQL Server dates are only accurate up to 1/300 of a second.
May 22, 2009 at 10:31 am
Goldie Graber (5/22/2009)
For some reason when I use GetDate() I always get zero.When I use the view I get some value, usually under 100 ms.
I'm thinking that's because SQL Server dates are only accurate up to 1/300 of a second.
It is possible that something takes less than one millisecond. Could you show a piece of code you use?
Viewing 15 posts - 1 through 15 (of 24 total)
You must be logged in to reply to this topic. Login to reply