Collect thread wakeup data.

This commit is contained in:
Bartosz Taudul 2019-08-17 17:05:29 +02:00
parent f957f64ce1
commit 414f903cc5
7 changed files with 158 additions and 65 deletions

View File

@ -39,6 +39,15 @@ struct CSwitch
uint32_t reserved;
};
struct ReadyThread
{
uint32_t threadId;
int8_t adjustReason;
int8_t adjustIncrement;
int8_t flag;
int8_t reserverd;
};
void EventRecordCallback( PEVENT_RECORD record )
{
#ifdef TRACY_ON_DEMAND
@ -46,31 +55,39 @@ void EventRecordCallback( PEVENT_RECORD record )
#endif
const auto& hdr = record->EventHeader;
if( hdr.EventDescriptor.Opcode != 36 ) return;
if( hdr.EventDescriptor.Opcode == 36 )
{
const auto cswitch = (const CSwitch*)record->UserData;
const auto cswitch = (const CSwitch*)record->UserData;
Magic magic;
auto token = GetToken();
auto& tail = token->get_tail_index();
auto item = token->enqueue_begin( magic );
MemWrite( &item->hdr.type, QueueType::ContextSwitch );
MemWrite( &item->contextSwitch.time, hdr.TimeStamp.QuadPart );
memcpy( &item->contextSwitch.oldThread, &cswitch->oldThreadId, sizeof( cswitch->oldThreadId ) );
memcpy( &item->contextSwitch.newThread, &cswitch->newThreadId, sizeof( cswitch->newThreadId ) );
memset( ((char*)&item->contextSwitch.oldThread)+4, 0, 4 );
memset( ((char*)&item->contextSwitch.newThread)+4, 0, 4 );
MemWrite( &item->contextSwitch.cpu, record->BufferContext.ProcessorNumber );
MemWrite( &item->contextSwitch.reason, cswitch->oldThreadWaitReason );
MemWrite( &item->contextSwitch.state, cswitch->oldThreadState );
tail.store( magic + 1, std::memory_order_release );
}
else if( hdr.EventDescriptor.Opcode == 50 )
{
const auto rt = (const ReadyThread*)record->UserData;
static_assert( sizeof( record->BufferContext.ProcessorNumber ) == sizeof( uint8_t ), "Bad data size" );
static_assert( sizeof( cswitch->oldThreadId ) == sizeof( uint32_t ), "Bad data size" );
static_assert( sizeof( cswitch->newThreadId ) == sizeof( uint32_t ), "Bad data size" );
static_assert( sizeof( hdr.TimeStamp.QuadPart ) == sizeof( int64_t ), "Bad data size" );
static_assert( sizeof( cswitch->oldThreadWaitReason ) == sizeof( uint8_t ), "Bad data size" );
static_assert( sizeof( cswitch->oldThreadState ) == sizeof( uint8_t ), "Bad data size" );
Magic magic;
auto token = GetToken();
auto& tail = token->get_tail_index();
auto item = token->enqueue_begin( magic );
MemWrite( &item->hdr.type, QueueType::ContextSwitch );
MemWrite( &item->contextSwitch.time, hdr.TimeStamp.QuadPart );
memcpy( &item->contextSwitch.oldThread, &cswitch->oldThreadId, sizeof( cswitch->oldThreadId ) );
memcpy( &item->contextSwitch.newThread, &cswitch->newThreadId, sizeof( cswitch->newThreadId ) );
memset( ((char*)&item->contextSwitch.oldThread)+4, 0, 4 );
memset( ((char*)&item->contextSwitch.newThread)+4, 0, 4 );
MemWrite( &item->contextSwitch.cpu, record->BufferContext.ProcessorNumber );
MemWrite( &item->contextSwitch.reason, cswitch->oldThreadWaitReason );
MemWrite( &item->contextSwitch.state, cswitch->oldThreadState );
tail.store( magic + 1, std::memory_order_release );
Magic magic;
auto token = GetToken();
auto& tail = token->get_tail_index();
auto item = token->enqueue_begin( magic );
MemWrite( &item->hdr.type, QueueType::ThreadWakeup );
MemWrite( &item->threadWakeup.time, hdr.TimeStamp.QuadPart );
memcpy( &item->threadWakeup.thread, &rt->threadId, sizeof( rt->threadId ) );
memset( ((char*)&item->threadWakeup.thread)+4, 0, 4 );
tail.store( magic + 1, std::memory_order_release );
}
}
bool SysTraceStart()
@ -91,7 +108,7 @@ bool SysTraceStart()
const auto psz = sizeof( EVENT_TRACE_PROPERTIES ) + sizeof( KERNEL_LOGGER_NAME );
s_prop = (EVENT_TRACE_PROPERTIES*)tracy_malloc( psz );
memset( s_prop, 0, sizeof( EVENT_TRACE_PROPERTIES ) );
s_prop->EnableFlags = EVENT_TRACE_FLAG_CSWITCH;
s_prop->EnableFlags = EVENT_TRACE_FLAG_CSWITCH | EVENT_TRACE_FLAG_DISPATCHER;
s_prop->LogFileMode = EVENT_TRACE_REAL_TIME_MODE;
s_prop->Wnode.BufferSize = psz;
s_prop->Wnode.Flags = WNODE_FLAG_TRACED_GUID;

View File

@ -57,6 +57,7 @@ enum class QueueType : uint8_t
CallstackFrame,
SysTimeReport,
ContextSwitch,
ThreadWakeup,
StringData,
ThreadName,
CustomStringData,
@ -312,6 +313,12 @@ struct QueueContextSwitch
uint8_t state;
};
struct QueueThreadWakeup
{
int64_t time;
uint64_t thread;
};
struct QueueHeader
{
union
@ -358,6 +365,7 @@ struct QueueItem
QueueCrashReport crashReport;
QueueSysTime sysTime;
QueueContextSwitch contextSwitch;
QueueThreadWakeup threadWakeup;
};
};
#pragma pack()
@ -416,6 +424,7 @@ static const size_t QueueDataSize[] = {
sizeof( QueueHeader ) + sizeof( QueueCallstackFrame ),
sizeof( QueueHeader ) + sizeof( QueueSysTime ),
sizeof( QueueHeader ) + sizeof( QueueContextSwitch ),
sizeof( QueueHeader ) + sizeof( QueueThreadWakeup ),
// keep all QueueStringTransfer below
sizeof( QueueHeader ) + sizeof( QueueStringTransfer ), // string data
sizeof( QueueHeader ) + sizeof( QueueStringTransfer ), // thread name

View File

@ -235,6 +235,7 @@ enum { CrashEventSize = sizeof( CrashEvent ) };
struct ContextSwitchData
{
enum : int8_t { NoState = 100 };
enum : int8_t { Wakeup = -2 };
int64_t Start() const { return int64_t( _start_cpu ) >> 8; }
void SetStart( int64_t start ) { assert( start < ( 1ll << 47 ) ); _start_cpu = ( _start_cpu & 0xFF ) | uint64_t( start << 8 ); }
@ -249,6 +250,7 @@ struct ContextSwitchData
uint64_t _start_cpu;
uint64_t _end_reason_state;
int64_t wakeup;
};
enum { ContextSwitchDataSize = sizeof( ContextSwitchData ) };

View File

@ -7,7 +7,7 @@ namespace Version
{
enum { Major = 0 };
enum { Minor = 5 };
enum { Patch = 3 };
enum { Patch = 4 };
}
}

View File

@ -2372,43 +2372,62 @@ void View::DrawContextSwitches( const ContextSwitch* ctx, bool hover, double pxn
{
const bool migration = pit->Cpu() != ev.Cpu();
const auto px0 = std::max( { ( pit->End() - m_zvStart ) * pxns, -10.0, minpx } );
const auto pxw = std::max( ( ev.wakeup - m_zvStart ) * pxns, -10.0 );
const auto px1 = std::min( ( ev.Start() - m_zvStart ) * pxns, w + 10.0 );
const auto color = migration ? 0xFFEE7711 : 0xFF2222AA;
draw->AddLine( wpos + ImVec2( px0, round( offset + ty * 0.5 ) - 0.5 ), wpos + ImVec2( px1, round( offset + ty * 0.5 ) - 0.5 ), color, 2 );
if( hover && ImGui::IsMouseHoveringRect( wpos + ImVec2( px0, offset ), wpos + ImVec2( px1, offset + ty ) ) )
draw->AddLine( wpos + ImVec2( px0, round( offset + ty * 0.5 ) - 0.5 ), wpos + ImVec2( pxw, round( offset + ty * 0.5 ) - 0.5 ), color, 2 );
if( ev.wakeup != ev.Start() )
{
ImGui::BeginTooltip();
TextFocused( "Thread is", migration ? "migrating CPUs" : "waiting" );
TextFocused( "Waiting time:", TimeToString( ev.Start() - pit->End() ) );
if( migration )
{
TextFocused( "CPU:", RealToString( pit->Cpu(), true ) );
ImGui::SameLine();
#ifdef TRACY_EXTENDED_FONT
TextFocused( ICON_FA_LONG_ARROW_ALT_RIGHT, RealToString( ev.Cpu(), true ) );
#else
TextFocused( "->", RealToString( ev.Cpu(), true ) );
#endif
}
else
{
TextFocused( "CPU:", RealToString( ev.Cpu(), true ) );
}
if( pit->Reason() != 100 )
{
TextFocused( "Wait reason:", DecodeContextSwitchReasonCode( pit->Reason() ) );
ImGui::SameLine();
TextDisabledUnformatted( DecodeContextSwitchReason( pit->Reason() ) );
}
TextFocused( "Wait state:", DecodeContextSwitchStateCode( pit->State() ) );
ImGui::SameLine();
TextDisabledUnformatted( DecodeContextSwitchState( pit->State() ) );
ImGui::EndTooltip();
draw->AddLine( wpos + ImVec2( pxw, round( offset + ty * 0.5 ) - 0.5 ), wpos + ImVec2( px1, round( offset + ty * 0.5 ) - 0.5 ), 0xFF2280A0, 2 );
}
if( ImGui::IsMouseClicked( 2 ) )
if( hover )
{
if( ImGui::IsMouseHoveringRect( wpos + ImVec2( px0, offset ), wpos + ImVec2( pxw, offset + ty ) ) )
{
ZoomToRange( pit->End(), ev.Start() );
ImGui::BeginTooltip();
TextFocused( "Thread is", migration ? "migrating CPUs" : "waiting" );
TextFocused( "Waiting time:", TimeToString( ev.wakeup - pit->End() ) );
if( migration )
{
TextFocused( "CPU:", RealToString( pit->Cpu(), true ) );
ImGui::SameLine();
#ifdef TRACY_EXTENDED_FONT
TextFocused( ICON_FA_LONG_ARROW_ALT_RIGHT, RealToString( ev.Cpu(), true ) );
#else
TextFocused( "->", RealToString( ev.Cpu(), true ) );
#endif
}
else
{
TextFocused( "CPU:", RealToString( ev.Cpu(), true ) );
}
if( pit->Reason() != 100 )
{
TextFocused( "Wait reason:", DecodeContextSwitchReasonCode( pit->Reason() ) );
ImGui::SameLine();
TextDisabledUnformatted( DecodeContextSwitchReason( pit->Reason() ) );
}
TextFocused( "Wait state:", DecodeContextSwitchStateCode( pit->State() ) );
ImGui::SameLine();
TextDisabledUnformatted( DecodeContextSwitchState( pit->State() ) );
ImGui::EndTooltip();
if( ImGui::IsMouseClicked( 2 ) )
{
ZoomToRange( pit->End(), ev.wakeup );
}
}
else if( ev.wakeup != ev.Start() && ImGui::IsMouseHoveringRect( wpos + ImVec2( pxw, offset ), wpos + ImVec2( px1, offset + ty ) ) )
{
ImGui::BeginTooltip();
TextFocused( "Thread is", "waking up" );
TextFocused( "Scheduling delay:", TimeToString( ev.Start() - ev.wakeup ) );
if( ImGui::IsMouseClicked( 2 ) )
{
ZoomToRange( pit->End(), ev.wakeup );
}
ImGui::EndTooltip();
}
}
}

View File

@ -1415,7 +1415,17 @@ Worker::Worker( FileRead& f, EventType::Type eventMask )
auto ptr = data->v.data();
for( uint64_t j=0; j<csz; j++ )
{
ptr->SetStart( ReadTimeOffset( f, refTime ) );
if( fileVer >= FileVersion( 0, 5, 4 ) )
{
ptr->wakeup = ReadTimeOffset( f, refTime );
ptr->SetStart( ReadTimeOffset( f, refTime ) );
}
else
{
int64_t start = ReadTimeOffset( f, refTime );
ptr->wakeup = start;
ptr->SetStart( start );
}
int64_t diff;
f.Read( diff );
if( diff > 0 ) runningTime += diff;
@ -3062,6 +3072,9 @@ bool Worker::Process( const QueueItem& ev )
case QueueType::ContextSwitch:
ProcessContextSwitch( ev.contextSwitch );
break;
case QueueType::ThreadWakeup:
ProcessThreadWakeup( ev.threadWakeup );
break;
default:
assert( false );
break;
@ -4119,13 +4132,22 @@ void Worker::ProcessContextSwitch( const QueueContextSwitch& ev )
it = m_data.ctxSwitch.emplace( ev.newThread, ctx ).first;
}
auto& data = it->second->v;
assert( data.empty() || (uint64_t)data.back().End() <= time );
auto& item = data.push_next();
item.SetStart( time );
item.SetEnd( -1 );
item.SetCpu( ev.cpu );
item.SetReason( -1 );
item.SetState( -1 );
ContextSwitchData* item = nullptr;
if( !data.empty() && data.back().Reason() == ContextSwitchData::Wakeup )
{
item = &data.back();
}
else
{
assert( data.empty() || (uint64_t)data.back().End() <= time );
item = &data.push_next();
item->wakeup = time;
}
item->SetStart( time );
item->SetEnd( -1 );
item->SetCpu( ev.cpu );
item->SetReason( -1 );
item->SetState( -1 );
auto& cx = cs.push_next();
cx.SetStart( time );
@ -4140,6 +4162,28 @@ void Worker::ProcessContextSwitch( const QueueContextSwitch& ev )
}
}
void Worker::ProcessThreadWakeup( const QueueThreadWakeup& ev )
{
const auto time = TscTime( ev.time - m_data.baseTime );
m_data.lastTime = std::max( m_data.lastTime, time );
auto it = m_data.ctxSwitch.find( ev.thread );
if( it == m_data.ctxSwitch.end() )
{
auto ctx = m_slab.AllocInit<ContextSwitch>();
it = m_data.ctxSwitch.emplace( ev.thread, ctx ).first;
}
auto& data = it->second->v;
if( !data.empty() && data.back().End() < 0 ) return; // wakeup of a running thread
auto& item = data.push_next();
item.wakeup = time;
item.SetStart( time );
item.SetEnd( -1 );
item.SetCpu( 0 );
item.SetReason( ContextSwitchData::Wakeup );
item.SetState( -1 );
}
void Worker::MemAllocChanged( int64_t time )
{
const auto val = (double)m_data.memory.usage;
@ -4948,6 +4992,7 @@ void Worker::Write( FileWrite& f )
int64_t refTime = 0;
for( auto& cs : ctx->second->v )
{
WriteTimeOffset( f, refTime, cs.wakeup );
WriteTimeOffset( f, refTime, cs.Start() );
WriteTimeOffset( f, refTime, cs.End() );
uint8_t cpu = cs.Cpu();

View File

@ -440,6 +440,7 @@ private:
tracy_force_inline void ProcessCrashReport( const QueueCrashReport& ev );
tracy_force_inline void ProcessSysTime( const QueueSysTime& ev );
tracy_force_inline void ProcessContextSwitch( const QueueContextSwitch& ev );
tracy_force_inline void ProcessThreadWakeup( const QueueThreadWakeup& ev );
tracy_force_inline void ProcessZoneBeginImpl( ZoneEvent* zone, const QueueZoneBegin& ev );
tracy_force_inline void ProcessZoneBeginAllocSrcLocImpl( ZoneEvent* zone, const QueueZoneBegin& ev );