August 22, 2011 at 4:49 pm
Has anyone else seen a case where a large percentage (90%+) of events were not captured by an xevents session? I'm trying to use the sqlos.spinlock_backoff event with the async bucketizer just like is outlined in the whitepaper http://go.microsoft.com/fwlink/?LinkId=223366 to capture a high frequency of SOS_TLIST backoffs on my server. but even though I can see that a large number of backoffs occur during my trace only a few are actually captured. Below is my script and the output. As you can see it only captured 2 of the backoff events but checking sys.dm_os_spinlock_stats shows there were 83 backoffs in the 1 minute trace period.
--create the even session that will capture the callstacks to a bucketizer
--more information is available in this reference: http://msdn.microsoft.com/en-us/library/bb630354.aspx
create event session spin_lock_backoff on server
add event sqlos.spinlock_backoff (action (package0.callstack)
where
type = 142--SOS_TLIST
)
add target package0.asynchronous_bucketizer (
set filtering_event_name='sqlos.spinlock_backoff',
source_type=1, source='package0.callstack')
with (MAX_MEMORY=500MB, MEMORY_PARTITION_MODE = PER_NODE, EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS)
--Run this section to measure the contention
alter event session spin_lock_backoff on server state=start
select backoffs from sys.dm_os_spinlock_stats where name = 'SOS_TLIST'
--wait to measure the number of backoffs over a 1 minute period
waitfor delay '00:01:00'
--To view the data
--1. Ensure the sqlservr.pdb is in the same directory as the sqlservr.exe
--2. Enable this trace flag to turn on symbol resolution
DBCC traceon (3656, -1)
select backoffs from sys.dm_os_spinlock_stats where name = 'SOS_TLIST'
--Check stats to see what was dropped
select * from sys.dm_xe_sessions
where name = 'spin_lock_backoff'
--Get the callstacks from the bucketize target
select event_session_address, target_name, execution_count, cast (target_data as XML)
from sys.dm_xe_session_targets xst
inner join sys.dm_xe_sessions xs on (xst.event_session_address = xs.address)
where xs.name = 'spin_lock_backoff'
--clean up the session
alter event session spin_lock_backoff on server state=stop
drop event session spin_lock_backoff on server
backoffs
-----------
178483
DBCC execution completed. If DBCC printed error messages, contact your system administrator.
backoffs
-----------
178566
address name pending_buffers total_regular_buffers regular_buffer_size total_large_buffers large_buffer_size total_buffer_size buffer_policy_flags buffer_policy_desc flags flag_desc dropped_event_count dropped_buffer_count blocked_event_fire_time create_time largest_event_dropped_size
------------------ ------------------- --------------- --------------------- -------------------- ------------------- -------------------- -------------------- ------------------- ---------------------- ----------- ---------------- ------------------- -------------------- ----------------------- ----------------------- --------------------------
0x0000002F8841F7E1 spin_lock_backoff 0 12 43712307 0 0 524547684 0 drop_event 1 flush_on_close 0 0 0 2011-08-22 15:43:18.510 0
(1 row(s) affected)
event_session_address target_name execution_count
--------------------- ------------------------------------------------------------ -------------------- ----------------------------------------------------------------------------------------------------------------------------------
0x0000002F8841F7E1 asynchronous_bucketizer 2 <BucketizerTarget truncated="0" buckets="256"><Slot count="1" trunc="0"><value>XeSosPkg::spinlock_backoff::Publish+e2 [ @ 0+0x0
SpinlockBase::Sleep+c7 [ @ 0+0x0
SpinlockBase::Backoff+8f [ @ 0+0x0
Spinlock<142,1,0>::SpinToAcquireOptimistic+f4 [ @ 0+0x0
TList<NodeManager,SOS_Node,16>::GetHead+36 [ @ 0+0x0
TEnumerator<NodeManager,SOS_Node,16>::TEnumerator<NodeManager,SOS_Node,16>+21 [ @ 0+0x0
ResourceMonitor::IsResourceSetProcessWide+2e [ @ 0+0x0
SOS_UserStore::Notify+42 [ @ 0+0x0
ResourceMonitor::NotifyMemoryConsumers+2ed [ @ 0+0x0
ResourceMonitor::ResourceMonitorTask+21a [ @ 0+0x0
SetupResourceMonitorTaskContext+133 [ @ 0+0x0
SOS_Task::Param::Execute+12a [ @ 0+0x0
SOS_Scheduler::RunTask+96 [ @ 0+0x0
SOS_Scheduler::ProcessTasks+128 [ @ 0+0x0
SchedulerManager::WorkerEntryPoint+2b6 [ @ 0+0x0
SystemThread::RunWorker+cc [ @ 0+0x0</value></Slot><Slot count="1" trunc="0"><value>XeSosPkg::spinlock_backoff::Publish+e2 [ @ 0+0x0
SpinlockBase::Sleep+c7 [ @ 0+0x0
SpinlockBase::Backoff+8f [ @ 0+0x0
Spinlock<142,1,0>::SpinToAcquireOptimistic+f4 [ @ 0+0x0
TList<NodeManager,SOS_Node,16>::GetHead+36 [ @ 0+0x0
TEnumerator<NodeManager,SOS_Node,16>::TEnumerator<NodeManager,SOS_Node,16>+21 [ @ 0+0x0
ResourceMonitor::GetResourcePoolMask+26 [ @ 0+0x0
SOS_UserStore::Notify+4d [ @ 0+0x0
ResourceMonitor::NotifyMemoryConsumers+2ed [ @ 0+0x0
ResourceMonitor::ResourceMonitorTask+21a [ @ 0+0x0
SetupResourceMonitorTaskContext+133 [ @ 0+0x0
SOS_Task::Param::Execute+12a [ @ 0+0x0
SOS_Scheduler::RunTask+96 [ @ 0+0x0
SOS_Scheduler::ProcessTasks+128 [ @ 0+0x0
SchedulerManager::WorkerEntryPoint+2b6 [ @ 0+0x0
SystemThread::RunWorker+cc [ @ 0+0x0</value></Slot></BucketizerTarget>
August 23, 2011 at 9:51 am
Anyone have a clue?
Maybe I should bite the bullet and open a case...
September 27, 2011 at 10:25 am
Microsoft answered the mystery.
It turns out that not all spinlock backoffs are collected by the XE event "sqlos.spinlock_backoff". The logic that is in the SQL code only passes the backoff to XE if a single thread has encountered 8 consecutive backoffs. This isn't at all obvious in any documentation I have seen out there. With this design if you have spinlock contention and it is a constantly moving target it will capture very few events in your trace and you may have to trace for a long period of time. In my case, I had to trace for 15 minutes and only captured 15 events even though there were 10's of 1000's of backoffs logged to the spinlock stats during the trace.
I hope this helps someone else out there.
March 13, 2012 at 10:44 am
ooookay... so it does NOT do all of them ???
Thx for the headsup, i ran into the same issue!
Viewing 4 posts - 1 through 3 (of 3 total)
You must be logged in to reply to this topic. Login to reply