Scarfski/tracy
1
0
Fork 0
mirror of https://github.com/wolfpld/tracy.git synced 2026-09-15 14:54:23 +00:00
Code Issues Packages Projects Releases Wiki Activity

Fix and refactor zone running time

Browse Source 
Many of the zones would have a negative running time due to a missing `cs->IsEndValid()` check.
This could end reporting context switches before the zone start, due to `cs->End()` returning -1.

This happened when systrace dropped event, or when using Fibers and `TracyFiberEnter` is called on the new thread once the fiber has been scheduled. (The manual actually does not really hint this is wrong, we should probably fix the manual or the server code.)

In both cases, we assume runtime to be 0 for that context switch. Since we have no actual information. Both options (counting full runtime or no runtime) are wrong, and most of the code handling `!cs->IsEndValid()` uses `Start` instead so that's what I did. This is still a net improvement over displaying negative values. If we want to change this handling, we'd need to review the other places that do `it->IsEndValid() ? it->End() : it->Start()` as well.

It also seems two different concepts were being mixed:
1. Do we have any context switch data at all ? (`it != ctx->v.end()` ie `count != 0`)
2. Do we have complete data for the last context switch (`eit != ctx->v.end()`)

This led to some places of the code not displaying or counting running time at all, notably when hovering a zone.

I think most of the time we wanted 1, as it reports correctly and assumes the last context switch is still running, which is a fair assumption if we didn't see one putting the thread to sleep.

I also fixed a case where we were overcounting runtime when range start was during a sleep.
This commit is contained in:
Clément Grégoire
2026-04-29 15:01:50 +02:00
parent 217bdcf5a9
commit 91c0b1e42b
6 changed files with 97 additions and 98 deletions
Download Patch File Download Diff File Expand all files Collapse all files

6
profiler/src/profiler/TracyView.hpp
View File

@@ -399,8 +399,10 @@ private:
int64_t GetZoneChildTimeFastClamped( const ZoneEvent& zone, int64_t t0, int64_t t1 );
int64_t GetZoneSelfTime( const ZoneEvent& zone );
int64_t GetZoneSelfTime( const GpuEvent& zone );
bool GetZoneRunningTime( const ContextSwitch* ctx, const ZoneEvent& ev, int64_t& time, uint64_t& cnt );
bool GetZoneRunningTime( const ContextSwitch* ctx, const ZoneEvent& ev, const RangeSlim& range, int64_t& time, uint64_t& cnt );
uint64_t GetRunningCsRange( const ContextSwitch* ctx, int64_t start, int64_t end, const ContextSwitchData*& outRunningBegin, const ContextSwitchData*& outRunningEnd, bool* incomplete = nullptr ) const;
void ComputeRunningTime( int64_t start, int64_t end, const ContextSwitchData* outRunningBegin, const ContextSwitchData* outRunningEnd, int64_t& time, uint8_t* cpus/*[256]*/ = nullptr ) const;
uint64_t GetZoneRunningTime( const ContextSwitch* ctx, const ZoneEvent& ev, int64_t& time, bool* incomplete = nullptr ) const;
uint64_t GetZoneRunningTime( const ContextSwitch* ctx, const ZoneEvent& ev, const RangeSlim& range, int64_t& time, bool* incomplete = nullptr ) const;
const char* GetThreadContextData( uint64_t thread, bool& local, bool& untracked, const char*& program );
tracy_force_inline void CalcZoneTimeData( unordered_flat_map<int16_t, ZoneTimeData>& data, int64_t& ztime, const ZoneEvent& zone );

28
profiler/src/profiler/TracyView_FindZone.cpp
View File

@@ -132,9 +132,8 @@ void View::DrawZoneList( int id, const Vector<short_ptr<ZoneEvent>>& zones )
const auto ctx0 = m_worker.GetContextSwitchData( GetZoneThread( *lhs ) );
const auto ctx1 = m_worker.GetContextSwitchData( GetZoneThread( *rhs ) );
int64_t t0, t1;
uint64_t c0, c1;
GetZoneRunningTime( ctx0, *lhs, t0, c0 );
GetZoneRunningTime( ctx1, *rhs, t1, c1 );
GetZoneRunningTime( ctx0, *lhs, t0 );
GetZoneRunningTime( ctx1, *rhs, t1 );
return t0 > t1;
} );
}
@@ -144,9 +143,8 @@ void View::DrawZoneList( int id, const Vector<short_ptr<ZoneEvent>>& zones )
const auto ctx0 = m_worker.GetContextSwitchData( GetZoneThread( *lhs ) );
const auto ctx1 = m_worker.GetContextSwitchData( GetZoneThread( *rhs ) );
int64_t t0, t1;
uint64_t c0, c1;
GetZoneRunningTime( ctx0, *lhs, t0, c0 );
GetZoneRunningTime( ctx1, *rhs, t1, c1 );
GetZoneRunningTime( ctx0, *lhs, t0 );
GetZoneRunningTime( ctx1, *rhs, t1 );
return t0 < t1;
} );
}
@@ -208,8 +206,7 @@ void View::DrawZoneList( int id, const Vector<short_ptr<ZoneEvent>>& zones )
if( m_findZone.runningTime )
{
const auto ctx = m_worker.GetContextSwitchData( GetZoneThread( *ev ) );
uint64_t cnt;
GetZoneRunningTime( ctx, *ev, timespan, cnt );
GetZoneRunningTime( ctx, *ev, timespan );
}
else
{
@@ -459,8 +456,7 @@ void View::DrawFindZone()
const auto ctx = m_worker.GetContextSwitchData( m_worker.DecompressThread( zones[i].Thread() ) );
if( !ctx ) break;
int64_t t;
uint64_t cnt;
if( !GetZoneRunningTime( ctx, zone, t, cnt ) ) break;
if( !GetZoneRunningTime( ctx, zone, t ) ) break;
vec.push_back_no_space_check( t );
total += t;
if( t < tmin ) tmin = t;
@@ -475,8 +471,7 @@ void View::DrawFindZone()
const auto ctx = m_worker.GetContextSwitchData( m_worker.DecompressThread( zones[i].Thread() ) );
if( !ctx ) break;
int64_t t;
uint64_t cnt;
if( !GetZoneRunningTime( ctx, zone, t, cnt ) ) break;
if( !GetZoneRunningTime( ctx, zone, t ) ) break;
vec.push_back_no_space_check( t );
total += t;
if( t < tmin ) tmin = t;
@@ -590,8 +585,7 @@ void View::DrawFindZone()
{
const auto ctx = m_worker.GetContextSwitchData( m_worker.DecompressThread( zones[i].Thread() ) );
int64_t t;
uint64_t cnt;
GetZoneRunningTime( ctx, *ev.Zone(), t, cnt );
GetZoneRunningTime( ctx, *ev.Zone(), t );
vec.push_back_no_space_check( t );
act++;
total += t;
@@ -608,8 +602,7 @@ void View::DrawFindZone()
{
const auto ctx = m_worker.GetContextSwitchData( m_worker.DecompressThread( zones[i].Thread() ) );
int64_t t;
uint64_t cnt;
GetZoneRunningTime( ctx, *ev.Zone(), t, cnt );
GetZoneRunningTime( ctx, *ev.Zone(), t );
vec.push_back_no_space_check( t );
act++;
total += t;
@@ -1667,8 +1660,7 @@ void View::DrawFindZone()
const auto ctx = m_worker.GetContextSwitchData( m_worker.DecompressThread( ev.Thread() ) );
if( !ctx ) break;
int64_t t;
uint64_t cnt;
if( !GetZoneRunningTime( ctx, *ev.Zone(), t, cnt ) ) break;
if( !GetZoneRunningTime( ctx, *ev.Zone(), t ) ) break;
timespan = t;
}

10
profiler/src/profiler/TracyView_FlameGraph.cpp
View File

@@ -144,14 +144,13 @@ void View::BuildFlameGraph( const Worker& worker, std::vector<FlameGraphItem>& d
if( !v.IsEndValid() ) break;
const auto srcloc = v.SrcLoc();
int64_t duration;
uint64_t cnt;
if ( m_flameRange.active )
{
if( !GetZoneRunningTime( ctx, v, m_flameGraphInvariant.range, duration, cnt ) ) continue;
if( !GetZoneRunningTime( ctx, v, m_flameGraphInvariant.range, duration ) ) continue;
}
else
{
if( !GetZoneRunningTime( ctx, v, duration, cnt ) ) break;
if( !GetZoneRunningTime( ctx, v, duration ) ) break;
}
if( srcloc == last )
@@ -197,14 +196,13 @@ void View::BuildFlameGraph( const Worker& worker, std::vector<FlameGraphItem>& d
if( !v->IsEndValid() ) break;
const auto srcloc = v->SrcLoc();
int64_t duration;
uint64_t cnt;
if ( m_flameRange.active )
{
if( !GetZoneRunningTime( ctx, *v, m_flameGraphInvariant.range, duration, cnt ) ) continue;
if( !GetZoneRunningTime( ctx, *v, m_flameGraphInvariant.range, duration ) ) continue;
}
else
{
if( !GetZoneRunningTime( ctx, *v, duration, cnt ) ) break;
if( !GetZoneRunningTime( ctx, *v, duration ) ) break;
}
if( srcloc == last )

86
profiler/src/profiler/TracyView_Utility.cpp
View File

@@ -702,61 +702,75 @@ int64_t View::GetZoneSelfTime( const GpuEvent& zone )
return selftime;
}
bool View::GetZoneRunningTime( const ContextSwitch* ctx, const ZoneEvent& ev, int64_t& time, uint64_t& cnt )
uint64_t View::GetRunningCsRange( const ContextSwitch* ctx, int64_t start, int64_t end, const ContextSwitchData*& outRunningBegin, const ContextSwitchData*& outRunningEnd, bool* incomplete ) const
{
auto it = std::lower_bound( ctx->v.begin(), ctx->v.end(), ev.Start(), [] ( const auto& l, const auto& r ) { return (uint64_t)l.End() < (uint64_t)r; } );
if( it == ctx->v.end() ) return false;
const auto end = m_worker.GetZoneEnd( ev );
const auto eit = std::upper_bound( it, ctx->v.end(), end, [] ( const auto& l, const auto& r ) { return l < r.Start(); } );
if( eit == ctx->v.end() ) return false;
cnt = std::distance( it, eit );
if( cnt == 0 ) return false;
if( cnt == 1 )
if( incomplete ) *incomplete = false;
outRunningBegin = std::lower_bound( ctx->v.begin(), ctx->v.end(), start, []( const ContextSwitchData& l, int64_t r ) { return l.EndOrStart() < r; } );
if( outRunningBegin == ctx->v.end() )
{
time = end - ev.Start();
outRunningEnd = ctx->v.end();
return 0; // No data
}
else
{
int64_t running = it->End() - ev.Start();
++it;
for( uint64_t i=0; i<cnt-2; i++ )
{
running += it->End() - it->Start();
++it;
}
running += end - it->Start();
time = running;
}
return true;
outRunningEnd = std::upper_bound( outRunningBegin, ctx->v.end(), end, []( int64_t l, const ContextSwitchData& r ) { return l < r.Start(); } );
if( incomplete ) *incomplete = outRunningEnd == ctx->v.end();
return std::distance( outRunningBegin, outRunningEnd );
}
bool View::GetZoneRunningTime( const ContextSwitch* ctx, const ZoneEvent& ev, const RangeSlim& range, int64_t& time, uint64_t& cnt )
void View::ComputeRunningTime( int64_t start, int64_t end, const ContextSwitchData* it, const ContextSwitchData* eit, int64_t& time, uint8_t* cpus/*[256]*/ ) const
{
const auto start = std::max( ev.Start(), range.min );
auto it = std::lower_bound( ctx->v.begin(), ctx->v.end(), start, [] ( const auto& l, const auto& r ) { return (uint64_t)l.End() < (uint64_t)r; } );
if( it == ctx->v.end() ) return false;
const auto end = std::min( m_worker.GetZoneEnd( ev ), range.max );
const auto eit = std::upper_bound( it, ctx->v.end(), end, [] ( const auto& l, const auto& r ) { return l < r.Start(); } );
if( eit == ctx->v.end() ) return false;
cnt = std::distance( it, eit );
if( cnt == 0 ) return false;
const ptrdiff_t cnt = std::distance( it, eit );
if( cnt <= 0 )
{
time = 0;
return;
}
// First CS start may be past `start` if the thread was sleeping or the previous CS was incomplete.
const int64_t runStart = std::max( start, it->Start() );
if( cnt == 1 )
{
time = end - start;
time = end - runStart;
}
else
{
int64_t running = it->End() - start;
int64_t running = it->EndOrStart() - runStart;
if( cpus ) cpus[it->Cpu()] = 1;
++it;
for( uint64_t i=0; i<cnt-2; i++ )
{
running += it->End() - it->Start();
running += it->EndOrStart() - it->Start();
if( cpus ) cpus[it->Cpu()] = 1;
++it;
}
running += end - it->Start();
if( cpus ) cpus[it->Cpu()] = 1;
time = running;
}
return true;
}
uint64_t View::GetZoneRunningTime( const ContextSwitch* ctx, const ZoneEvent& ev, int64_t& time, bool* incomplete ) const
{
const ContextSwitchData* it = nullptr;
const ContextSwitchData* eit = nullptr;
const int64_t start = ev.Start();
const int64_t end = m_worker.GetZoneEnd( ev );
const uint64_t cnt = GetRunningCsRange( ctx, start, end, it, eit, incomplete );
ComputeRunningTime( start, end, it, eit, time, nullptr );
return cnt;
}
uint64_t View::GetZoneRunningTime( const ContextSwitch* ctx, const ZoneEvent& ev, const RangeSlim& range, int64_t& time, bool* incomplete ) const
{
const ContextSwitchData* it = nullptr;
const ContextSwitchData* eit = nullptr;
const int64_t start = std::max( ev.Start(), range.min );
const int64_t end = std::min( m_worker.GetZoneEnd( ev ), range.max );
const uint64_t cnt = GetRunningCsRange( ctx, start, end, it, eit, incomplete );
ComputeRunningTime( start, end, it, eit, time, nullptr );
return cnt;
}
const char* View::SourceSubstitution( const char* srcFile ) const

64
profiler/src/profiler/TracyView_ZoneInfo.cpp
View File

@@ -98,8 +98,7 @@ void View::CalcZoneTimeDataImpl( const V& children, const ContextSwitch* ctx, un
for( auto& child : children )
{
int64_t t;
uint64_t cnt;
const auto res = GetZoneRunningTime( ctx, a(child), t, cnt );
const auto res = GetZoneRunningTime( ctx, a(child), t );
assert( res );
zt -= t;
}
@@ -109,8 +108,7 @@ void View::CalcZoneTimeDataImpl( const V& children, const ContextSwitch* ctx, un
{
const auto srcloc = a(child).SrcLoc();
int64_t t;
uint64_t cnt;
const auto res = GetZoneRunningTime( ctx, a(child), t, cnt );
const auto res = GetZoneRunningTime( ctx, a(child), t );
assert( res );
auto it = data.find( srcloc );
if( it == data.end() )
@@ -366,13 +364,19 @@ void View::DrawZoneInfoWindow()
const auto ctx = m_worker.GetContextSwitchData( tid );
if( ctx )
{
auto it = std::lower_bound( ctx->v.begin(), ctx->v.end(), ev.Start(), [] ( const auto& l, const auto& r ) { return (uint64_t)l.End() < (uint64_t)r; } );
if( it != ctx->v.end() )
const ContextSwitchData* it = nullptr;
const ContextSwitchData* eit = nullptr;
const int64_t zstart = ev.Start();
const int64_t zend = m_worker.GetZoneEnd( ev );
bool incomplete = false;
const uint64_t cnt = GetRunningCsRange( ctx, zstart, zend, it, eit, &incomplete );
incomplete = incomplete && !m_worker.IsThreadFiber( tid ); // Don't consider incomplete for fibers
if( cnt != 0 )
{
const auto end = m_worker.GetZoneEnd( ev );
auto eit = std::upper_bound( it, ctx->v.end(), end, [] ( const auto& l, const auto& r ) { return l < r.Start(); } );
bool incomplete = eit == ctx->v.end() && !m_worker.IsThreadFiber( tid );
uint64_t cnt = std::distance( it, eit );
int64_t running = 0;
uint8_t cpus[256] = {};
ComputeRunningTime( zstart, zend, it, eit, running, cpus );
if( cnt == 1 )
{
if( !incomplete )
@@ -387,19 +391,6 @@ void View::DrawZoneInfoWindow()
}
else if( cnt > 1 )
{
uint8_t cpus[256] = {};
auto bit = it;
int64_t running = it->End() - ev.Start();
cpus[it->Cpu()] = 1;
++it;
for( uint64_t i=0; i<cnt-2; i++ )
{
running += it->End() - it->Start();
cpus[it->Cpu()] = 1;
++it;
}
running += end - it->Start();
cpus[it->Cpu()] = 1;
TextFocused( "Running state time:", TimeToString( running ) );
if( ztime != 0 )
{
@@ -479,7 +470,7 @@ void View::DrawZoneInfoWindow()
ImGui::SameLine();
SmallCheckbox( "Time relative to zone start", &m_ctxSwitchTimeRelativeToZone );
const int64_t adjust = m_ctxSwitchTimeRelativeToZone ? ev.Start() : 0;
const auto wrsz = eit - bit;
const auto wrsz = eit - it;
const auto numColumns = threadData->isFiber ? 4 : 6;
if( ImGui::BeginTable( "##waitregions", numColumns, ImGuiTableFlags_Resizable | ImGuiTableFlags_ScrollY | ImGuiTableFlags_Reorderable | ImGuiTableFlags_Hideable, ImVec2( 0, ImGui::GetTextLineHeightWithSpacing() * std::min<int64_t>( 1+wrsz, 15 ) ) ) )
@@ -506,9 +497,9 @@ void View::DrawZoneInfoWindow()
{
for( auto i=clipper.DisplayStart; i<clipper.DisplayEnd; i++ )
{
const auto cend = bit[i].End();
const auto cstart = bit[i+1].Start();
const auto cwakeup = bit[i+1].WakeupVal();
const auto cend = it[i].End();
const auto cstart = it[i+1].Start();
const auto cwakeup = it[i+1].WakeupVal();
ImGui::PushID( i );
ImGui::TableNextRow();
@@ -533,17 +524,17 @@ void View::DrawZoneInfoWindow()
ImGui::TableNextColumn();
if( threadData->isFiber )
{
const auto ftid = m_worker.DecompressThread( bit[i].Thread() );
const auto ftid = m_worker.DecompressThread( it[i].Thread() );
ImGui::TextUnformatted( m_worker.GetThreadName( ftid ) );
ImGui::SameLine();
ImGui::TextDisabled( "(%s)", RealToString( ftid ) );
}
else
{
const auto cpu0 = bit[i].Cpu();
const auto reason = bit[i].Reason();
const auto state = bit[i].State();
const auto cpu1 = bit[i+1].Cpu();
const auto cpu0 = it[i].Cpu();
const auto reason = it[i].Reason();
const auto state = it[i].State();
const auto cpu1 = it[i+1].Cpu();
if( cstart != cwakeup )
{
@@ -983,8 +974,9 @@ void View::DrawZoneInfoWindow()
{
assert( ctx );
int64_t time;
uint64_t cnt;
if( !GetZoneRunningTime( ctx, ev, time, cnt ) )
bool incomplete = false;
const uint64_t cnt = GetZoneRunningTime( ctx, ev, time, &incomplete );
if( incomplete || cnt == 0 )
{
TextDisabledUnformatted( "Incomplete context switch data." );
m_timeDist.dataValidFor = nullptr;
@@ -1889,8 +1881,8 @@ void View::ZoneTooltip( const ZoneEvent& ev )
if( ctx )
{
int64_t time;
uint64_t cnt;
if( GetZoneRunningTime( ctx, ev, time, cnt ) )
const uint64_t cnt = GetZoneRunningTime( ctx, ev, time );
if( cnt != 0 )
{
TextFocused( "Running state time:", TimeToString( time ) );
if( ztime != 0 )

1
server/TracyEvent.hpp
View File

@@ -563,6 +563,7 @@ struct ContextSwitchData
tracy_force_inline int64_t End() const { return _end.Val(); }
tracy_force_inline void SetEnd( int64_t end ) { assert( end < (int64_t)( 1ull << 47 ) ); _end = end; }
tracy_force_inline bool IsEndValid() const { return _end.IsNonNegative(); }
tracy_force_inline int64_t EndOrStart() const { return _end.IsNonNegative() ? _end.Val() : _start.Val(); }
tracy_force_inline uint8_t Cpu() const { return _cpu; }
tracy_force_inline void SetCpu( uint8_t cpu ) { _cpu = cpu; }
tracy_force_inline uint8_t WakeupCpu() const { return _wakeupcpu; }