September 28, 2010 at 12:43 am
I'm working as a developer on a project that stores large amounts of data per transaction (Often 200 MB or more). After having committed or rolled back a large transaction, I often see the SQL Server process use a lot of CPU power for a long time. I assume that the SQL Server is restoring data from the TempDb, after having a transaction roll back, but I don't know what is going on when a transaction is successfully committed.
I tried looking at the Activity monitor, to determine which session is using all of the CPU time, but I don't see any long lasting transactions there. I also tried looking in the SQL Server profiler, to see which commands were being executed, but didn't see any commands there.
Can you tell me how to find out why my SQL Server is using a lot of CPU ?
My main focus is finding out how to determine what is going on, when Activity monitor and SQL Server profiler don't reveal the issue.
PS) I am running on an SQL Server 2008 Express, because this best replicates the customer systems, but I have the Management Studio from the SQL Server Developer Edition installed for development purposes.
September 29, 2010 at 6:55 am
Perhaps this is a dumb question, but have you tried:
EXEC SP_WHO2
September 29, 2010 at 7:13 am
Mr. Andersen (9/28/2010)
I'm working as a developer on a project that stores large amounts of data per transaction (Often 200 MB or more). After having committed or rolled back a large transaction, I often see the SQL Server process use a lot of CPU power for a long time. I assume that the SQL Server is restoring data from the TempDb, after having a transaction roll back, but I don't know what is going on when a transaction is successfully committed.I tried looking at the Activity monitor, to determine which session is using all of the CPU time, but I don't see any long lasting transactions there. I also tried looking in the SQL Server profiler, to see which commands were being executed, but didn't see any commands there.
Can you tell me how to find out why my SQL Server is using a lot of CPU ?
My main focus is finding out how to determine what is going on, when Activity monitor and SQL Server profiler don't reveal the issue.
PS) I am running on an SQL Server 2008 Express, because this best replicates the customer systems, but I have the Management Studio from the SQL Server Developer Edition installed for development purposes.
Mr. Anderson,
High CPU can denote a number of issues. More often than not there is some outside hardware factor that is adding "pressure" to SQL Performance.
High CPU, or CPU Pressure, can come up when some of the following occur:
1) Not enough RAM available for both the OS and the SQL Server Instance (causes paging on the OS level)
2) High Disk queues (takes to long to retrieve data)
As a side note, it might be the edition of SQL Server that you are using, but I don't think moving to SQL Sever Standard Ed. is going to resolve the problem.
Check this blog post from Pinal Dave on CPU Pressure. He gives some advice on how to figure out what is going on.
http://blog.sqlauthority.com/2009/08/17/sql-server-measure-cpu-pressure-cpu-business/
Also, you might want to if you can get Gail's (Gilamonster) attention. She is wicked awesome on finding performance issues.
Regards, Irish
October 5, 2010 at 3:37 am
mferanda (9/29/2010)
Perhaps this is a dumb question, but have you tried:EXEC SP_WHO2
That's not a dumb question at all.
The answer is yes, I have tried to call sp_who2, but unfortunately I have gotten only the same information as when watching the Activity monitor.
Jeffrey Irish, I agree with you that under normal circumstances resource shortage will slow down performance and use up a lot of CPU power. My primary concern is that the CPU time is being used after I have finished executing my large transaction and waited for the transaction to complete.
The transaction itself is visible as a process under Activity monitor (And sp_who2), but after the transaction completes the CPU is still being used, without any indication of which process is using the CPU.
October 5, 2010 at 6:57 am
Mr. Andersen (10/5/2010)
Jeffrey Irish, I agree with you that under normal circumstances resource shortage will slow down performance and use up a lot of CPU power. My primary concern is that the CPU time is being used after I have finished executing my large transaction and waited for the transaction to complete.The transaction itself is visible as a process under Activity monitor (And sp_who2), but after the transaction completes the CPU is still being used, without any indication of which process is using the CPU.
Okay, this changes thing a little. Let me make sure that I understand what you are saying.
The transaction runs and completes. If you run SP_WHO2 you can see that the transaction is no longer executing, but SQL Server is still consuming CPU.
Let me give you a script that I find very helpful for identifying just what the heck is going on in a database. I found it in another SQL Server Central post, but changed it so I can execute it at runtime rather than creating a procedure. (Thank you Jason Brimhall!)
All this will do is really allow you to identify what is really running for each SPID. After that, you will need to spend some time in SQL DMV's to figure out what is taking up the CPU time.:-D. I might have some queries for that, but those too would be gleened from the Interweb.
Keep me posted. If you figure this one out we are all interested in hearing the resolution!
/***************************************************************************************************************
*Author: Jason Brimhall <http://www.sqlservercentral.com/articles/sp_who2/70222/>
*Routine Name: [dbo].[jb_mywho2]
*Purpose: Return SPID information from SQL Server
*Used by: Admins
*Inputs: @IsUserProcess (0,1) 0= Show All Processes 1= Show User Processes Only
* @CurrentSpid (0,Null) 0 = Include current Query SPID NULL = Exclude Current Query SPID
*Returns:
*Test Code: EXEC jb_mywho2
***************************************************************************************************************/
--Create Procedure jb_mywho2
DECLARE
@IsUserProcess TinyInt
,@CurrentSpid TinyInt
SELECT @IsUserProcess = 0;
SELECT @CurrentSpid = 0;
--As
Begin
Set NoCount On
/*
Test Code
------------------------------------------
Declare @IsUserProcess TinyInt
,@CurrentSpid TinyInt
Select @IsUserProcess = 0
,@CurrentSpid = 0
*/
Select es.session_id As SPID
,ROW_NUMBER() over (partition by es.session_id order by es.login_time) As SubProcessID
,DB_NAME(Coalesce(er.database_id,tl1.resource_database_id,' - ')) As DBName
,Coalesce(ot.task_state,es.status,' - ') As TaskStatus
,es.login_name As LoginName
,Coalesce(ec.client_net_address,' - ') As IPAddress
,Coalesce((SELECT text As [processing-instruction(definition)]
FROM sys.dm_exec_sql_text(ec.most_recent_sql_handle)
FOR XML PATH(''), TYPE
),'') As QueryText
,Coalesce(er.wait_type,wt.wait_type,er.last_wait_type,' - ') As WaitType
,Coalesce(es.host_name,' - ') As HostName
,Coalesce(tl.request_session_id,'') As BlockedBy
,Coalesce((SELECT p.text
FROM (SELECT MIN(sql_handle) As sql_handle
FROM sys.dm_exec_requests r2
WHERE r2.session_id = tl.request_session_id
) As rb
CROSS APPLY
(SELECT text As [processing-instruction(definition)]
FROM sys.dm_exec_sql_text(rb.sql_handle)
FOR XML PATH(''), TYPE
) p (text)
),'') As BlockingText
,Coalesce(es.program_name,' - ') As ProgramName
,Coalesce(es.client_interface_name,' - ') As ClientInterface
,Coalesce(es.host_process_id,' - ') As UserProcessID
,es.login_time As LoginTime
,es.last_request_start_time As LastBatch
,es.total_elapsed_time *.001 As SessionElapsedTime
,es.total_scheduled_time * .001 As CPUTime
,es.memory_usage As Num8kPages
,Coalesce(ec.num_reads,'') As NumReads
,Coalesce(ec.num_writes,'') As NumWrites
,Coalesce(er.open_transaction_count,st.TranCount,0) As OpenTranCount
,Coalesce(dt.lockcount,0) As LockCount
From sys.dm_exec_sessions es
Left Outer Join sys.dm_exec_connections ec
On ec.session_id = es.session_id
Left Outer Join sys.dm_os_waiting_tasks wt
On wt.session_id = es.session_id
Left Outer Join sys.dm_os_tasks ot
On es.session_id = ot.session_id
Left Outer Join sys.dm_tran_locks tl
On wt.blocking_session_id = tl.request_session_id
Left Outer Join sys.dm_tran_locks tl1
On ec.session_id = tl1.request_session_id
Left Outer Join sys.dm_exec_requests er
On tl.request_session_id = er.session_id
Left Outer Join (
Select request_session_id,COUNT(request_session_id) As LockCount
From sys.dm_tran_locks
Group By request_session_id
) dt
On ec.session_id = dt.request_session_id
Left Outer Join (
Select session_id,COUNT(session_id) As TranCount
From sys.dm_tran_session_transactions
Group By session_id
) st
On ec.session_id = st.session_id
Where es.is_user_process >= (Case when @IsUserProcess = 0 Then 0 Else 1 End)
And es.session_id <> (Case when @CurrentSPID = 0 Then 0 Else @@SPID End) --@@SPID if current Spid is to be excluded
End
Regards, Irish
October 5, 2010 at 9:13 am
dbcc_inputbuffer(SPID)
October 5, 2010 at 9:19 am
Rome1981 (10/5/2010)
dbcc_inputbuffer(SPID)
Yes, that will show you what is running for the SPID, but it does not show you the rest of the information like SP_WHO2 does. This adds the inputbuffer to the query output.
Regards, Irish
October 5, 2010 at 9:29 am
You said this happens after a large transaction? What is the large transaction actually doing?
If you're performing a mass update or delete to a large table, it could have something to do with the indexes involved or expansion of your log file. This still sounds like a bottleneck issue as someone else described above. So, I would think you would see some queue issues going on through performance monitor. (regardless of exactly what is doing this through MSSQL)
October 5, 2010 at 9:37 am
Never mind about what the transaction is doing. *forgot you described this above.
Still though, have you checked the performance monitor?
Also, what is your space reserved / space used of your data file and log file for the database? If it's a large transaction and depending on your settings, both files may be expanding and causing the transaction to take longer.
October 20, 2010 at 5:56 am
I finally had time to go back to this issue and had a chance to run the script you suggested. I tried running the script immediately after the transaction failed and rolled back. The script took forever without finish executing. I started another copy of the script 10 minutes later and the result was the same. 5 minutes after that I started yet another copy of the script and got a rather large result (~1.1 million rows).
The results started with 23 uninteresting entries that occurred in the master database. These all had 0.000 CPU time and 0 locks.
Following came the 3 requests for executing the proposed script itself. These used 0.598 CPU time and had 3 locks (But were also not interesting).
Next came 1.1 million entries identical to these two (Sorry about the formatting, this forum doesn't allow posting table results in a good way):
SPIDSubProcessIDDBNameTaskStatusLoginNameIPAddressQueryTextWaitTypeHostNameBlockedByBlockingTextProgramNameClientInterfaceUserProcessIDLoginTimeLastBatchSessionElapsedTimeCPUTimeNum8kPagesNumReadsNumWritesOpenTranCountLockCount
521MyDatabaseRUNNINGMyUserAccount<local machine><?definition (@Item_ID uniqueidentifier)DELETE FROM Item WHERE Item_ID=@Item_ID?> - MyComputer0My Application.Net SqlClient Data Provider54882010-10-20 12:53:56.5102010-10-20 13:04:18.507478.354415.4532593037138656611138947
522MyDatabaseRUNNINGMyUserAccount<local machine><?definition (@Item_ID uniqueidentifier)DELETE FROM Item WHERE Item_ID=@Item_ID?> - MyComputer0My Application.Net SqlClient Data Provider54882010-10-20 12:53:56.5102010-10-20 13:04:18.507478.354415.4532593037138656611138947
The only thing different for each row is the SubProcessID field. This is being incremented by 1 for each row. The code is consistent with what is being executed by the application that uses the SQL Server. The entries are all executed in a single transaction, by the application.
mferanda: Which performance monitor counters would you suggest to look at ?
October 20, 2010 at 7:20 am
Mr. Andersen (10/20/2010)
I finally had time to go back to this issue and had a chance to run the script you suggested. I tried running the script immediately after the transaction failed and rolled back. The script took forever without finish executing. I started another copy of the script 10 minutes later and the result was the same. 5 minutes after that I started yet another copy of the script and got a rather large result (~1.1 million rows).The results started with 23 uninteresting entries that occurred in the master database. These all had 0.000 CPU time and 0 locks.
Following came the 3 requests for executing the proposed script itself. These used 0.598 CPU time and had 3 locks (But were also not interesting).
Next came 1.1 million entries identical to these two (Sorry about the formatting, this forum doesn't allow posting table results in a good way):
SPIDSubProcessIDDBNameTaskStatusLoginNameIPAddressQueryTextWaitTypeHostNameBlockedByBlockingTextProgramNameClientInterfaceUserProcessIDLoginTimeLastBatchSessionElapsedTimeCPUTimeNum8kPagesNumReadsNumWritesOpenTranCountLockCount
521MyDatabaseRUNNINGMyUserAccount<local machine><?definition (@Item_ID uniqueidentifier)DELETE FROM Item WHERE Item_ID=@Item_ID?> - MyComputer0My Application.Net SqlClient Data Provider54882010-10-20 12:53:56.5102010-10-20 13:04:18.507478.354415.4532593037138656611138947
522MyDatabaseRUNNINGMyUserAccount<local machine><?definition (@Item_ID uniqueidentifier)DELETE FROM Item WHERE Item_ID=@Item_ID?> - MyComputer0My Application.Net SqlClient Data Provider54882010-10-20 12:53:56.5102010-10-20 13:04:18.507478.354415.4532593037138656611138947
The only thing different for each row is the SubProcessID field. This is being incremented by 1 for each row. The code is consistent with what is being executed by the application that uses the SQL Server. The entries are all executed in a single transaction, by the application.
mferanda: Which performance monitor counters would you suggest to look at ?
If you have two instances of the exact same code running, maybe you could consider checking what your Max DOP (Degree of Parallelism) is set to. If I recall correctly, a value of zero (0) allows MSSQL to manage this dynamically. It can be dangerous and has caused me issues in the past. I have set the Max DOP to 1 or equal to the number of processors (depending on a number of factors).
Check out some articles on the Interweb and see what you find. Bear in mind, this is just an idea and not necessarily the resolution.
Regards, Irish
October 20, 2010 at 8:19 am
ok, here's some that I use. They give a lot of insight into what's going on in sql server. I got this from jimmy may's blog on microsoft. they rock.
looking at what you had there -- Is there a cursor in the stored procedure doing that work? Also I saw the use of a guid there...
what is the primary key and clustered index on that table? I know it's a dumb question but just trying to rule out the use of indexing a guid.
--<<<<<<<<<<----------------------------------------------------------------->>>>>>>>>>--
--DMV_All-Stars.sql
--Jimmy May 317.590.8650
--A.C.E. Performance Team
--http://blogs.msdn.com/jimmymay
--Table of Contents
--1. expensive queries
--2. wait stats
--3. virtual file stats (& virtual file latency)
--4. plan cache interrogation
--5. real-time blockers
--<<<<<<<<<<----------------------------------------------------------------->>>>>>>>>>--
--Weasel Clause: This script is provided "AS IS" with no warranties, and confers no rights.
-- Use of included script samples are subject to the terms specified at
-- http://www.microsoft.com/info/cpyright.htm
--<<<<<<<<<<----------------------------------------------------------------->>>>>>>>>>--
--1. expensive queries
--text *and* statement
--usage: modify WHERE & ORDER BY clauses to suit circumstances
SELECT TOP 25
-- the following four columns are NULL for ad hoc and prepared batches
DB_Name(qp.dbid) as dbname , qp.dbid , qp.objectid , qp.number
--, qp.query_plan --the query plan can be *very* useful; enable if desired
, qt.text
, SUBSTRING(qt.text, (qs.statement_start_offset/2) + 1,
((CASE statement_end_offset
WHEN -1 THEN DATALENGTH(qt.text)
ELSE qs.statement_end_offset END
- qs.statement_start_offset)/2) + 1) as statement_text
, qs.creation_time , qs.last_execution_time , qs.execution_count
, qs.total_worker_time / qs.execution_count as avg_worker_time
, qs.total_physical_reads / qs.execution_count as avg_physical_reads
, qs.total_logical_reads / qs.execution_count as avg_logical_reads
, qs.total_logical_writes / qs.execution_count as avg_logical_writes
, qs.total_elapsed_time / qs.execution_count as avg_elapsed_time
, qs.total_clr_time / qs.execution_count as avg_clr_time
, qs.total_worker_time , qs.last_worker_time , qs.min_worker_time , qs.max_worker_time
, qs.total_physical_reads , qs.last_physical_reads , qs.min_physical_reads , qs.max_physical_reads
, qs.total_logical_reads , qs.last_logical_reads , qs.min_logical_reads , qs.max_logical_reads
, qs.total_logical_writes , qs.last_logical_writes , qs.min_logical_writes , qs.max_logical_writes
, qs.total_elapsed_time , qs.last_elapsed_time , qs.min_elapsed_time , qs.max_elapsed_time
, qs.total_clr_time , qs.last_clr_time , qs.min_clr_time , qs.max_clr_time
--, qs.sql_handle , qs.statement_start_offset , qs.statement_end_offset
, qs.plan_generation_num -- , qp.encrypted
FROM sys.dm_exec_query_stats as qs
CROSS APPLY sys.dm_exec_query_plan(qs.plan_handle) as qp
CROSS APPLY sys.dm_exec_sql_text(qs.sql_handle) as qt
--WHERE...
--ORDER BY qs.execution_count DESC --Frequency
ORDER BY qs.total_worker_time DESC --CPU
--ORDER BY qs.total_elapsed_time DESC --Durn
--ORDER BY qs.total_logical_reads DESC --Reads
--ORDER BY qs.total_logical_writes DESC --Writes
--ORDER BY qs.total_physical_reads DESC --PhysicalReads
--ORDER BY avg_worker_time DESC --AvgCPU
--ORDER BY avg_elapsed_time DESC --AvgDurn
--ORDER BY avg_logical_reads DESC --AvgReads
--ORDER BY avg_logical_writes DESC --AvgWrites
--ORDER BY avg_physical_reads DESC --AvgPhysicalReads
--sample WHERE clauses
--WHERE last_execution_time > '20070507 15:00'
--WHERE execution_count = 1
-- WHERE SUBSTRING(qt.text, (qs.statement_start_offset/2) + 1,
-- ((CASE statement_end_offset
-- WHEN -1 THEN DATALENGTH(qt.text)
-- ELSE qs.statement_end_offset END
-- - qs.statement_start_offset)/2) + 1)
-- LIKE '%MyText%'
--<<<<<<<<<<----------------------------------------------------------------->>>>>>>>>>--
--2. wait stats
--2000
--DBCC sqlperf(waitstats,CLEAR) --re-initialize waitstats
DBCC sqlperf(waitstats)
--2005
--DBCC sqlperf('sys.dm_os_wait_stats',CLEAR) --re-initialize waitstats
SELECT * , (wait_time_ms - signal_wait_time_ms) as resource_wait_time_ms
FROM sys.dm_os_wait_stats
ORDER BY resource_wait_time_ms DESC
--ORDER BY wait_time_ms DESC
--ORDER BY signal_wait_time_ms DESC
--ORDER BY waiting_tasks_count DESC
--ORDER BY max_wait_time_ms DESC
--<<<<<<<<<<----------------------------------------------------------------->>>>>>>>>>--
--3. virtual file stats
--2000
SELECT DB_NAME(DBID) as DbName
, (IoStallMS/(NumberReads + NumberWrites)) as IsStall
, * FROM ::fn_virtualfilestats(-1,-1)
--2005
SELECT
--virtual file latency
vReadLatency
= CASE WHEN num_of_reads = 0
THEN 0 ELSE (io_stall_read_ms/num_of_reads) END
, vWriteLatency
= CASE WHEN io_stall_write_ms = 0
THEN 0 ELSE (io_stall_write_ms/num_of_writes) END
, vLatency
= CASE WHEN (num_of_reads = 0 AND num_of_writes = 0)
THEN 0 ELSE (io_stall/(num_of_reads + num_of_writes)) END
--avg bytes per IOP
, BytesperRead
= CASE WHEN num_of_reads = 0
THEN 0 ELSE (num_of_bytes_read/num_of_reads) END
, BytesperWrite
= CASE WHEN io_stall_write_ms = 0
THEN 0 ELSE (num_of_bytes_written/num_of_writes) END
, BytesperTransfer
= CASE WHEN (num_of_reads = 0 AND num_of_writes = 0)
THEN 0 ELSE ((num_of_bytes_read+num_of_bytes_written)/(num_of_reads + num_of_writes)) END
, LEFT(mf.physical_name,2) as Drive
, DB_NAME(vfs.database_id) as DB
--, mf.name AS FileName
, vfs.*
, mf.physical_name
FROM sys.dm_io_virtual_file_stats(NULL,NULL) as vfs
JOIN sys.master_files as mf ON vfs.database_id = mf.database_id AND vfs.file_id = mf.file_id
--WHERE vfs.file_id = 2 -- log files
ORDER BY vLatency DESC
-- ORDER BY vReadLatency DESC
-- ORDER BY vWriteLatency DESC
--<<<<<<<<<<----------------------------------------------------------------->>>>>>>>>>--
--4. plan cache interrogation
-- note: sys.dm_exec_cached_plans is diminutive version of syscacheobjects
-- no dbid, setopts
-- we want reusable code, absence of ad hoc SQL
-- we want relatively few rows with low usecounts
--2000
SELECT cacheobjtype , objtype , usecounts , pagesused , dbid , sql
FROM master.dbo.syscacheobjects
WHERE cacheobjtype = 'Compiled Plan'
ORDER BY usecounts DESC
--ORDER BY sql
--2005
SELECT c.cacheobjtype , c.objtype , c.usecounts , c.size_in_bytes , t.dbid , t.text
FROM sys.dm_exec_cached_plans as c
CROSS APPLY sys.dm_exec_sql_text(plan_handle) as t
WHERE c.cacheobjtype = 'Compiled Plan'
ORDER BY c.usecounts DESC
--ORDER BY t.text
--<<<<<<<<<<----------------------------------------------------------------->>>>>>>>>>--
--5. real-time blockers
--Report Blocker and Waiter SQL Statements
--http://www.microsoft.com/technet/scriptcenter/scripts/sql/sql2005/trans/sql05vb044.mspx?mfr=true
-- SQLCAT BPT
SELECT
t1.resource_type as lock_type
, db_name(resource_database_id) as DB
, t1.resource_associated_entity_id as blkd_obj
, t1.request_mode as lock_req -- lock requested
, t1.request_session_id as waiter_sid-- spid of waiter
, t2.wait_duration_ms as waittime
, (SELECT text FROM sys.dm_exec_requests as r --- get sql for waiter
CROSS APPLY sys.dm_exec_sql_text(r.sql_handle)
WHERE r.session_id = t1.request_session_id) as waiter_batch
, (SELECT SUBSTRING(qt.text , r.statement_start_offset/2
, (CASE WHEN r.statement_end_offset = -1
THEN LEN(CONVERT(nvarchar(MAX), qt.text)) * 2
ELSE r.statement_end_offset END - r.statement_start_offset)/2)
FROM sys.dm_exec_requests as r
CROSS APPLY sys.dm_exec_sql_text(r.sql_handle) as qt
WHERE r.session_id = t1.request_session_id) as waiter_stmt --- this is the statement executing right now
, t2.blocking_session_id as blocker_sid -- spid of blocker
, (SELECT text FROM sys.sysprocesses as p --- get sql for blocker
CROSS APPLY sys.dm_exec_sql_text(p.sql_handle)
WHERE p.spid = t2.blocking_session_id) as blocker_stmt
FROM sys.dm_tran_locks as t1
JOIN sys.dm_os_waiting_tasks as t2
ON t1.lock_owner_address = t2.resource_address
October 22, 2010 at 6:47 pm
Sorry, it's been a while.
So you are dealing with a million rows being inserted and this processor usage is after the fact? *the table in question is not locked and the heavy processor usage is all you see.
October 23, 2010 at 12:13 am
@Anderson,
Have u tried to use Jimmy May's DMV which has been provided by enwicc.
If yes, kindly update the forum with results.
Regards,
Chetan
November 1, 2010 at 1:46 am
I'm sorry, but I haven't had the time to run the script provided by fenwicc yet.
I promise to return with the results, as soon as I am able to perform the test.
Viewing 15 posts - 1 through 14 (of 14 total)
You must be logged in to reply to this topic. Login to reply