// Copyright Epic Games, Inc. All Rights Reserved. #include "Analysis/Engine.h" #include "Algo/BinarySearch.h" #include "Algo/Sort.h" #include "Algo/StableSort.h" #include "Containers/ArrayView.h" #include "CoreGlobals.h" #include "HAL/UnrealMemory.h" #include "Internationalization/Internationalization.h" #include "Logging/LogMacros.h" #include "Misc/StringBuilder.h" #include "StreamReader.h" #include "Templates/UnrealTemplate.h" #include "TraceAnalysisDebug.h" #include "Trace/Analysis.h" #include "Trace/Analyzer.h" #include "Trace/Detail/Protocol.h" #include "Trace/Detail/Transport.h" #include "Transport/PacketTransport.h" #include "Transport/TidPacketTransport.h" #include "Transport/Transport.h" DEFINE_LOG_CATEGORY_STATIC(LogTraceAnalysis, Log, All) #define LOCTEXT_NAMESPACE "TraceAnalysis" namespace UE { namespace Trace { // {{{1 misc ------------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// void SerializeToCborImpl(TArray&, const IAnalyzer::FEventData&, uint32); //////////////////////////////////////////////////////////////////////////////// class FFnv1aHash { public: FFnv1aHash() = default; FFnv1aHash(uint32 PrevResult) { Result = PrevResult; } void Add(const ANSICHAR* String) { for (; *String; ++String) { Add(*String); } } void Add(const uint8* Data, uint32 Size) { for (uint32 i = 0; i < Size; ++Data, ++i) { Add(*Data); } } void Add(uint8 Value) { Result ^= Value; Result *= 0x01000193; } uint32 Get() const { return Result; } private: uint32 Result = 0x811c9dc5; // uint32: bias=0x811c9dc5 prime=0x01000193 // uint64: bias=0xcbf29ce484222325 prime=0x00000100000001b3; }; // {{{1 aux-data --------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// struct FAuxData { const uint8* Data; uint32 DataSize; uint16 FieldIndex; int8 FieldSizeAndType; uint8 bSigned : 1; uint8 bFragmented : 1; uint8 bOwnsData : 1; uint8 _Unused : 5; }; //////////////////////////////////////////////////////////////////////////////// struct FAuxDataCollector : public TArray> { using Super = TArray>; ~FAuxDataCollector() { Reset(); } void Add(const FAuxData& Data); void Defragment(FAuxData& Head); void Reset(); }; //////////////////////////////////////////////////////////////////////////////// void FAuxDataCollector::Add(const FAuxData& Data) { if (Num() == 0) { Super::Add(Data); return; } FAuxData* Prev = &Last(); if (Prev->FieldIndex != Data.FieldIndex) { Super::Add(Data); return; } while (Prev > GetData()) { if (Prev[-1].FieldIndex != Data.FieldIndex) { break; } --Prev; } Prev->bFragmented = 1; Super::Add(Data); } //////////////////////////////////////////////////////////////////////////////// void FAuxDataCollector::Defragment(FAuxData& Data) { check(Data.bFragmented); uint32 Size = Data.DataSize; for (FAuxData* Read = &Data + 1;;) { Size += Read->DataSize; ++Read; if (Read > &Last() || Read->FieldIndex != Data.FieldIndex) { break; } } uint8* Buffer = (uint8*)(FMemory::Malloc(Size)); uint8* Write = Buffer; uint8* End = Buffer + Size; for (FAuxData* Read = &Data;; ++Read) { FMemory::Memcpy(Write, Read->Data, Read->DataSize); Write += Read->DataSize; if (Write >= End) { break; } } Data.Data = Buffer; Data.DataSize = Size; Data.bOwnsData = 1; Data.bFragmented = 0; } //////////////////////////////////////////////////////////////////////////////// void FAuxDataCollector::Reset() { for (const FAuxData& AuxData : *this) { if (!AuxData.bOwnsData) { continue; } FMemory::Free((void*)(AuxData.Data)); } Super::Reset(); } // {{{1 threads ---------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FThreads { public: struct FInfo { TArray ScopeRoutes; TArray Name; TArray GroupName; int64 PrevTimestamp = 0; uint32 ThreadId = ~0u; uint32 SystemId = 0; int32 SortHint = 0xff; }; FThreads(); ~FThreads(); FInfo* GetInfo(); FInfo* GetInfo(uint32 ThreadId); void SetGroupName(const ANSICHAR* InGroupName, uint32 Length); const TArray*GetGroupName() const; private: uint32 LastGetInfoId = ~0u; TArray Infos; TArray GroupName; }; //////////////////////////////////////////////////////////////////////////////// FThreads::FThreads() { Infos.Reserve(64); } //////////////////////////////////////////////////////////////////////////////// FThreads::~FThreads() { for (FInfo* Info : Infos) { delete Info; } } //////////////////////////////////////////////////////////////////////////////// FThreads::FInfo* FThreads::GetInfo() { return GetInfo(LastGetInfoId); } //////////////////////////////////////////////////////////////////////////////// FThreads::FInfo* FThreads::GetInfo(uint32 ThreadId) { LastGetInfoId = ThreadId; if (ThreadId >= uint32(Infos.Num())) { Infos.SetNumZeroed(ThreadId + 1); } FInfo* Info = Infos[ThreadId]; if (Info == nullptr) { Info = new FInfo(); Info->ThreadId = ThreadId; Infos[ThreadId] = Info; } return Info; } //////////////////////////////////////////////////////////////////////////////// void FThreads::SetGroupName(const ANSICHAR* InGroupName, uint32 Length) { if (InGroupName == nullptr || *InGroupName == '\0') { GroupName.SetNum(0); return; } GroupName.SetNumUninitialized(Length + 1); GroupName[Length] = '\0'; FMemory::Memcpy(GroupName.GetData(), InGroupName, Length); } //////////////////////////////////////////////////////////////////////////////// const TArray* FThreads::GetGroupName() const { return (GroupName.Num() > 0) ? &GroupName : nullptr; } // {{{1 thread-info ------------------------------------------------------------ //////////////////////////////////////////////////////////////////////////////// uint32 IAnalyzer::FThreadInfo::GetId() const { const auto* Info = (const FThreads::FInfo*)this; return Info->ThreadId; } //////////////////////////////////////////////////////////////////////////////// uint32 IAnalyzer::FThreadInfo::GetSystemId() const { const auto* Info = (const FThreads::FInfo*)this; return Info->SystemId; } //////////////////////////////////////////////////////////////////////////////// int32 IAnalyzer::FThreadInfo::GetSortHint() const { const auto* Info = (const FThreads::FInfo*)this; return Info->SortHint; } //////////////////////////////////////////////////////////////////////////////// const ANSICHAR* IAnalyzer::FThreadInfo::GetName() const { const auto* Info = (const FThreads::FInfo*)this; if (Info->Name.Num() <= 0) { return nullptr; } return (const ANSICHAR*)(Info->Name.GetData()); } //////////////////////////////////////////////////////////////////////////////// const ANSICHAR* IAnalyzer::FThreadInfo::GetGroupName() const { const auto* Info = (const FThreads::FInfo*)this; if (Info->GroupName.Num() <= 0) { return ""; } return (const ANSICHAR*)(Info->GroupName.GetData()); } // {{{1 timing ----------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// struct FTiming { uint64 BaseTimestamp = 0; uint64 TimestampHz = 0; double InvTimestampHz = 0.0; uint64 EventTimestamp = 0; }; //////////////////////////////////////////////////////////////////////////////// uint64 IAnalyzer::FEventTime::GetTimestamp() const { const auto* Timing = (const FTiming*)this; return Timing->EventTimestamp; } //////////////////////////////////////////////////////////////////////////////// double IAnalyzer::FEventTime::AsSeconds() const { const auto* Timing = (const FTiming*)this; return double(Timing->EventTimestamp) * Timing->InvTimestampHz; } //////////////////////////////////////////////////////////////////////////////// uint64 IAnalyzer::FEventTime::AsCycle64() const { const auto* Timing = (const FTiming*)this; return Timing->BaseTimestamp + Timing->EventTimestamp; } //////////////////////////////////////////////////////////////////////////////// double IAnalyzer::FEventTime::AsSeconds(uint64 Cycles64) const { const auto* Timing = (const FTiming*)this; return double(int64(Cycles64) - int64(Timing->BaseTimestamp)) * Timing->InvTimestampHz; } //////////////////////////////////////////////////////////////////////////////// double IAnalyzer::FEventTime::AsSecondsAbsolute(int64 DurationCycles64) const { const auto* Timing = (const FTiming*)this; return double(DurationCycles64) * Timing->InvTimestampHz; } // {{{1 dispatch --------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// struct FDispatch { enum { Flag_Important = 1 << 0, Flag_MaybeHasAux = 1 << 1, Flag_NoSync = 1 << 2, Flag_Definition = 1 << 3, }; struct FField { uint32 Hash; uint16 Offset; uint16 Size; uint16 NameOffset; // From FField ptr int8 SizeAndType; // value == byte_size, sign == float < 0 < int uint8 Class : 7; uint8 bArray : 1; uint32 RefUid; // If reference field, uid of ref type }; int32 GetFieldIndex(const ANSICHAR* Name) const; uint32 Hash = 0; uint16 Uid = 0; uint8 FieldCount = 0; uint8 Flags = 0; uint16 EventSize = 0; uint16 LoggerNameOffset = 0; // From FDispatch ptr uint16 EventNameOffset = 0; // From FDispatch ptr FField Fields[]; }; //////////////////////////////////////////////////////////////////////////////// int32 FDispatch::GetFieldIndex(const ANSICHAR* Name) const { FFnv1aHash NameHash; NameHash.Add(Name); for (int32 i = 0, n = FieldCount; i < n; ++i) { if (Fields[i].Hash == NameHash.Get()) { return i; } } return -1; } // {{{1 dispatch-builder ------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FDispatchBuilder { public: FDispatchBuilder(); void SetUid(uint16 Uid); void SetLoggerName(const ANSICHAR* Name, int32 NameSize=-1); void SetEventName(const ANSICHAR* Name, int32 NameSize=-1); void SetImportant(); void SetMaybeHasAux(); void SetNoSync(); void SetDefinition(); FDispatch::FField& AddField(const ANSICHAR* Name, int32 NameSize, uint16 Size); FDispatch* Finalize(); private: uint32 AppendName(const ANSICHAR* Name, int32 NameSize); TArray Buffer; TArray NameBuffer; }; //////////////////////////////////////////////////////////////////////////////// FDispatchBuilder::FDispatchBuilder() { Buffer.SetNum(sizeof(FDispatch)); auto* Dispatch = (FDispatch*)(Buffer.GetData()); new (Dispatch) FDispatch(); } //////////////////////////////////////////////////////////////////////////////// FDispatch* FDispatchBuilder::Finalize() { int32 Size = Buffer.Num() + NameBuffer.Num(); auto* Dispatch = (FDispatch*)FMemory::Malloc(Size); memcpy(Dispatch, Buffer.GetData(), Buffer.Num()); memcpy(Dispatch->Fields + Dispatch->FieldCount, NameBuffer.GetData(), NameBuffer.Num()); // Fix up name offsets for (int i = 0, n = Dispatch->FieldCount; i < n; ++i) { auto* Field = Dispatch->Fields + i; Field->NameOffset += (uint16)(Buffer.Num() - uint32(UPTRINT(Field) - UPTRINT(Dispatch))); } // Calculate this dispatch's hash. if (Dispatch->LoggerNameOffset || Dispatch->EventNameOffset) { Dispatch->LoggerNameOffset += (uint16)Buffer.Num(); Dispatch->EventNameOffset += (uint16)Buffer.Num(); FFnv1aHash Hash; Hash.Add((const ANSICHAR*)Dispatch + Dispatch->LoggerNameOffset); Hash.Add((const ANSICHAR*)Dispatch + Dispatch->EventNameOffset); Dispatch->Hash = Hash.Get(); } return Dispatch; } //////////////////////////////////////////////////////////////////////////////// void FDispatchBuilder::SetUid(uint16 Uid) { auto* Dispatch = (FDispatch*)(Buffer.GetData()); Dispatch->Uid = Uid; } //////////////////////////////////////////////////////////////////////////////// void FDispatchBuilder::SetLoggerName(const ANSICHAR* Name, int32 NameSize) { auto* Dispatch = (FDispatch*)(Buffer.GetData()); Dispatch->LoggerNameOffset += (uint16)AppendName(Name, NameSize); } //////////////////////////////////////////////////////////////////////////////// void FDispatchBuilder::SetEventName(const ANSICHAR* Name, int32 NameSize) { auto* Dispatch = (FDispatch*)(Buffer.GetData()); Dispatch->EventNameOffset = (uint16)AppendName(Name, NameSize); } //////////////////////////////////////////////////////////////////////////////// void FDispatchBuilder::SetImportant() { auto* Dispatch = (FDispatch*)(Buffer.GetData()); Dispatch->Flags |= FDispatch::Flag_Important; } //////////////////////////////////////////////////////////////////////////////// void FDispatchBuilder::SetMaybeHasAux() { auto* Dispatch = (FDispatch*)(Buffer.GetData()); Dispatch->Flags |= FDispatch::Flag_MaybeHasAux; } //////////////////////////////////////////////////////////////////////////////// void FDispatchBuilder::SetNoSync() { auto* Dispatch = (FDispatch*)(Buffer.GetData()); Dispatch->Flags |= FDispatch::Flag_NoSync; } //////////////////////////////////////////////////////////////////////////////// void FDispatchBuilder::SetDefinition() { auto* Dispatch = (FDispatch*)(Buffer.GetData()); Dispatch->Flags |= FDispatch::Flag_Definition; } //////////////////////////////////////////////////////////////////////////////// FDispatch::FField& FDispatchBuilder::AddField(const ANSICHAR* Name, int32 NameSize, uint16 Size) { int32 Bufoff = Buffer.AddUninitialized(sizeof(FDispatch::FField)); auto* Field = (FDispatch::FField*)(Buffer.GetData() + Bufoff); Field->NameOffset = (uint16)AppendName(Name, NameSize); Field->Size = Size; Field->RefUid = 0; FFnv1aHash Hash; Hash.Add((const uint8*)Name, NameSize); Field->Hash = Hash.Get(); auto* Dispatch = (FDispatch*)(Buffer.GetData()); Dispatch->FieldCount++; Dispatch->EventSize += Field->Size; return *Field; } //////////////////////////////////////////////////////////////////////////////// uint32 FDispatchBuilder::AppendName(const ANSICHAR* Name, int32 NameSize) { if (NameSize < 0) { NameSize = int32(FCStringAnsi::Strlen(Name)); } int32 Ret = NameBuffer.AddUninitialized(NameSize + 1); uint8* Out = NameBuffer.GetData() + Ret; memcpy(Out, Name, NameSize); Out[NameSize] = '\0'; return Ret; } // {{{1 event-type-info -------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// uint32 IAnalyzer::FEventTypeInfo::GetId() const { const auto* Inner = (const FDispatch*)this; return Inner->Uid; } //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG_API uint8 IAnalyzer::FEventTypeInfo::GetFlags() const { const auto* Inner = (const FDispatch*)this; return Inner->Flags; } #endif // UE_TRACE_ANALYSIS_DEBUG_API //////////////////////////////////////////////////////////////////////////////// const ANSICHAR* IAnalyzer::FEventTypeInfo::GetName() const { const auto* Inner = (const FDispatch*)this; return (const ANSICHAR*)Inner + Inner->EventNameOffset; } //////////////////////////////////////////////////////////////////////////////// const ANSICHAR* IAnalyzer::FEventTypeInfo::GetLoggerName() const { const auto* Inner = (const FDispatch*)this; return (const ANSICHAR*)Inner + Inner->LoggerNameOffset; } //////////////////////////////////////////////////////////////////////////////// uint32 IAnalyzer::FEventTypeInfo::GetSize() const { const auto* Inner = (const FDispatch*)this; return Inner->EventSize; } //////////////////////////////////////////////////////////////////////////////// uint32 IAnalyzer::FEventTypeInfo::GetFieldCount() const { const auto* Inner = (const FDispatch*)this; return Inner->FieldCount; } //////////////////////////////////////////////////////////////////////////////// const IAnalyzer::FEventFieldInfo* IAnalyzer::FEventTypeInfo::GetFieldInfo(uint32 Index) const { if (Index >= GetFieldCount()) { return nullptr; } const auto* Inner = (const FDispatch*)this; return (const IAnalyzer::FEventFieldInfo*)(Inner->Fields + Index); } //////////////////////////////////////////////////////////////////////////////// int32 IAnalyzer::FEventTypeInfo::GetFieldIndex(const ANSICHAR* FieldName) const { const auto* Inner = (const FDispatch*)this; return Inner->GetFieldIndex(FieldName); } //////////////////////////////////////////////////////////////////////////////// IAnalyzer::FEventFieldHandle IAnalyzer::FEventTypeInfo::GetFieldHandleUnchecked(uint32 Index) const { const auto* Inner = (const FDispatch*)this; if (Index >= Inner->FieldCount) { return FEventFieldHandle { -1 }; } return FEventFieldHandle { Inner->Fields[Index].Offset }; } //////////////////////////////////////////////////////////////////////////////// IAnalyzer::FEventFieldHandle IAnalyzer::FEventTypeInfo::GetFieldHandleImpl( const ANSICHAR* FieldName, int16& SizeAndType) const { const auto* Inner = (const FDispatch*)this; int32 Index = Inner->GetFieldIndex(FieldName); if (Index < 0) { return { -1 }; } const FDispatch::FField& Field = Inner->Fields[Index]; SizeAndType = Field.SizeAndType; return { Field.Offset }; } // {{{1 field-info ------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// const ANSICHAR* IAnalyzer::FEventFieldInfo::GetName() const { const auto* Inner = (const FDispatch::FField*)this; return (const ANSICHAR*)(UPTRINT(Inner) + Inner->NameOffset); } //////////////////////////////////////////////////////////////////////////////// IAnalyzer::FEventFieldInfo::EType IAnalyzer::FEventFieldInfo::GetType() const { const auto* Inner = (const FDispatch::FField*)this; if (Inner->RefUid != 0) { switch(Inner->Size) { case sizeof(uint8): return EType::Reference8; case sizeof(uint16): return EType::Reference16; case sizeof(uint32): return EType::Reference32; case sizeof(uint64): return EType::Reference64; default: check(false); // Unsupported width } } if (Inner->Class == UE::Trace::Protocol0::Field_String) { return (Inner->SizeAndType == 1) ? EType::AnsiString : EType::WideString; } if (Inner->SizeAndType > 0) { return EType::Integer; } if (Inner->SizeAndType < 0) { return EType::Float; } return EType::None; } //////////////////////////////////////////////////////////////////////////////// bool IAnalyzer::FEventFieldInfo::IsArray() const { const auto* Inner = (const FDispatch::FField*)this; return Inner->bArray; } //////////////////////////////////////////////////////////////////////////////// bool IAnalyzer::FEventFieldInfo::IsSigned() const { const auto* Inner = (const FDispatch::FField*)this; return (Inner->Class & UE::Trace::Protocol0::Field_Signed) != 0; } //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG_API uint32 IAnalyzer::FEventFieldInfo::GetOffset() const { const auto* Inner = (const FDispatch::FField*)this; return Inner->Offset; } #endif // UE_TRACE_ANALYSIS_DEBUG_API //////////////////////////////////////////////////////////////////////////////// uint8 IAnalyzer::FEventFieldInfo::GetSize() const { const auto* Inner = (const FDispatch::FField*)this; return uint8(Inner->Size); } // {{{1 array-reader ----------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// uint32 IAnalyzer::FArrayReader::Num() const { const auto* Inner = (const FAuxData*)this; int32 SizeAndType = Inner->FieldSizeAndType; SizeAndType = (SizeAndType < 0) ? -SizeAndType : SizeAndType; return (SizeAndType == 0) ? SizeAndType : (Inner->DataSize / SizeAndType); } //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG_API const uint8* IAnalyzer::FArrayReader::GetRawData() const { const auto* Inner = (const FAuxData*)this; return Inner->Data; } #endif // UE_TRACE_ANALYSIS_DEBUG_API //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG_API uint32 IAnalyzer::FArrayReader::GetRawDataSize() const { const auto* Inner = (const FAuxData*)this; return Inner->DataSize; } #endif // UE_TRACE_ANALYSIS_DEBUG_API //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG_API int8 IAnalyzer::FArrayReader::GetSizeAndType() const { const auto* Inner = (const FAuxData*)this; return Inner->FieldSizeAndType; } #endif // UE_TRACE_ANALYSIS_DEBUG_API //////////////////////////////////////////////////////////////////////////////// const void* IAnalyzer::FArrayReader::GetImpl(uint32 Index, int8& SizeAndType) const { const auto* Inner = (const FAuxData*)this; SizeAndType = Inner->FieldSizeAndType; uint32 Count = Num(); if (Index >= Count) { return nullptr; } SizeAndType = (SizeAndType < 0) ? -SizeAndType : SizeAndType; return Inner->Data + (Index * SizeAndType); } // {{{1 event-data ------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// struct FEventDataInfo { const FAuxData* GetAuxData(uint32 FieldIndex) const; const uint8* Ptr; const FDispatch& Dispatch; FAuxDataCollector* AuxCollector; uint16 Size; }; //////////////////////////////////////////////////////////////////////////////// const FAuxData* FEventDataInfo::GetAuxData(uint32 FieldIndex) const { const auto* Info = (const FEventDataInfo*)this; if (Info->AuxCollector == nullptr) { return nullptr; } for (FAuxData& Data : *(Info->AuxCollector)) { if (Data.FieldIndex == FieldIndex) { if (Data.bFragmented) { Info->AuxCollector->Defragment(Data); } const FDispatch::FField& Field = Info->Dispatch.Fields[FieldIndex]; Data.FieldSizeAndType = Field.SizeAndType; Data.bSigned = (Field.Class & UE::Trace::Protocol0::Field_Signed) != 0; return &Data; } } return nullptr; } //////////////////////////////////////////////////////////////////////////////// const IAnalyzer::FEventTypeInfo& IAnalyzer::FEventData::GetTypeInfo() const { const auto* Info = (const FEventDataInfo*)this; return (const FEventTypeInfo&)(Info->Dispatch); } //////////////////////////////////////////////////////////////////////////////// const IAnalyzer::FArrayReader* IAnalyzer::FEventData::GetArrayImpl(const ANSICHAR* FieldName) const { const auto* Info = (const FEventDataInfo*)this; int32 Index = Info->Dispatch.GetFieldIndex(FieldName); if (Index >= 0) { if (const FAuxData* Data = Info->GetAuxData(Index)) { return (IAnalyzer::FArrayReader*)Data; } } static const FAuxData EmptyAuxData = {}; return (const IAnalyzer::FArrayReader*)&EmptyAuxData; } //////////////////////////////////////////////////////////////////////////////// const void* IAnalyzer::FEventData::GetValueImpl(const ANSICHAR* FieldName, int8& SizeAndType) const { const auto* Info = (const FEventDataInfo*)this; const auto& Dispatch = Info->Dispatch; int32 Index = Dispatch.GetFieldIndex(FieldName); if (Index < 0) { return nullptr; } const auto& Field = Dispatch.Fields[Index]; SizeAndType = Field.SizeAndType; return (Info->Ptr + Field.Offset); } //////////////////////////////////////////////////////////////////////////////// bool IAnalyzer::FEventData::GetString(const ANSICHAR* FieldName, FAnsiStringView& Out) const { const auto* Info = (const FEventDataInfo*)this; const auto& Dispatch = Info->Dispatch; int32 Index = Dispatch.GetFieldIndex(FieldName); if (Index < 0) { return false; } const auto& Field = Dispatch.Fields[Index]; if (Field.Class != UE::Trace::Protocol0::Field_String || Field.SizeAndType != sizeof(ANSICHAR)) { return false; } if (const FAuxData* Data = Info->GetAuxData(Index)) { Out = FAnsiStringView((const ANSICHAR*)(Data->Data), Data->DataSize); return true; } Out = FAnsiStringView(); return true; } //////////////////////////////////////////////////////////////////////////////// bool IAnalyzer::FEventData::GetString(const ANSICHAR* FieldName, FWideStringView& Out) const { const auto* Info = (const FEventDataInfo*)this; const auto& Dispatch = Info->Dispatch; int32 Index = Dispatch.GetFieldIndex(FieldName); if (Index < 0) { return false; } const auto& Field = Dispatch.Fields[Index]; if (Field.Class != UE::Trace::Protocol0::Field_String || Field.SizeAndType != sizeof(WIDECHAR)) { return false; } if (const FAuxData* Data = Info->GetAuxData(Index)) { Out = FWideStringView((const WIDECHAR*)(Data->Data), Data->DataSize / sizeof(WIDECHAR)); return true; } Out = FWideStringView(); return true; } //////////////////////////////////////////////////////////////////////////////// bool IAnalyzer::FEventData::GetString(const ANSICHAR* FieldName, FString& Out) const { const auto* Info = (const FEventDataInfo*)this; const auto& Dispatch = Info->Dispatch; int32 Index = Dispatch.GetFieldIndex(FieldName); if (Index < 0) { return false; } const auto& Field = Dispatch.Fields[Index]; if (Field.Class == UE::Trace::Protocol0::Field_String) { const FAuxData* Data = Info->GetAuxData(Index); if (Data == nullptr) { Out = FString(); return true; } if (Field.SizeAndType == sizeof(ANSICHAR)) { Out = FString::ConstructFromPtrSize((const ANSICHAR*)(Data->Data), Data->DataSize); return true; } if (Field.SizeAndType == sizeof(WIDECHAR)) { Out = FWideStringView((const WIDECHAR*)(Data->Data), Data->DataSize / sizeof(WIDECHAR)); return true; } } return false; } //////////////////////////////////////////////////////////////////////////////// uint32 IAnalyzer::FEventData::GetSize() const { const auto* Info = (const FEventDataInfo*)this; uint32 Size = Info->Size; if (Info->AuxCollector) { for (const FAuxData& Data : *(Info->AuxCollector)) { Size += Data.DataSize; } } return Size; } //////////////////////////////////////////////////////////////////////////////// void IAnalyzer::FEventData::SerializeToCbor(TArray& Out) const { const auto* Info = (const FEventDataInfo*)this; uint32 Size = Info->Size; if (Info->AuxCollector != nullptr) { for (FAuxData& Data : *(Info->AuxCollector)) { Size += Data.DataSize; } } SerializeToCborImpl(Out, *this, Size); } //////////////////////////////////////////////////////////////////////////////// const void* IAnalyzer::FEventData::GetValueRaw(FEventFieldHandle Handle) const { const auto* Info = (const FEventDataInfo*)this; if (!Handle.IsValid()) { return nullptr; } return Info->Ptr + Handle.Detail; } //////////////////////////////////////////////////////////////////////////////// const uint8* IAnalyzer::FEventData::GetAttachment() const { const auto* Info = (const FEventDataInfo*)this; return Info->Ptr + Info->Dispatch.EventSize; } //////////////////////////////////////////////////////////////////////////////// uint32 IAnalyzer::FEventData::GetAttachmentSize() const { const auto* Info = (const FEventDataInfo*)this; return Info->Size - Info->Dispatch.EventSize; } //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG_API const uint8* IAnalyzer::FEventData::GetRawPointer() const { const auto* Info = (const FEventDataInfo*)this; return Info->Ptr; } #endif // UE_TRACE_ANALYSIS_DEBUG_API //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG_API uint32 IAnalyzer::FEventData::GetRawSize() const { const auto* Info = (const FEventDataInfo*)this; return Info->Size; } #endif // UE_TRACE_ANALYSIS_DEBUG_API //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG_API uint32 IAnalyzer::FEventData::GetAuxSize() const { const auto* Info = (const FEventDataInfo*)this; if ((Info->Dispatch.Flags & UE::Trace::FDispatch::Flag_MaybeHasAux) == 0) { return 0; } else { uint32 Size = 0; if (Info->AuxCollector) { for (FAuxData& Data : *(Info->AuxCollector)) { Size += 4; // aux field header Size += Data.DataSize; } } ++Size; // aux terminator return Size; } } #endif // UE_TRACE_ANALYSIS_DEBUG_API //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG_API uint32 IAnalyzer::FEventData::GetTotalSize(IAnalyzer::EStyle Style, const IAnalyzer::FOnEventContext& Context, uint32 ProtocolVersion) const { uint32 Size = 0; if (Style == EStyle::EnterScope) { // Include the size of the previous EnterScope event. if (Context.EventTime.GetTimestamp() == 0) { Size = 1; // uid } else { Size = 8; // 1 uid + 7 timestamp } } else if (Style == EStyle::LeaveScope) { // Return only the size of the LeaveScope event. if (Context.EventTime.GetTimestamp() == 0) { return 1; // uid } else { return 8; // 1 uid + 7 timestamp } } const auto* Info = (const FEventDataInfo*)this; const uint16 KnownEventUids = (ProtocolVersion >= 5) ? Protocol5::EKnownEventUids::User : (ProtocolVersion == 4) ? Protocol4::EKnownEventUids::User : 0; static_assert(Protocol6::EKnownEventUids::User == Protocol5::EKnownEventUids::User, "Protocol6::EKnownEventUids::User"); static_assert(Protocol7::EKnownEventUids::User == Protocol5::EKnownEventUids::User, "Protocol7::EKnownEventUids::User"); // Add header size. if (Info->Dispatch.Uid < KnownEventUids) { Size += 1; // uid } else if ((Info->Dispatch.Flags & UE::Trace::FDispatch::Flag_Important) != 0) { Size += 4; // sizeof(UE::Trace::Protocol5::FImportantEventHeader); } else if (Info->Dispatch.Flags & UE::Trace::FDispatch::Flag_NoSync) { if (ProtocolVersion < 5) { Size += 4; // sizeof(UE::Trace::Protocol2::FEventHeader); } else { Size += 2; // uid == sizeof(UE::Trace::Protocol5::FEventHeader); } } else // Sync { if (ProtocolVersion < 5) { Size += 7; // sizeof(UE::Trace::Protocol2::FEventHeaderSync); } else { Size += 2 + 3; // uid + serial == sizeof(UE::Trace::Protocol5::FEventHeaderSync); } } // Add fixed size and attachment size. Size += Info->Size; // Add aux data size (including headers). Size += GetAuxSize(); return Size; } #endif // UE_TRACE_ANALYSIS_DEBUG_API //////////////////////////////////////////////////////////////////////////////// bool IAnalyzer::FEventData::IsDefinitionImpl(uint32& OutTypeId) const { const auto* Info = (const FEventDataInfo*)this; OutTypeId = Info->Dispatch.Uid; return (Info->Dispatch.Flags & FDispatch::Flag_Definition) != 0; } //////////////////////////////////////////////////////////////////////////////// const void* IAnalyzer::FEventData::GetReferenceValueImpl(const char* FieldName, uint16& OutSizeType, uint32& OutTypeUid) const { const auto* Info = (const FEventDataInfo*)this; const auto& Dispatch = Info->Dispatch; const int32 Index = Dispatch.GetFieldIndex(FieldName); if (Index < 0) { return nullptr; } const auto& Field = Dispatch.Fields[Index]; if (Field.RefUid) { OutSizeType = Field.SizeAndType; OutTypeUid = Field.RefUid; return (Info->Ptr + Field.Offset); } return nullptr; } //////////////////////////////////////////////////////////////////////////////// const void* IAnalyzer::FEventData::GetReferenceValueImpl(uint32 FieldIndex, uint32& OutTypeUid) const { const auto* Info = (const FEventDataInfo*)this; const auto& Dispatch = Info->Dispatch; const auto& Field = Dispatch.Fields[FieldIndex]; if (Field.RefUid) { OutTypeUid = Field.RefUid; return (Info->Ptr + Field.Offset); } return nullptr; } // }}} // {{{1 type-registry ---------------------------------------------------------- class FTypeRegistry { public: typedef FDispatch FTypeInfo; ~FTypeRegistry(); const FTypeInfo* Add(const void* TraceData, uint32 Version); const FTypeInfo* AddVersion4(const void* TraceData); const FTypeInfo* AddVersion6(const void* TraceData); void Add(FTypeInfo* TypeInfo); const FTypeInfo* Get(uint32 Uid) const; bool IsUidValid(uint32 Uid) const; private: TArray TypeInfos; }; //////////////////////////////////////////////////////////////////////////////// FTypeRegistry::~FTypeRegistry() { for (FTypeInfo* TypeInfo : TypeInfos) { FMemory::Free(TypeInfo); } } //////////////////////////////////////////////////////////////////////////////// const FTypeRegistry::FTypeInfo* FTypeRegistry::Add(const void* TraceData, uint32 Version) { switch(Version) { case 0: return AddVersion4(TraceData); case 4: return AddVersion4(TraceData); case 6: return AddVersion6(TraceData); case 7: return AddVersion6(TraceData); default: check(false); // Unknown version } return nullptr; } //////////////////////////////////////////////////////////////////////////////// const FTypeRegistry::FTypeInfo* FTypeRegistry::Get(uint32 Uid) const { if (Uid >= uint32(TypeInfos.Num())) { return nullptr; } return TypeInfos[Uid]; } //////////////////////////////////////////////////////////////////////////////// const FTypeRegistry::FTypeInfo* FTypeRegistry::AddVersion4(const void* TraceData) { FDispatchBuilder Builder; const auto& NewEvent = *(Protocol4::FNewEventEvent*)(TraceData); const auto* NameCursor = (const ANSICHAR*)(NewEvent.Fields + NewEvent.FieldCount); Builder.SetLoggerName(NameCursor, NewEvent.LoggerNameSize); NameCursor += NewEvent.LoggerNameSize; Builder.SetEventName(NameCursor, NewEvent.EventNameSize); NameCursor += NewEvent.EventNameSize; Builder.SetUid(NewEvent.EventUid); // Fill out the fields for (int32 i = 0, n = NewEvent.FieldCount; i < n; ++i) { const auto& Field = NewEvent.Fields[i]; int8 TypeSize = (int8)(1 << (Field.TypeInfo & Protocol0::Field_Pow2SizeMask)); if (Field.TypeInfo & Protocol0::Field_Float) { TypeSize = -TypeSize; } auto& OutField = Builder.AddField(NameCursor, Field.NameSize, Field.Size); OutField.Offset = Field.Offset; OutField.SizeAndType = TypeSize; OutField.Class = Field.TypeInfo & Protocol0::Field_SpecialMask; OutField.bArray = !!(Field.TypeInfo & Protocol0::Field_Array); NameCursor += Field.NameSize; } if (NewEvent.Flags & uint32(Protocol4::EEventFlags::Important)) { Builder.SetImportant(); } if (NewEvent.Flags & uint32(Protocol4::EEventFlags::MaybeHasAux)) { Builder.SetMaybeHasAux(); } if (NewEvent.Flags & uint32(Protocol4::EEventFlags::NoSync)) { Builder.SetNoSync(); } FTypeInfo* TypeInfo = Builder.Finalize(); Add(TypeInfo); return TypeInfo; } //////////////////////////////////////////////////////////////////////////////// const FTypeRegistry::FTypeInfo* FTypeRegistry::AddVersion6(const void* TraceData) { using namespace Protocol6; FDispatchBuilder Builder; const auto& NewEvent = *(FNewEventEvent*)(TraceData); const auto* NameCursor = (const ANSICHAR*)(NewEvent.Fields + NewEvent.FieldCount); Builder.SetLoggerName(NameCursor, NewEvent.LoggerNameSize); NameCursor += NewEvent.LoggerNameSize; Builder.SetEventName(NameCursor, NewEvent.EventNameSize); NameCursor += NewEvent.EventNameSize; Builder.SetUid(NewEvent.EventUid); // Fill out the fields for (int32 i = 0, n = NewEvent.FieldCount; i < n; ++i) { const auto& Field = NewEvent.Fields[i]; if (Field.FieldType == EFieldFamily::Regular) { int8 TypeSize = (int8)(1 << (Field.Regular.TypeInfo & Protocol0::Field_Pow2SizeMask)); if (Field.Regular.TypeInfo & Protocol0::Field_Float) { TypeSize = -TypeSize; } auto& OutField = Builder.AddField(NameCursor, Field.Regular.NameSize, Field.Regular.Size); OutField.Offset = Field.Regular.Offset; OutField.SizeAndType = TypeSize; OutField.Class = Field.Regular.TypeInfo & Protocol0::Field_SpecialMask; OutField.bArray = !!(Field.Regular.TypeInfo & Protocol0::Field_Array); NameCursor += Field.Regular.NameSize; } else if (Field.FieldType == EFieldFamily::Reference) { check((Field.Reference.TypeInfo & Protocol0::Field_CategoryMask) == Protocol0::Field_Integer); const int8 TypeSize = (int8)(1 << (Field.Reference.TypeInfo & Protocol0::Field_Pow2SizeMask)); auto& OutField = Builder.AddField(NameCursor, Field.Reference.NameSize, TypeSize); OutField.Offset = Field.Reference.Offset; OutField.SizeAndType = TypeSize; OutField.RefUid = uint32(Field.Reference.RefUid); OutField.Class = 0; OutField.bArray = false; NameCursor += Field.Reference.NameSize; } else if (Field.FieldType == EFieldFamily::DefinitionId) { check((Field.DefinitionId.TypeInfo & Protocol0::Field_CategoryMask) == Protocol0::Field_Integer); const int8 TypeSize = (int8)(1 << (Field.DefinitionId.TypeInfo & Protocol0::Field_Pow2SizeMask)); auto DefinitionIdFieldName = ANSITEXTVIEW("DefinitionId"); auto& OutField = Builder.AddField(DefinitionIdFieldName.GetData(), DefinitionIdFieldName.Len(), TypeSize); OutField.Offset = Field.DefinitionId.Offset; OutField.SizeAndType = TypeSize; OutField.RefUid = NewEvent.EventUid; OutField.Class = 0; OutField.bArray = false; } else { // Error! continue; } } if (NewEvent.Flags & uint32(EEventFlags::Important)) { Builder.SetImportant(); } if (NewEvent.Flags & uint32(EEventFlags::MaybeHasAux)) { Builder.SetMaybeHasAux(); } if (NewEvent.Flags & uint32(EEventFlags::NoSync)) { Builder.SetNoSync(); } if (NewEvent.Flags & uint32(EEventFlags::Definition)) { Builder.SetDefinition(); } FTypeInfo* TypeInfo = Builder.Finalize(); Add(TypeInfo); return TypeInfo; } //////////////////////////////////////////////////////////////////////////////// void FTypeRegistry::Add(FTypeInfo* TypeInfo) { // Add the type to the type-infos table. Usually duplicates are an error // but due to backwards compatibility we'll override existing types. uint16 Uid = TypeInfo->Uid; if (Uid < uint32(TypeInfos.Num())) { if (TypeInfos[Uid] != nullptr) { UE_TRACE_ANALYSIS_DEBUG_LOG("Warning: Override type for Uid=%u", uint32(Uid)); FMemory::Free(TypeInfos[Uid]); TypeInfos[Uid] = nullptr; } } else { #if UE_TRACE_ANALYSIS_DEBUG if (Uid > TypeInfos.Num() + 100) { UE_TRACE_ANALYSIS_DEBUG_LOG("Warning: Unexpected large Uid=%u", uint32(Uid)); } #endif // UE_TRACE_ANALYSIS_DEBUG TypeInfos.SetNum(Uid + 1); } TypeInfos[Uid] = TypeInfo; } //////////////////////////////////////////////////////////////////////////////// bool FTypeRegistry::IsUidValid(uint32 Uid) const { return (Uid < uint32(TypeInfos.Num())) && (TypeInfos[Uid] != nullptr); } // {{{1 analyzer-hub ----------------------------------------------------------- class FAnalyzerHub { public: void End(); void SetAnalyzers(TArray&& InAnalyzers); uint32 GetActiveAnalyzerNum() const; void OnNewType(const FTypeRegistry::FTypeInfo* TypeInfo); void OnEvent(const FTypeRegistry::FTypeInfo& TypeInfo, IAnalyzer::EStyle Style, const IAnalyzer::FOnEventContext& Context); void OnThreadInfo(const FThreads::FInfo& ThreadInfo); #if UE_TRACE_ANALYSIS_DEBUG_API void OnVersion(uint32 TransportVersion, uint32 ProtocolVersion); #endif // UE_TRACE_ANALYSIS_DEBUG_API private: void BuildRoutes(); void AddRoute(uint16 AnalyzerIndex, uint16 Id, const ANSICHAR* Logger, const ANSICHAR* Event, bool bScoped); int32 GetRouteIndex(const FTypeRegistry::FTypeInfo& TypeInfo); void RetireAnalyzer(IAnalyzer* Analyzer); template void ForEachRoute(uint32 RouteIndex, bool bScoped, ImplType&& Impl) const; struct FRoute { uint32 Hash; uint16 AnalyzerIndex : 15; uint16 bScoped : 1; uint16 Id; union { uint32 ParentHash; struct { int16 Count; int16 Parent; }; }; }; typedef TArray> TypeToRouteArray; TArray Analyzers; TArray Routes; TypeToRouteArray TypeToRoute; // biases by one so zero represents no route }; //////////////////////////////////////////////////////////////////////////////// void FAnalyzerHub::End() { for (IAnalyzer* Analyzer : Analyzers) { if (Analyzer != nullptr) { Analyzer->OnAnalysisEnd(); } } } //////////////////////////////////////////////////////////////////////////////// void FAnalyzerHub::SetAnalyzers(TArray&& InAnalyzers) { Analyzers = MoveTemp(InAnalyzers); BuildRoutes(); } //////////////////////////////////////////////////////////////////////////////// uint32 FAnalyzerHub::GetActiveAnalyzerNum() const { uint32 Count = 0; for (IAnalyzer* Analyzer : Analyzers) { Count += (Analyzer != nullptr); } return Count; } //////////////////////////////////////////////////////////////////////////////// int32 FAnalyzerHub::GetRouteIndex(const FTypeRegistry::FTypeInfo& TypeInfo) { if (TypeInfo.Uid >= uint32(TypeToRoute.Num())) { return -1; } return int32(TypeToRoute[TypeInfo.Uid]) - 1; } //////////////////////////////////////////////////////////////////////////////// template void FAnalyzerHub::ForEachRoute(uint32 RouteIndex, bool bScoped, ImplType&& Impl) const { uint32 RouteCount = Routes.Num(); if (RouteIndex >= RouteCount) { return; } const FRoute* FirstRoute = Routes.GetData(); const FRoute* Route = FirstRoute + RouteIndex; do { const FRoute* NextRoute = FirstRoute + Route->Parent; for (uint32 n = Route->Count; n--; ++Route) { if (Route->bScoped != (bScoped == true)) { continue; } IAnalyzer* Analyzer = Analyzers[Route->AnalyzerIndex]; if (Analyzer != nullptr) { Impl(Analyzer, Route->Id); } } Route = NextRoute; } while (Route >= FirstRoute); } //////////////////////////////////////////////////////////////////////////////// void FAnalyzerHub::OnNewType(const FTypeRegistry::FTypeInfo* TypeInfo) { // Find routes that have subscribed to this event. auto FindRoute = [this] (uint32 Hash) { int32 Index = Algo::LowerBoundBy(Routes, Hash, [] (const FRoute& Route) { return Route.Hash; }); return (Index < Routes.Num() && Routes[Index].Hash == Hash) ? Index : -1; }; int32 FirstRoute = FindRoute(TypeInfo->Hash); if (FirstRoute < 0) { FFnv1aHash LoggerHash; LoggerHash.Add((const ANSICHAR*)TypeInfo + TypeInfo->LoggerNameOffset); if ((FirstRoute = FindRoute(LoggerHash.Get())) < 0) { FirstRoute = FindRoute(FFnv1aHash().Get()); } } uint16 Uid = TypeInfo->Uid; if (Uid >= uint16(TypeToRoute.Num())) { TypeToRoute.SetNumZeroed(Uid + 32); } TypeToRoute[Uid] = uint16(FirstRoute + 1); #if UE_TRACE_ANALYSIS_DEBUG const IAnalyzer::FEventTypeInfo& EventTypeInfo = *(IAnalyzer::FEventTypeInfo*)TypeInfo; #if UE_TRACE_ANALYSIS_DEBUG_API const uint8 EventTypeFlags = EventTypeInfo.GetFlags(); UE_TRACE_ANALYSIS_DEBUG_LOG("NewEvent: Uid=%u (%s.%s) Flags=%s%s%s%s", EventTypeInfo.GetId(), EventTypeInfo.GetLoggerName(), EventTypeInfo.GetName(), (EventTypeFlags & FDispatch::Flag_Definition) ? "Definition|" : "", (EventTypeFlags & FDispatch::Flag_Important) ? "Important|" : "", (EventTypeFlags & FDispatch::Flag_MaybeHasAux) ? "MaybeHasAux|" : "", (EventTypeFlags & FDispatch::Flag_NoSync) ? "NoSync" : "Sync"); #else // UE_TRACE_ANALYSIS_DEBUG_API UE_TRACE_ANALYSIS_DEBUG_LOG("NewEvent: Uid=%u (%s.%s)", EventTypeInfo.GetId(), EventTypeInfo.GetLoggerName(), EventTypeInfo.GetName()); #endif // UE_TRACE_ANALYSIS_DEBUG_API #endif // UE_TRACE_ANALYSIS_DEBUG // Inform routes that a new event has been declared. if (FirstRoute >= 0) { ForEachRoute(FirstRoute, false, [&] (IAnalyzer* Analyzer, uint16 RouteId) { if (!Analyzer->OnNewEvent(RouteId, *(IAnalyzer::FEventTypeInfo*)TypeInfo)) { RetireAnalyzer(Analyzer); } }); } } //////////////////////////////////////////////////////////////////////////////// void FAnalyzerHub::OnEvent( const FTypeRegistry::FTypeInfo& TypeInfo, const IAnalyzer::EStyle Style, const IAnalyzer::FOnEventContext& Context) { int32 RouteIndex = GetRouteIndex(TypeInfo); if (RouteIndex < 0) { return; } bool bScoped = (Style != IAnalyzer::EStyle::Normal); ForEachRoute(RouteIndex, bScoped, [&] (IAnalyzer* Analyzer, uint16 RouteId) { if (!Analyzer->OnEvent(RouteId, Style, Context)) { RetireAnalyzer(Analyzer); } }); } //////////////////////////////////////////////////////////////////////////////// void FAnalyzerHub::OnThreadInfo(const FThreads::FInfo& ThreadInfo) { const auto& OuterThreadInfo = (IAnalyzer::FThreadInfo&)ThreadInfo; for (IAnalyzer* Analyzer : Analyzers) { if (Analyzer != nullptr) { Analyzer->OnThreadInfo(OuterThreadInfo); } } } //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG_API void FAnalyzerHub::OnVersion(uint32 TransportVersion, uint32 ProtocolVersion) { for (IAnalyzer* Analyzer : Analyzers) { if (Analyzer != nullptr) { Analyzer->OnVersion(TransportVersion, ProtocolVersion); } } } #endif // UE_TRACE_ANALYSIS_DEBUG_API //////////////////////////////////////////////////////////////////////////////// void FAnalyzerHub::BuildRoutes() { // Call out to all registered analyzers to have them register event interest struct : public IAnalyzer::FInterfaceBuilder { virtual void RouteEvent(uint16 RouteId, const ANSICHAR* Logger, const ANSICHAR* Event, bool bScoped) override { Self->AddRoute(AnalyzerIndex, RouteId, Logger, Event, bScoped); } virtual void RouteLoggerEvents(uint16 RouteId, const ANSICHAR* Logger, bool bScoped) override { Self->AddRoute(AnalyzerIndex, RouteId, Logger, "", bScoped); } virtual void RouteAllEvents(uint16 RouteId, bool bScoped) override { Self->AddRoute(AnalyzerIndex, RouteId, "", "", bScoped); } FAnalyzerHub* Self; uint16 AnalyzerIndex; } Builder; Builder.Self = this; IAnalyzer::FOnAnalysisContext OnAnalysisContext = { Builder }; for (uint16 i = 0, n = uint16(Analyzers.Num()); i < n; ++i) { uint32 RouteCount = Routes.Num(); Builder.AnalyzerIndex = i; IAnalyzer* Analyzer = Analyzers[i]; Analyzer->OnAnalysisBegin(OnAnalysisContext); // If the analyzer didn't add any routes we'll retire it immediately if (RouteCount == Routes.Num()) { RetireAnalyzer(Analyzer); } } // Sort routes by their hashes. auto RouteProjection = [] (const FRoute& Route) { return Route.Hash; }; Algo::SortBy(Routes, RouteProjection); auto FindRoute = [this, &RouteProjection] (uint32 Hash) { int32 Index = Algo::LowerBoundBy(Routes, Hash, RouteProjection); return (Index < Routes.Num() && Routes[Index].Hash == Hash) ? Index : -1; }; int32 AllEventsIndex = FindRoute(FFnv1aHash().Get()); auto FixupRoute = [this, &FindRoute, AllEventsIndex] (FRoute* Route) { if (Route->ParentHash) { int32 ParentIndex = FindRoute(Route->ParentHash); Route->Parent = int16((ParentIndex < 0) ? AllEventsIndex : ParentIndex); } else { Route->Parent = -1; } Route->Count = 1; return Route; }; FRoute* Cursor = FixupRoute(Routes.GetData()); for (uint16 i = 1, n = uint16(Routes.Num()); i < n; ++i) { FRoute* Route = Routes.GetData() + i; if (Route->Hash == Cursor->Hash) { Cursor->Count++; } else { Cursor = FixupRoute(Route); } } } //////////////////////////////////////////////////////////////////////////////// void FAnalyzerHub::RetireAnalyzer(IAnalyzer* Analyzer) { for (uint32 i = 0, n = Analyzers.Num(); i < n; ++i) { if (Analyzers[i] != Analyzer) { continue; } Analyzer->OnAnalysisEnd(); Analyzers[i] = nullptr; break; } } //////////////////////////////////////////////////////////////////////////////// void FAnalyzerHub::AddRoute( uint16 AnalyzerIndex, uint16 Id, const ANSICHAR* Logger, const ANSICHAR* Event, bool bScoped) { check(AnalyzerIndex < Analyzers.Num()); uint32 ParentHash = 0; if (Logger[0] && Event[0]) { FFnv1aHash Hash; Hash.Add(Logger); ParentHash = Hash.Get(); } FFnv1aHash Hash; Hash.Add(Logger); Hash.Add(Event); FRoute& Route = Routes.Emplace_GetRef(); Route.Id = Id; Route.Hash = Hash.Get(); Route.ParentHash = ParentHash; Route.AnalyzerIndex = AnalyzerIndex; Route.bScoped = (bScoped == true); } // {{{1 state ------------------------------------------------------------------ //////////////////////////////////////////////////////////////////////////////// struct FAnalysisState { struct FSerial { uint32 Value = 0; uint32 Mask = 0; }; FThreads Threads; FTiming Timing; FSerial Serial; uint32 UserUidBias = Protocol4::EKnownEventUids::User; #if UE_TRACE_ANALYSIS_DEBUG uint32 TempUidBytes = 0; // for protocol 4 int32 MaxEventDescs = 0; // for protocol 5 int32 SerialWrappedCount = 0; // for protocol 5 int32 NumSkippedSerialGaps = 0; // for protocol 5 uint64 NumSkippedSerials = 0; // for protocol 5 uint64 TotalEventCount = 0; uint64 NewEventCount = 0; uint64 SyncEventCount = 0; uint64 ImportantNoSyncEventCount = 0; uint64 OtherNoSyncEventCount = 0; uint64 EnterScopeEventCount = 0; uint64 LeaveScopeEventCount = 0; uint64 EnterScopeTEventCount = 0; uint64 LeaveScopeTEventCount = 0; uint64 TotalEventSize = 0; uint64 NewEventSize = 0; uint64 SyncEventSize = 0; uint64 ImportantNoSyncEventSize = 0; uint64 OtherNoSyncEventSize = 0; uint64 EnterScopeEventSize = 0; uint64 LeaveScopeEventSize = 0; uint64 EnterScopeTEventSize = 0; uint64 LeaveScopeTEventSize = 0; #endif // UE_TRACE_ANALYSIS_DEBUG }; // {{{1 thread-info-cb --------------------------------------------------------- class FThreadInfoCallback { public: virtual ~FThreadInfoCallback() {} virtual void OnThreadInfo(const FThreads::FInfo& Info) = 0; }; // {{{1 analyzer --------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// enum { RouteId_NewTrace, RouteId_SerialSync, RouteId_Timing, RouteId_ThreadTiming, RouteId_ThreadInfo, RouteId_ThreadGroupBegin, RouteId_ThreadGroupEnd, }; //////////////////////////////////////////////////////////////////////////////// class FTraceAnalyzer : public IAnalyzer { public: FTraceAnalyzer(FAnalysisState& InState, FThreadInfoCallback& InCallback); virtual bool OnEvent(uint16 RouteId, EStyle Style, const FOnEventContext& Context) override; virtual void OnAnalysisBegin(const FOnAnalysisContext& Context) override; void OnNewTrace(const FOnEventContext& Context); void OnSerialSync(const FOnEventContext& Context); void OnThreadTiming(const FOnEventContext& Context); void OnThreadInfoInternal(const FOnEventContext& Context); void OnThreadGroupBegin(const FOnEventContext& Context); void OnThreadGroupEnd(); void OnTiming(const FOnEventContext& Context); private: FAnalysisState& State; FThreadInfoCallback& ThreadInfoCallback; }; //////////////////////////////////////////////////////////////////////////////// FTraceAnalyzer::FTraceAnalyzer(FAnalysisState& InState, FThreadInfoCallback& InCallback) : State(InState) , ThreadInfoCallback(InCallback) { } //////////////////////////////////////////////////////////////////////////////// void FTraceAnalyzer::OnAnalysisBegin(const FOnAnalysisContext& Context) { auto& Builder = Context.InterfaceBuilder; Builder.RouteEvent(RouteId_NewTrace, "$Trace", "NewTrace"); Builder.RouteEvent(RouteId_SerialSync, "$Trace", "SerialSync"); Builder.RouteEvent(RouteId_Timing, "$Trace", "Timing"); Builder.RouteEvent(RouteId_ThreadTiming, "$Trace", "ThreadTiming"); Builder.RouteEvent(RouteId_ThreadInfo, "$Trace", "ThreadInfo"); Builder.RouteEvent(RouteId_ThreadGroupBegin,"$Trace", "ThreadGroupBegin"); Builder.RouteEvent(RouteId_ThreadGroupEnd, "$Trace", "ThreadGroupEnd"); } //////////////////////////////////////////////////////////////////////////////// bool FTraceAnalyzer::OnEvent(uint16 RouteId, EStyle Style, const FOnEventContext& Context) { switch (RouteId) { case RouteId_NewTrace: OnNewTrace(Context); break; case RouteId_SerialSync: OnSerialSync(Context); break; case RouteId_Timing: OnTiming(Context); break; case RouteId_ThreadTiming: OnThreadTiming(Context); break; case RouteId_ThreadInfo: OnThreadInfoInternal(Context); break; case RouteId_ThreadGroupBegin: OnThreadGroupBegin(Context); break; case RouteId_ThreadGroupEnd: OnThreadGroupEnd(); break; } return true; } //////////////////////////////////////////////////////////////////////////////// void FTraceAnalyzer::OnNewTrace(const FOnEventContext& Context) { const FEventData& EventData = Context.EventData; // "Serial" will tell us approximately where we've started in the log serial // range. We'll bias it by half so we won't accept any serialized events and // mark the MSB to indicate that the current serial should be corrected. auto& Serial = State.Serial; uint32 Hint = EventData.GetValue("Serial"); UE_TRACE_ANALYSIS_DEBUG_LOG("Serial=%u (hint)", Hint); Hint -= (Serial.Mask + 1) >> 1; Hint &= Serial.Mask; Serial.Value = Hint; Serial.Value |= 0xc0000000; UE_TRACE_ANALYSIS_DEBUG_LOG("Serial.Value=%u|0xC0000000 (Next=%u)", Hint, Serial.Value & Serial.Mask); UE_TRACE_ANALYSIS_DEBUG_LOG("Serial.Mask=0x%X", Serial.Mask); // Later traces will have an explicit "SerialSync" trace event to indicate // when there is enough data to establish the correct log serial const uint8 FeatureSet = EventData.GetValue("FeatureSet"); UE_TRACE_ANALYSIS_DEBUG_LOG("FeatureSet=%d", FeatureSet); if ((FeatureSet & 1) == 0) { OnSerialSync(Context); } State.UserUidBias = EventData.GetValue("UserUidBias", uint32(UE::Trace::Protocol3::EKnownEventUids::User)); UE_TRACE_ANALYSIS_DEBUG_LOG("UserUidBias=%u", State.UserUidBias); OnTiming(Context); } //////////////////////////////////////////////////////////////////////////////// void FTraceAnalyzer::OnSerialSync(const FOnEventContext& Context) { State.Serial.Value &= ~0x40000000; UE_TRACE_ANALYSIS_DEBUG_LOG("SerialSync: Next=%u", State.Serial.Value & State.Serial.Mask); } //////////////////////////////////////////////////////////////////////////////// void FTraceAnalyzer::OnTiming(const FOnEventContext& Context) { uint64 StartCycle = Context.EventData.GetValue("StartCycle"); uint64 CycleFrequency = Context.EventData.GetValue("CycleFrequency"); State.Timing.BaseTimestamp = StartCycle; State.Timing.TimestampHz = CycleFrequency; State.Timing.InvTimestampHz = 1.0 / double(CycleFrequency); } //////////////////////////////////////////////////////////////////////////////// void FTraceAnalyzer::OnThreadTiming(const FOnEventContext& Context) { uint64 BaseTimestamp = Context.EventData.GetValue("BaseTimestamp"); if (FThreads::FInfo* Info = State.Threads.GetInfo()) { Info->PrevTimestamp = BaseTimestamp; // We can springboard of this event as a way to know a thread has just // started (or at least is about to send its first event). Notify analyzers // so they're aware of threads that never get explicitly registered. ThreadInfoCallback.OnThreadInfo(*Info); } } //////////////////////////////////////////////////////////////////////////////// void FTraceAnalyzer::OnThreadInfoInternal(const FOnEventContext& Context) { const FEventData& EventData = Context.EventData; FThreads::FInfo* ThreadInfo; uint32 ThreadId = EventData.GetValue("ThreadId", ~0u); if (ThreadId != ~0u) { // Post important-events; the thread-info event is not on the thread it // represents anymore. Fortunately the thread-id is traced now. ThreadInfo = State.Threads.GetInfo(ThreadId); } else { ThreadInfo = State.Threads.GetInfo(); } if (ThreadInfo == nullptr) { return; } ThreadInfo->SystemId = EventData.GetValue("SystemId"); ThreadInfo->SortHint = EventData.GetValue("SortHint"); FAnsiStringView Name; EventData.GetString("Name", Name); ThreadInfo->Name.SetNumUninitialized(Name.Len() + 1); ThreadInfo->Name[Name.Len()] = '\0'; FMemory::Memcpy(ThreadInfo->Name.GetData(), Name.GetData(), Name.Len()); if (ThreadInfo->GroupName.Num() <= 0) { if (const TArray* GroupName = State.Threads.GetGroupName()) { ThreadInfo->GroupName = *GroupName; } } UE_TRACE_ANALYSIS_DEBUG_LOG("Thread: Tid=%u SysId=0x%X Name=\"%s\"", ThreadInfo->ThreadId, ThreadInfo->SystemId, ThreadInfo->Name.GetData()); ThreadInfoCallback.OnThreadInfo(*ThreadInfo); } //////////////////////////////////////////////////////////////////////////////// void FTraceAnalyzer::OnThreadGroupBegin(const FOnEventContext& Context) { const FEventData& EventData = Context.EventData; FAnsiStringView Name; EventData.GetString("Name", Name); State.Threads.SetGroupName(Name.GetData(), Name.Len()); } //////////////////////////////////////////////////////////////////////////////// void FTraceAnalyzer::OnThreadGroupEnd() { State.Threads.SetGroupName("", 0); } // {{{1 bridge ----------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FAnalysisBridge : public FThreadInfoCallback { public: typedef FAnalysisState::FSerial FSerial; FAnalysisBridge(TArray&& Analyzers); bool IsStillAnalyzing() const; void Reset(); FAnalysisState& GetState(); uint32 GetUserUidBias() const; FSerial& GetSerial(); uint32 GetActiveThreadId() const; void SetActiveThread(uint32 ThreadId); void OnNewType(const FTypeRegistry::FTypeInfo* TypeInfo); void OnEvent(const FEventDataInfo& EventDataInfo); virtual void OnThreadInfo(const FThreads::FInfo& InThreadInfo) override; void EnterScope(); void EnterScope(uint64 RelativeTimestamp); void EnterScopeA(uint64 AbsoluteTimestamp); void EnterScopeB(uint64 BaseRelativeTimestamp); void LeaveScope(); void LeaveScope(uint64 RelativeTimestamp); void LeaveScopeA(uint64 AbsoluteTimestamp); void LeaveScopeB(uint64 BaseRelativeTimestamp); #if UE_TRACE_ANALYSIS_DEBUG_API void OnVersion(uint32 TransportVersion, uint32 ProtocolVersion) { AnalyzerHub.OnVersion(TransportVersion, ProtocolVersion); } #endif // UE_TRACE_ANALYSIS_DEBUG_API #if UE_TRACE_ANALYSIS_DEBUG void DebugLogEvent(const FTypeRegistry::FTypeInfo* TypeInfo, uint32 FixedSize, uint32 AuxSize, uint32 Serial); void DebugLogNewEvent(uint32 Uid, const FTypeRegistry::FTypeInfo* TypeInfo, uint32 EventSize); void DebugLogEnterScopeEvent(uint32 Uid, uint32 EventSize); void DebugLogEnterScopeEvent(uint32 Uid, uint64 RelativeTimestamp, uint32 EventSize); void DebugLogEnterScopeAEvent(uint32 Uid, uint64 AbsoluteTimestamp, uint32 EventSize); void DebugLogEnterScopeBEvent(uint32 Uid, uint64 BaseRelativeTimestamp, uint32 EventSize); void DebugLogLeaveScopeEvent(uint32 Uid, uint32 EventSize); void DebugLogLeaveScopeEvent(uint32 Uid, uint64 RelativeTimestamp, uint32 EventSize); void DebugLogLeaveScopeAEvent(uint32 Uid, uint64 AbsoluteTimestamp, uint32 EventSize); void DebugLogLeaveScopeBEvent(uint32 Uid, uint64 BaseRelativeTimestamp, uint32 EventSize); #endif // UE_TRACE_ANALYSIS_DEBUG_API private: void DispatchLeaveScope(); FAnalysisState State; FTraceAnalyzer TraceAnalyzer = { State, *this }; FAnalyzerHub AnalyzerHub; FThreads::FInfo* ThreadInfo = nullptr; }; //////////////////////////////////////////////////////////////////////////////// FAnalysisBridge::FAnalysisBridge(TArray&& Analyzers) { TArray TempAnalyzers(MoveTemp(Analyzers)); TempAnalyzers.Add(&TraceAnalyzer); AnalyzerHub.SetAnalyzers(MoveTemp(TempAnalyzers)); } //////////////////////////////////////////////////////////////////////////////// bool FAnalysisBridge::IsStillAnalyzing() const { // "> 1" because TraceAnalyzer is always present but shouldn't be considered return AnalyzerHub.GetActiveAnalyzerNum() > 1; } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::Reset() { AnalyzerHub.End(); State.~FAnalysisState(); new (&State) FAnalysisState(); } //////////////////////////////////////////////////////////////////////////////// FAnalysisState& FAnalysisBridge::GetState() { return State; } //////////////////////////////////////////////////////////////////////////////// uint32 FAnalysisBridge::GetUserUidBias() const { return State.UserUidBias; } //////////////////////////////////////////////////////////////////////////////// FAnalysisBridge::FSerial& FAnalysisBridge::GetSerial() { return State.Serial; } //////////////////////////////////////////////////////////////////////////////// uint32 FAnalysisBridge::GetActiveThreadId() const { return ThreadInfo ? ThreadInfo->ThreadId : ~0u; } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::SetActiveThread(uint32 ThreadId) { ThreadInfo = State.Threads.GetInfo(ThreadId); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::OnNewType(const FTypeRegistry::FTypeInfo* TypeInfo) { AnalyzerHub.OnNewType(TypeInfo); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::OnEvent(const FEventDataInfo& EventDataInfo) { // TODO "Dispatch" should be renamed "EventTypeInfo" or similar. const FTypeRegistry::FTypeInfo* TypeInfo = &(EventDataInfo.Dispatch); IAnalyzer::EStyle Style = IAnalyzer::EStyle::Normal; if (ThreadInfo->ScopeRoutes.Num() > 0 && int64(ThreadInfo->ScopeRoutes.Last()) < 0) { Style = IAnalyzer::EStyle::EnterScope; State.Timing.EventTimestamp = ~(ThreadInfo->ScopeRoutes.Last()); ThreadInfo->ScopeRoutes.Last() = PTRINT(TypeInfo); } else { State.Timing.EventTimestamp = 0; } IAnalyzer::FOnEventContext Context = { *(const IAnalyzer::FThreadInfo*)ThreadInfo, (const IAnalyzer::FEventTime&)(State.Timing), (const IAnalyzer::FEventData&)EventDataInfo, }; AnalyzerHub.OnEvent(*TypeInfo, Style, Context); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::OnThreadInfo(const FThreads::FInfo& InThreadInfo) { // Note that InThreadInfo might not equal the bridge's ThreadInfo because // information about threads comes from trace and could have been traced on // a different thread to the one it is describing (or no thread at all in // the case of important events). AnalyzerHub.OnThreadInfo(InThreadInfo); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::EnterScope() { ThreadInfo->ScopeRoutes.Push(~0); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::EnterScope(uint64 Timestamp) { Timestamp = ThreadInfo->PrevTimestamp += Timestamp; ThreadInfo->ScopeRoutes.Push(~Timestamp); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::EnterScopeA(uint64 Timestamp) { Timestamp -= State.Timing.BaseTimestamp; ThreadInfo->ScopeRoutes.Push(~Timestamp); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::EnterScopeB(uint64 Timestamp) { ThreadInfo->ScopeRoutes.Push(~Timestamp); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::LeaveScope() { State.Timing.EventTimestamp = 0; DispatchLeaveScope(); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::LeaveScope(uint64 Timestamp) { Timestamp = ThreadInfo->PrevTimestamp += Timestamp; State.Timing.EventTimestamp = Timestamp; DispatchLeaveScope(); State.Timing.EventTimestamp = 0; } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::LeaveScopeA(uint64 Timestamp) { Timestamp -= State.Timing.BaseTimestamp; State.Timing.EventTimestamp = Timestamp; DispatchLeaveScope(); State.Timing.EventTimestamp = 0; } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::LeaveScopeB(uint64 Timestamp) { State.Timing.EventTimestamp = Timestamp; DispatchLeaveScope(); State.Timing.EventTimestamp = 0; } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DispatchLeaveScope() { if (ThreadInfo->ScopeRoutes.Num() <= 0) { // Leave scope without a corresponding enter return; } int64 ScopeValue = int64(ThreadInfo->ScopeRoutes.Pop(EAllowShrinking::No)); if (ScopeValue < 0) { // enter/leave pair without an event in-between. return; } const auto* TypeInfo = (FTypeRegistry::FTypeInfo*)PTRINT(ScopeValue); FEventDataInfo EmptyEventInfo = { nullptr, *TypeInfo }; IAnalyzer::FOnEventContext Context = { *(const IAnalyzer::FThreadInfo*)ThreadInfo, (const IAnalyzer::FEventTime&)(State.Timing), (const IAnalyzer::FEventData&)EmptyEventInfo, }; AnalyzerHub.OnEvent(*TypeInfo, IAnalyzer::EStyle::LeaveScope, Context); } #if UE_TRACE_ANALYSIS_DEBUG //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DebugLogEvent(const FTypeRegistry::FTypeInfo* TypeInfo, uint32 FixedSize, uint32 AuxSize, uint32 Serial) { ++State.TotalEventCount; uint32 EventSize = FixedSize + AuxSize; State.TotalEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_BeginStringBuilder(); UE_TRACE_ANALYSIS_DEBUG_Appendf("[EVENT %llu]", State.TotalEventCount); if (GetActiveThreadId() != ~0u) { UE_TRACE_ANALYSIS_DEBUG_Appendf(" Tid=%u", GetActiveThreadId()); } UE_TRACE_ANALYSIS_DEBUG_Appendf(" Uid=%u", uint32(TypeInfo->Uid)); const IAnalyzer::FEventTypeInfo& EventTypeInfo = *(IAnalyzer::FEventTypeInfo*)TypeInfo; UE_TRACE_ANALYSIS_DEBUG_Appendf(" (%s.%s)", EventTypeInfo.GetLoggerName(), EventTypeInfo.GetName()); UE_TRACE_ANALYSIS_DEBUG_Appendf(" Size=%u", EventSize); if (AuxSize != 0) { UE_TRACE_ANALYSIS_DEBUG_Appendf(" (%u + %u)", FixedSize, AuxSize); } #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL if ((TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_NoSync) == 0) { ++State.SyncEventCount; State.SyncEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_Appendf(" Sync=%u", Serial); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } else if ((TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_Important) != 0) { ++State.ImportantNoSyncEventCount; State.ImportantNoSyncEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_Append(" Important"); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } else { ++State.OtherNoSyncEventCount; State.OtherNoSyncEventSize += EventSize; } #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_EndStringBuilder(); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DebugLogNewEvent(uint32 Uid, const FTypeRegistry::FTypeInfo* TypeInfo, uint32 EventSize) { ++State.TotalEventCount; ++State.NewEventCount; State.TotalEventSize += EventSize; State.NewEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 const uint32 Tid = ETransportTid::Importants; // GetActiveThreadId() UE_TRACE_ANALYSIS_DEBUG_LOG("[EVENT %llu] Tid=%u Uid=%u (NewEvent) Size=%u", State.TotalEventCount, Tid, Uid, EventSize); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DebugLogEnterScopeEvent(uint32 Uid, uint32 EventSize) { ++State.TotalEventCount; ++State.EnterScopeEventCount; State.TotalEventSize += EventSize; State.EnterScopeEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("[EVENT %llu] Tid=%u Uid=%u (EnterScope) Size=%u", State.TotalEventCount, GetActiveThreadId(), Uid, EventSize); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DebugLogEnterScopeEvent(uint32 Uid, uint64 RelativeTimestamp, uint32 EventSize) { ++State.TotalEventCount; ++State.EnterScopeTEventCount; State.TotalEventSize += EventSize; State.EnterScopeTEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 check(ThreadInfo); UE_TRACE_ANALYSIS_DEBUG_LOG("[EVENT %llu] Tid=%u Uid=%u (EnterScope_T) Timestamp=(+%llu)=%llu Size=%u", State.TotalEventCount, GetActiveThreadId(), Uid, RelativeTimestamp, State.Timing.BaseTimestamp + ThreadInfo->PrevTimestamp + RelativeTimestamp, EventSize); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DebugLogEnterScopeAEvent(uint32 Uid, uint64 AbsoluteTimestamp, uint32 EventSize) { ++State.TotalEventCount; ++State.EnterScopeTEventCount; State.TotalEventSize += EventSize; State.EnterScopeTEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("[EVENT %llu] Tid=%u Uid=%u (EnterScope_TA) Timestamp=%llu Size=%u", State.TotalEventCount, GetActiveThreadId(), Uid, AbsoluteTimestamp, EventSize); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DebugLogEnterScopeBEvent(uint32 Uid, uint64 BaseAbsoluteTimestamp, uint32 EventSize) { ++State.TotalEventCount; ++State.EnterScopeTEventCount; State.TotalEventSize += EventSize; State.EnterScopeTEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("[EVENT %llu] Tid=%u Uid=%u (EnterScope_TB) Timestamp=(+%llu)=%llu Size=%u", State.TotalEventCount, GetActiveThreadId(), Uid, BaseAbsoluteTimestamp, State.Timing.BaseTimestamp + BaseAbsoluteTimestamp, EventSize); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DebugLogLeaveScopeEvent(uint32 Uid, uint32 EventSize) { ++State.TotalEventCount; ++State.LeaveScopeEventCount; State.TotalEventSize += EventSize; State.LeaveScopeEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("[EVENT %llu] Tid=%u Uid=%u (LeaveScope) Size=%u", State.TotalEventCount, GetActiveThreadId(), Uid, EventSize); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DebugLogLeaveScopeEvent(uint32 Uid, uint64 RelativeTimestamp, uint32 EventSize) { ++State.TotalEventCount; ++State.LeaveScopeTEventCount; State.TotalEventSize += EventSize; State.LeaveScopeTEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 check(ThreadInfo); UE_TRACE_ANALYSIS_DEBUG_LOG("[EVENT %llu] Tid=%u Uid=%u (LeaveScope_T) Timestamp=(+%llu)=%llu Size=%u", State.TotalEventCount, GetActiveThreadId(), Uid, RelativeTimestamp, State.Timing.BaseTimestamp + ThreadInfo->PrevTimestamp + RelativeTimestamp, EventSize); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DebugLogLeaveScopeAEvent(uint32 Uid, uint64 AbsoluteTimestamp, uint32 EventSize) { ++State.TotalEventCount; ++State.LeaveScopeTEventCount; State.TotalEventSize += EventSize; State.LeaveScopeTEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("[EVENT %llu] Tid=%u Uid=%u (LeaveScope_TA) Timestamp=%llu Size=%u", State.TotalEventCount, GetActiveThreadId(), Uid, AbsoluteTimestamp, EventSize); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } //////////////////////////////////////////////////////////////////////////////// void FAnalysisBridge::DebugLogLeaveScopeBEvent(uint32 Uid, uint64 BaseAbsoluteTimestamp, uint32 EventSize) { ++State.TotalEventCount; ++State.LeaveScopeTEventCount; State.TotalEventSize += EventSize; State.LeaveScopeTEventSize += EventSize; #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("[EVENT %llu] Tid=%u Uid=%u (LeaveScope_TB) Timestamp=(+%llu)=%llu Size=%u", State.TotalEventCount, GetActiveThreadId(), Uid, BaseAbsoluteTimestamp, State.Timing.BaseTimestamp + BaseAbsoluteTimestamp, EventSize); #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL } #endif // UE_TRACE_ANALYSIS_DEBUG // {{{1 machine ---------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FAnalysisMachine { public: enum class EStatus { Error, Abort, NotEnoughData, EndOfStream, Continue, Sync, }; struct FMachineContext { FAnalysisMachine& Machine; FAnalysisBridge& Bridge; FMessageDelegate& OnMessage; inline void EmitMessage(EAnalysisMessageSeverity Severity, FStringView Message) const { const bool _ = OnMessage.ExecuteIfBound(Severity, Message); } template inline void EmitMessagef(EAnalysisMessageSeverity Severity, const FormatType& Format, Types... Args) const { TStringBuilder<128> FormattedMessage; FormattedMessage.Appendf(Format, Forward(Args)...); EmitMessage(Severity, FormattedMessage.ToView()); } }; class FStage { public: typedef FAnalysisMachine::FMachineContext FMachineContext; typedef FAnalysisMachine::EStatus EStatus; virtual ~FStage() {} virtual EStatus OnData(FStreamReader& Reader, const FMachineContext& Context) = 0; virtual void EnterStage(const FMachineContext& Context) {}; virtual void ExitStage(const FMachineContext& Context) {}; }; FAnalysisMachine(FAnalysisBridge& InBridge, FMessageDelegate&& InMessage); ~FAnalysisMachine(); EStatus OnData(FStreamReader& Reader); void Transition(); template StageType* QueueStage(ArgsType... Args); private: void CleanUp(); FAnalysisBridge& Bridge; FStage* ActiveStage = nullptr; TArray StageQueue; TArray DeadStages; FMessageDelegate OnMessage; }; //////////////////////////////////////////////////////////////////////////////// FAnalysisMachine::FAnalysisMachine(FAnalysisBridge& InBridge, FMessageDelegate&& InMessage) : Bridge(InBridge) , OnMessage(InMessage) { } //////////////////////////////////////////////////////////////////////////////// FAnalysisMachine::~FAnalysisMachine() { CleanUp(); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisMachine::CleanUp() { for (FStage* Stage : DeadStages) { delete Stage; } DeadStages.Reset(); } //////////////////////////////////////////////////////////////////////////////// template StageType* FAnalysisMachine::QueueStage(ArgsType... Args) { StageType* Stage = new StageType(Args...); StageQueue.Insert(Stage, 0); return Stage; } //////////////////////////////////////////////////////////////////////////////// void FAnalysisMachine::Transition() { if (ActiveStage != nullptr) { const FMachineContext Context = { *this, Bridge, OnMessage }; ActiveStage->ExitStage(Context); DeadStages.Add(ActiveStage); } ActiveStage = (StageQueue.Num() > 0) ? StageQueue.Pop() : nullptr; if (ActiveStage != nullptr) { const FMachineContext Context = { *this, Bridge, OnMessage }; ActiveStage->EnterStage(Context); } } //////////////////////////////////////////////////////////////////////////////// FAnalysisMachine::EStatus FAnalysisMachine::OnData(FStreamReader& Reader) { const FMachineContext Context = { *this, Bridge, OnMessage }; EStatus Ret; do { CleanUp(); check(ActiveStage != nullptr); Ret = ActiveStage->OnData(Reader, Context); } while (Ret == EStatus::Continue); return Ret; } // {{{1 protocol-0 ------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FProtocol0Stage : public FAnalysisMachine::FStage { public: FProtocol0Stage(FTransport* InTransport); ~FProtocol0Stage(); virtual EStatus OnData(FStreamReader& Reader, const FMachineContext& Context) override; virtual void EnterStage(const FMachineContext& Context) override; virtual void ExitStage(const FMachineContext& Context) override; private: FTypeRegistry TypeRegistry; FTransport* Transport; }; //////////////////////////////////////////////////////////////////////////////// FProtocol0Stage::FProtocol0Stage(FTransport* InTransport) : Transport(InTransport) { } //////////////////////////////////////////////////////////////////////////////// FProtocol0Stage::~FProtocol0Stage() { delete Transport; } //////////////////////////////////////////////////////////////////////////////// void FProtocol0Stage::EnterStage(const FMachineContext& Context) { Context.Bridge.SetActiveThread(0); } //////////////////////////////////////////////////////////////////////////////// void FProtocol0Stage::ExitStage(const FMachineContext& Context) { // Ensure the transport does not have pending buffers (i.e. event data not yet processed). if (!Transport->IsEmpty()) { Context.EmitMessage(EAnalysisMessageSeverity::Warning, TEXT("Transport buffers are not empty at end of analysis (protocol 0)!")); } #if UE_TRACE_ANALYSIS_DEBUG Transport->DebugEnd(); #endif } //////////////////////////////////////////////////////////////////////////////// FProtocol0Stage::EStatus FProtocol0Stage::OnData( FStreamReader& Reader, const FMachineContext& Context) { Transport->SetReader(Reader); while (true) { const auto* Header = Transport->GetPointer(); if (Header == nullptr) { break; } uint32 BlockSize = Header->Size + sizeof(Protocol0::FEventHeader); Header = Transport->GetPointer(BlockSize); if (Header == nullptr) { break; } uint32 Uid = uint32(Header->Uid) & uint32(Protocol0::EKnownEventUids::UidMask); if (Uid == uint32(Protocol0::EKnownEventUids::NewEvent)) { // There is no need to check size here as the runtime never builds // packets that fragment new-event events. const FTypeRegistry::FTypeInfo* TypeInfo = TypeRegistry.Add(Header->EventData, 0); #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogNewEvent(Uid, TypeInfo, BlockSize); #endif Context.Bridge.OnNewType(TypeInfo); Transport->Advance(BlockSize); continue; } const FTypeRegistry::FTypeInfo* TypeInfo = TypeRegistry.Get(Uid); if (TypeInfo == nullptr) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Invalid TypeInfo for Uid %u (Tid=%u)", Uid, Context.Bridge.GetActiveThreadId()); return EStatus::Error; } #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogEvent(TypeInfo, BlockSize, 0, Context.Bridge.GetSerial().Value); //??? #endif FEventDataInfo EventDataInfo = { Header->EventData, *TypeInfo, nullptr, Header->Size }; Context.Bridge.OnEvent(EventDataInfo); Transport->Advance(BlockSize); } return Reader.IsEmpty() ? EStatus::EndOfStream : EStatus::NotEnoughData; } // {{{1 protocol-2 ------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FProtocol2Stage : public FAnalysisMachine::FStage { public: FProtocol2Stage(uint32 Version, FTransport* InTransport); ~FProtocol2Stage(); virtual EStatus OnData(FStreamReader& Reader, const FMachineContext& Context) override; virtual void EnterStage(const FMachineContext& Context) override; virtual void ExitStage(const FMachineContext& Context) override; protected: virtual int32 OnData(FStreamReader& Reader, FAnalysisBridge& Bridge); int32 OnDataAux(FStreamReader& Reader, FAuxDataCollector& Collector); FTypeRegistry TypeRegistry; FTransport* Transport; uint32 ProtocolVersion; uint32 SerialInertia = ~0u; }; //////////////////////////////////////////////////////////////////////////////// FProtocol2Stage::FProtocol2Stage(uint32 Version, FTransport* InTransport) : Transport(InTransport) , ProtocolVersion(Version) { switch (ProtocolVersion) { case Protocol0::EProtocol::Id: case Protocol1::EProtocol::Id: case Protocol2::EProtocol::Id: { FDispatchBuilder Dispatch; Dispatch.SetUid(uint16(Protocol2::EKnownEventUids::NewEvent)); Dispatch.SetLoggerName("$Trace"); Dispatch.SetEventName("NewEvent"); TypeRegistry.Add(Dispatch.Finalize()); } break; case Protocol3::EProtocol::Id: { FDispatchBuilder Dispatch; Dispatch.SetUid(uint16(Protocol3::EKnownEventUids::NewEvent)); Dispatch.SetLoggerName("$Trace"); Dispatch.SetEventName("NewEvent"); Dispatch.SetNoSync(); TypeRegistry.Add(Dispatch.Finalize()); } break; } } //////////////////////////////////////////////////////////////////////////////// FProtocol2Stage::~FProtocol2Stage() { delete Transport; } //////////////////////////////////////////////////////////////////////////////// void FProtocol2Stage::EnterStage(const FMachineContext& Context) { auto& Serial = Context.Bridge.GetSerial(); if (ProtocolVersion == Protocol1::EProtocol::Id) { Serial.Mask = 0x0000ffff; } else { Serial.Mask = 0x00ffffff; } UE_TRACE_ANALYSIS_DEBUG_LOG("Serial.Mask = 0x%X", Serial.Mask); } //////////////////////////////////////////////////////////////////////////////// void FProtocol2Stage::ExitStage(const FMachineContext& Context) { // Ensure the transport does not have pending buffers (i.e. event data not yet processed). if (!Transport->IsEmpty()) { Context.EmitMessagef(EAnalysisMessageSeverity::Warning, TEXT("Transport buffers are not empty at end of analysis (protocol %u)!"), ProtocolVersion); } #if UE_TRACE_ANALYSIS_DEBUG Transport->DebugEnd(); #endif } //////////////////////////////////////////////////////////////////////////////// FProtocol2Stage::EStatus FProtocol2Stage::OnData( FStreamReader& Reader, const FMachineContext& Context) { auto* InnerTransport = (FTidPacketTransport*)Transport; InnerTransport->SetReader(Reader); const FTidPacketTransport::ETransportResult Result = InnerTransport->Update(); if (Result == FTidPacketTransport::ETransportResult::Error) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: An error was detected in the transport layer, most likely due to a corrupt trace file."); Context.EmitMessage( EAnalysisMessageSeverity::Error, TEXT("An error was detected in the transport layer, most likely due to a corrupt trace file. See log for details.") ); return EStatus::Error; } struct FRotaItem { uint32 Serial; uint32 ThreadId; FStreamReader* Reader; bool operator < (const FRotaItem& Rhs) const { int32 Delta = Rhs.Serial - Serial; int32 Wrapped = uint32(Delta + 0x007f'fffe) >= uint32(0x00ff'fffd); return (Wrapped ^ (Delta > 0)) != 0; } }; TArray Rota; for (uint32 i = 0, n = InnerTransport->GetThreadCount(); i < n; ++i) { FStreamReader* ThreadReader = InnerTransport->GetThreadStream(i); uint32 ThreadId = InnerTransport->GetThreadId(i); Rota.Add({~0u, ThreadId, ThreadReader}); } auto& Serial = Context.Bridge.GetSerial(); while (true) { uint32 ActiveCount = uint32(Rota.Num()); for (uint32 i = 0; i < ActiveCount;) { FRotaItem& RotaItem = Rota[i]; if (int32(RotaItem.Serial) > int32(Serial.Value & Serial.Mask)) { ++i; continue; } Context.Bridge.SetActiveThread(RotaItem.ThreadId); uint32 AvailableSerial = OnData(*(RotaItem.Reader), Context.Bridge); if (int32(AvailableSerial) >= 0) { RotaItem.Serial = AvailableSerial; if (Rota[0].Serial > AvailableSerial) { Swap(Rota[0], RotaItem); } ++i; } else { FRotaItem TempItem = RotaItem; TempItem.Serial = ~0u; for (uint32 j = i, m = ActiveCount - 1; j < m; ++j) { Rota[j] = Rota[j + 1]; } Rota[ActiveCount - 1] = TempItem; --ActiveCount; } if (((Rota[0].Serial - Serial.Value) & Serial.Mask) == 0) { i = 0; } } if (ActiveCount < 1) { break; } TArrayView ActiveRota(Rota.GetData(), ActiveCount); Algo::Sort(ActiveRota); int32 MinLogSerial = Rota[0].Serial; if (ActiveCount > 1) { int32 MaxLogSerial = Rota[ActiveCount - 1].Serial; if ((uint32(MinLogSerial - Serial.Value) & Serial.Mask) == 0) { continue; } // If min/max are more than half the serial range apart consider them // as having wrapped. int32 HalfRange = int32(Serial.Mask >> 1); if ((MaxLogSerial - MinLogSerial) >= HalfRange) { for (uint32 i = 0; i < ActiveCount; ++i) { FRotaItem& RotaItem = Rota[i]; if (int32(RotaItem.Serial) >= HalfRange) { MinLogSerial = RotaItem.Serial; break; } } } } // If the current serial has its MSB set we're currently in a mode trying // to derive the best starting serial. if (int32(Serial.Value) < int32(0xc0000000)) { Serial.Value = (MinLogSerial & Serial.Mask); UE_TRACE_ANALYSIS_DEBUG_LOG("New Serial.Value: %u", Serial.Value); continue; } // If we didn't stumble across the next serialized event we have done all // we can for now. if ((uint32(MinLogSerial - Serial.Value) & Serial.Mask) != 0) { break; } } // Patch the serial value to try and recover from gaps. Note that the bits // used to wait for the serial-sync event are ignored as that event may never // be reached if leading events are synchronized. Some inertia is added as // the missing range of events can be in subsequent packets. (Maximum inertia // need only be the size of the tail / io-read-size). if (Rota.Num() > 0) { int32 LowestSerial = int32(Rota[0].Serial); if (LowestSerial >= 0) { enum { InertiaLen = 0x20, InertiaStart = 0x7f - InertiaLen, InertiaBase = InertiaStart << 25, // leaves bit 24 unset so InertiaInc = 1 << 25, // ~0u can never happen }; if (SerialInertia == ~0u) { SerialInertia = LowestSerial + InertiaBase; } else { SerialInertia += InertiaInc; if (int32(SerialInertia) >= 0) { if (SerialInertia == LowestSerial) { SerialInertia = ~0u; Serial.Value = LowestSerial; UE_TRACE_ANALYSIS_DEBUG_LOG("New Serial.Value: %u (LowestSerial)", Serial.Value); return OnData(Reader, Context); } SerialInertia = ~0u; } } } } return Reader.IsEmpty() ? EStatus::EndOfStream : EStatus::NotEnoughData; } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol2Stage::OnData(FStreamReader& Reader, FAnalysisBridge& Bridge) { auto& Serial = Bridge.GetSerial(); while (true) { auto Mark = Reader.SaveMark(); const auto* Header = Reader.GetPointer(); if (Header == nullptr) { break; } uint32 Uid = uint32(Header->Uid) & uint32(Protocol2::EKnownEventUids::UidMask); const FTypeRegistry::FTypeInfo* TypeInfo = TypeRegistry.Get(Uid); if (TypeInfo == nullptr) { // Event-types may not to be discovered in Uid order. UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Invalid TypeInfo for Uid %u (Tid=%u)", Uid, Bridge.GetActiveThreadId()); break; } uint32 BlockSize = Header->Size; // Make sure we consume events in the correct order if ((TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_NoSync) == 0) { switch (ProtocolVersion) { case Protocol1::EProtocol::Id: { const auto* HeaderV1 = (Protocol1::FEventHeader*)Header; if (HeaderV1->Serial != (Serial.Value & Serial.Mask)) { #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Tid=%u --> EventSerial=%u", Bridge.GetActiveThreadId(), HeaderV1->Serial); #endif return HeaderV1->Serial; } BlockSize += sizeof(*HeaderV1); } break; case Protocol2::EProtocol::Id: case Protocol3::EProtocol::Id: { const auto* HeaderSync = (Protocol2::FEventHeaderSync*)Header; uint32 EventSerial = HeaderSync->SerialLow|(uint32(HeaderSync->SerialHigh) << 16); if (EventSerial != (Serial.Value & Serial.Mask)) { #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Tid=%u --> EventSerial=%u", Bridge.GetActiveThreadId(), EventSerial); #endif return EventSerial; } BlockSize += sizeof(*HeaderSync); } break; } } else { BlockSize += sizeof(*Header); } if (Reader.GetPointer(BlockSize) == nullptr) { break; } Reader.Advance(BlockSize); #if UE_TRACE_ANALYSIS_DEBUG uint32 AuxSize = 0; #endif FAuxDataCollector AuxCollector; if (TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_MaybeHasAux) { #if UE_TRACE_ANALYSIS_DEBUG auto AuxMark = Reader.SaveMark(); #endif int AuxStatus = OnDataAux(Reader, AuxCollector); if (AuxStatus == 0) { Reader.RestoreMark(Mark); break; } #if UE_TRACE_ANALYSIS_DEBUG AuxSize = uint32(UPTRINT(Reader.SaveMark()) - UPTRINT(AuxMark)); #endif } if ((TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_NoSync) == 0) { Serial.Value += 1; Serial.Value &= 0x3fffffff; // Don't set MSBs. They have other uses } auto* EventData = (const uint8*)Header + BlockSize - Header->Size; if (Uid == uint32(Protocol2::EKnownEventUids::NewEvent)) { // There is no need to check size here as the runtime never builds // packets that fragment new-event events. TypeInfo = TypeRegistry.Add(EventData, 0); #if UE_TRACE_ANALYSIS_DEBUG Bridge.DebugLogNewEvent(Uid, TypeInfo, uint32(UPTRINT(Reader.SaveMark()) - UPTRINT(Mark))); #endif Bridge.OnNewType(TypeInfo); } else { #if UE_TRACE_ANALYSIS_DEBUG const uint32 EventSize = uint32(UPTRINT(Reader.SaveMark()) - UPTRINT(Mark)); Bridge.DebugLogEvent(TypeInfo, EventSize - AuxSize, AuxSize, Serial.Value - 1); #endif FEventDataInfo EventDataInfo = { EventData, *TypeInfo, &AuxCollector, Header->Size, }; Bridge.OnEvent(EventDataInfo); } } return -1; } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol2Stage::OnDataAux(FStreamReader& Reader, FAuxDataCollector& Collector) { while (true) { const uint8* NextByte = Reader.GetPointer(); if (NextByte == nullptr) { return 0; } // Is the following sequence a blob of auxiliary data or the null // terminator byte? if (NextByte[0] == 0) { Reader.Advance(1); return 1; } // Get header and the auxiliary blob's size const auto* Header = Reader.GetPointer(); if (Header == nullptr) { return 0; } // Check it exists uint32 BlockSize = (Header->Size >> 8) + sizeof(*Header); if (Reader.GetPointer(BlockSize) == nullptr) { return 0; } // Attach to event FAuxData AuxData = {}; AuxData.Data = Header->Data; AuxData.DataSize = uint32(BlockSize - sizeof(*Header)); AuxData.FieldIndex = uint16(Header->FieldIndex & Protocol1::FAuxHeader::FieldMask); Collector.Push(AuxData); Reader.Advance(BlockSize); } } // {{{1 protocol-4 ------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FProtocol4Stage : public FProtocol2Stage { public: FProtocol4Stage(uint32 Version, FTransport* InTransport); private: virtual int32 OnData(FStreamReader& Reader, FAnalysisBridge& Bridge) override; int32 OnDataImpl(FStreamReader& Reader, FAnalysisBridge& Bridge); int32 OnDataKnown(uint32 Uid, FStreamReader& Reader, FAnalysisBridge& Bridge); }; //////////////////////////////////////////////////////////////////////////////// FProtocol4Stage::FProtocol4Stage(uint32 Version, FTransport* InTransport) : FProtocol2Stage(Version, InTransport) { } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol4Stage::OnData(FStreamReader& Reader, FAnalysisBridge& Bridge) { while (true) { if (int32 TriResult = OnDataImpl(Reader, Bridge)) { return (TriResult < 0) ? ~TriResult : -1; } } } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol4Stage::OnDataImpl(FStreamReader& Reader, FAnalysisBridge& Bridge) { auto& Serial = Bridge.GetSerial(); /* Returns 0 if an event was successfully processed, 1 if there's not enough * data available, or ~AvailableLogSerial if the pending event is in the future */ auto Mark = Reader.SaveMark(); const auto* UidCursor = Reader.GetPointer(); if (UidCursor == nullptr) { return 1; } uint32 UidBytes = 1 + !!(*UidCursor & Protocol4::EKnownEventUids::Flag_TwoByteUid); if (UidBytes > 1 && Reader.GetPointer(UidBytes) == nullptr) { return 1; } uint32 Uid = ~0u; switch (UidBytes) { case 1: Uid = *UidCursor; break; case 2: Uid = *(uint16*)UidCursor; break; } Uid >>= Protocol4::EKnownEventUids::_UidShift; if (Uid < Bridge.GetUserUidBias()) { Reader.Advance(UidBytes); #if UE_TRACE_ANALYSIS_DEBUG FAnalysisState& State = Bridge.GetState(); State.TempUidBytes = UidBytes; #endif if (!OnDataKnown(Uid, Reader, Bridge)) { Reader.RestoreMark(Mark); return 1; } return 0; } // Do we know about this event type yet? const FTypeRegistry::FTypeInfo* TypeInfo = TypeRegistry.Get(Uid); if (TypeInfo == nullptr) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Invalid TypeInfo for Uid %u (Tid=%u)", Uid, Bridge.GetActiveThreadId()); return 1; } if (!ensure(UidBytes == 2)) // see Protocol4::FEventHeader { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Invalid trace stream: Tid=%u Uid=%u encoded on 1 byte (instead of 2 bytes).", Bridge.GetActiveThreadId(), Uid); return 1; } // Parse the header const auto* Header = Reader.GetPointer(); if (Header == nullptr) { return 1; } uint32 BlockSize = Header->Size; // Make sure we consume events in the correct order if ((TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_NoSync) == 0) { if (Reader.GetPointer() == nullptr) { return 1; } const auto* HeaderSync = (Protocol4::FEventHeaderSync*)Header; uint32 EventSerial = HeaderSync->SerialLow|(uint32(HeaderSync->SerialHigh) << 16); if (EventSerial != (Serial.Value & Serial.Mask)) { #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Tid=%u --> EventSerial=%u", Bridge.GetActiveThreadId(), EventSerial); #endif return ~EventSerial; } BlockSize += sizeof(*HeaderSync); } else { BlockSize += sizeof(*Header); } // Is all the event's data available? if (Reader.GetPointer(BlockSize) == nullptr) { return 1; } Reader.Advance(BlockSize); #if UE_TRACE_ANALYSIS_DEBUG uint32 AuxSize = 0; #endif // Collect auxiliary data FAuxDataCollector AuxCollector; if (TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_MaybeHasAux) { // Important events' size may include their array data so we need to backtrack auto NextMark = Reader.SaveMark(); if (TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_Important) { Reader.RestoreMark(Mark); Reader.Advance(sizeof(Protocol4::FEventHeader) + TypeInfo->EventSize); } #if UE_TRACE_ANALYSIS_DEBUG auto AuxMark = Reader.SaveMark(); #endif int AuxStatus = OnDataAux(Reader, AuxCollector); if (AuxStatus == 0) { Reader.RestoreMark(Mark); return 1; } #if UE_TRACE_ANALYSIS_DEBUG AuxSize = uint32(UPTRINT(Reader.SaveMark()) - UPTRINT(AuxMark)); #endif // User error could have resulted in less space being used that was // allocated for important events. So we can't assume that aux data // reading has read all the way up to the next event. So we use marks if (TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_Important) { Reader.RestoreMark(NextMark); } } #if UE_TRACE_ANALYSIS_DEBUG const uint32 EventSize = uint32(UPTRINT(Reader.SaveMark()) - UPTRINT(Mark)); Bridge.DebugLogEvent(TypeInfo, EventSize - AuxSize, AuxSize, Serial.Value); #endif // Maintain sync if ((TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_NoSync) == 0) { Serial.Value += 1; Serial.Value &= 0x7fffffff; // don't set msb. that has other uses } // Sent the event to subscribed analyzers FEventDataInfo EventDataInfo = { (const uint8*)Header + BlockSize - Header->Size, *TypeInfo, &AuxCollector, Header->Size, }; Bridge.OnEvent(EventDataInfo); return 0; } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol4Stage::OnDataKnown( uint32 Uid, FStreamReader& Reader, FAnalysisBridge& Bridge) { #if UE_TRACE_ANALYSIS_DEBUG FAnalysisState& State = Bridge.GetState(); #endif switch (Uid) { case Protocol4::EKnownEventUids::NewEvent: { const auto* Size = Reader.GetPointer(); check(Size != nullptr); const void* EventTypeAndData = Reader.GetPointer(sizeof(*Size) + *Size); check(EventTypeAndData != nullptr); const FTypeRegistry::FTypeInfo* TypeInfo = TypeRegistry.Add(Size + 1, 4); #if UE_TRACE_ANALYSIS_DEBUG Bridge.DebugLogNewEvent(Uid, TypeInfo, uint32(State.TempUidBytes + sizeof(*Size) + *Size)); #endif Bridge.OnNewType(TypeInfo); Reader.Advance(sizeof(*Size) + *Size); } return 1; case Protocol4::EKnownEventUids::EnterScope: #if UE_TRACE_ANALYSIS_DEBUG Bridge.DebugLogEnterScopeEvent(Uid, State.TempUidBytes); #endif Bridge.EnterScope(); return 1; case Protocol4::EKnownEventUids::LeaveScope: #if UE_TRACE_ANALYSIS_DEBUG Bridge.DebugLogLeaveScopeEvent(Uid, State.TempUidBytes); #endif Bridge.LeaveScope(); return 1; case Protocol4::EKnownEventUids::EnterScope_T: { const uint8* Stamp = Reader.GetPointer(sizeof(uint64) - 1); if (Stamp == nullptr) { return 0; } const uint64 RelativeTimestamp = *(uint64*)(Stamp - 1) >> 8; #if UE_TRACE_ANALYSIS_DEBUG Bridge.DebugLogEnterScopeEvent(Uid, RelativeTimestamp, uint32(State.TempUidBytes + sizeof(uint64) - 1)); #endif Bridge.EnterScope(RelativeTimestamp); Reader.Advance(sizeof(uint64) - 1); } return 1; case Protocol4::EKnownEventUids::LeaveScope_T: { const uint8* Stamp = Reader.GetPointer(sizeof(uint64) - 1); if (Stamp == nullptr) { return 0; } const uint64 RelativeTimestamp = *(uint64*)(Stamp - 1) >> 8; #if UE_TRACE_ANALYSIS_DEBUG Bridge.DebugLogLeaveScopeEvent(Uid, RelativeTimestamp, uint32(State.TempUidBytes + sizeof(uint64) - 1)); #endif Bridge.LeaveScope(RelativeTimestamp); Reader.Advance(sizeof(uint64) - 1); } return 1; default: UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Cannot process known event %llu with Uid %u", State.TotalEventCount, Uid); return 0; }; } // {{{1 protocol-5 ------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FProtocol5Stage : public FAnalysisMachine::FStage { public: FProtocol5Stage(FTransport* InTransport); virtual void ExitStage(const FMachineContext& Context) override; protected: struct alignas(16) FEventDesc { union { struct { int32 Serial; uint16 Uid : 14; uint16 bTwoByteUid : 1; uint16 bHasAux : 1; uint16 AuxKey; }; uint64 Meta = 0; }; union { uint32 GapLength; const uint8* Data = nullptr; }; #if UE_TRACE_ANALYSIS_DEBUG uint32 EventSize = 0; uint32 AuxSize = 0; uint64 Reserved = 0; #endif }; #if UE_TRACE_ANALYSIS_DEBUG static_assert(sizeof(FEventDesc) == 32, ""); #else static_assert(sizeof(FEventDesc) == 16, ""); #endif struct alignas(16) FEventDescStream { uint32 ThreadId; uint32 TransportIndex; union { uint32 ContainerIndex; const FEventDesc* EventDescs; }; enum { GapThreadId = ~0u }; }; static_assert(sizeof(FEventDescStream) == 16, ""); struct FSerialDistancePredicate { bool operator () (const FEventDescStream& Lhs, const FEventDescStream& Rhs) const { // Provided that less than approximately "SerialRange * BytesPerSerial" // is buffered there should never be more that "SerialRange / 2" serial // numbers. Thus if the distance between any two serial numbers is larger // than half the serial space, they have wrapped. uint32 Ld = Lhs.EventDescs->Serial - Origin; uint32 Rd = Rhs.EventDescs->Serial - Origin; return Ld < Rd; }; uint32 Origin; }; enum ESerial : int32 { Bits = 24, Mask = (1 << Bits) - 1, Range = 1 << Bits, Ignored = Range << 2, // far away so proper serials always compare less-than Terminal, }; using EventDescArray = TArray; using EKnownUids = Protocol5::EKnownEventUids; virtual EStatus OnData(FStreamReader& Reader, const FMachineContext& Context) override; EStatus OnDataNewEvents(const FMachineContext& Context); EStatus OnDataImportant(const FMachineContext& Context); EStatus OnDataNormal(const FMachineContext& Context); int32 ParseImportantEvents(FStreamReader& Reader, EventDescArray& OutEventDescs, const FMachineContext& Context); int32 ParseEvents(FStreamReader& Reader, EventDescArray& OutEventDescs, const FMachineContext& Context); int32 ParseEventsWithAux(FStreamReader& Reader, EventDescArray& OutEventDescs, const FMachineContext& Context); int32 ParseEvent(FStreamReader& Reader, FEventDesc& OutEventDesc, const FMachineContext& Context); virtual void SetSizeIfKnownEvent(uint32 Uid, uint32& InOutEventSize); virtual bool DispatchKnownEvent(const FMachineContext& Context, uint32 Uid, const FEventDesc* Cursor); int32 DispatchNormalEvents(const FMachineContext& Context, TArray& EventDescHeap); int32 DispatchEvents(const FMachineContext& Context, TArray& EventDescHeap); int32 DispatchEvents(const FMachineContext& Context, const FEventDesc* EventDesc, uint32 Count); void DetectSerialGaps(TArray& EventDescHeap); template void ForEachSerialGap(const TArray& EventDescHeap, Callback&& InCallback); #if UE_TRACE_ANALYSIS_DEBUG void PrintParsedEvent(int EventIndex, const FEventDesc& EventDesc, int32 Size); #endif // UE_TRACE_ANALYSIS_DEBUG FTypeRegistry TypeRegistry; FTidPacketTransport& Transport; EventDescArray EventDescs; EventDescArray SerialGaps; uint32 NextSerial = ~0u; uint32 OldNextSerial = ~0u; uint32 NextSerialWaitCount = 0; uint32 SyncCount; uint32 EventVersion = 4; //Protocol version 5 uses the event version from protocol 4 bool bSkipSerialError = false; bool bSkipSerial = false; }; //////////////////////////////////////////////////////////////////////////////// FProtocol5Stage::FProtocol5Stage(FTransport* InTransport) : Transport(*(FTidPacketTransport*)InTransport) , SyncCount(Transport.GetSyncCount()) { EventDescs.Reserve(8 << 10); } //////////////////////////////////////////////////////////////////////////////// void FProtocol5Stage::ExitStage(const FMachineContext& Context) { // Ensure the transport does not have pending buffers (i.e. event data not yet processed). if (!Transport.IsEmpty()) { Context.EmitMessage(EAnalysisMessageSeverity::Warning, TEXT("Transport buffers are not empty at end of analysis (protocol 5)!")); } #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.GetSerial().Value = NextSerial; Transport.DebugEnd(); #endif } //////////////////////////////////////////////////////////////////////////////// FProtocol5Stage::EStatus FProtocol5Stage::OnData( FStreamReader& Reader, const FMachineContext& Context) { Transport.SetReader(Reader); const FTidPacketTransport::ETransportResult Result = Transport.Update(); if (Result == FTidPacketTransport::ETransportResult::Error) { Context.EmitMessage( EAnalysisMessageSeverity::Error, TEXT("An error was detected in the transport layer, most likely due to a corrupt trace file. See log for details.") ); return EStatus::Error; } do { // New-events. They must be processed before anything else otherwise events // can not be interpreted. EStatus Ret = OnDataNewEvents(Context); if (Ret == EStatus::Error) { return Ret; } // Important events Ret = OnDataImportant(Context); if (Ret == EStatus::Error) { return Ret; } bool bNotEnoughData = (Ret == EStatus::NotEnoughData); // Normal events Ret = OnDataNormal(Context); if (Ret == EStatus::Error) { return Ret; } if (Ret == EStatus::Sync) { // After processing a SYNC packet, we need to read data once more. return OnData(Reader, Context); } bNotEnoughData |= (Ret == EStatus::NotEnoughData); if (bNotEnoughData && !bSkipSerial) { return EStatus::NotEnoughData; } } while (bSkipSerial); return Reader.CanMeetDemand() ? EStatus::Continue : EStatus::EndOfStream; } //////////////////////////////////////////////////////////////////////////////// FProtocol5Stage::EStatus FProtocol5Stage::OnDataNewEvents(const FMachineContext& Context) { EventDescs.Reset(); FStreamReader* ThreadReader = Transport.GetThreadStream(ETransportTid::Events); if (ThreadReader->IsEmpty()) { return EStatus::EndOfStream; } if (ParseImportantEvents(*ThreadReader, EventDescs, Context) < 0) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Failed to parse important events"); return EStatus::Error; } for (const FEventDesc& EventDesc : EventDescs) { const FTypeRegistry::FTypeInfo* TypeInfo = TypeRegistry.Add(EventDesc.Data, EventVersion); #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogNewEvent(uint32(EventDesc.Uid), TypeInfo, EventDesc.EventSize + EventDesc.AuxSize); #endif Context.Bridge.OnNewType(TypeInfo); } return EStatus::EndOfStream; } //////////////////////////////////////////////////////////////////////////////// FProtocol5Stage::EStatus FProtocol5Stage::OnDataImportant(const FMachineContext& Context) { static_assert(ETransportTid::Importants == ETransportTid::Internal, "It is assumed there is only one 'important' thread stream"); EventDescs.Reset(); FStreamReader* ThreadReader = Transport.GetThreadStream(ETransportTid::Importants); if (ThreadReader->IsEmpty()) { return EStatus::EndOfStream; } if (ParseImportantEvents(*ThreadReader, EventDescs, Context) < 0) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Failed to parse important events"); return EStatus::Error; } bool bNotEnoughData = !ThreadReader->IsEmpty(); if (EventDescs.Num() <= 0) { return bNotEnoughData ? EStatus::NotEnoughData : EStatus::EndOfStream; } // Dispatch looks ahead to the next desc looking for runs of aux blobs. As // such we should add a terminal desc for it to read. Note the "- 1" too. FEventDesc& EventDesc = EventDescs.Emplace_GetRef(); EventDesc.Serial = ESerial::Terminal; Context.Bridge.SetActiveThread(ETransportTid::Importants); if (DispatchEvents(Context, EventDescs.GetData(), EventDescs.Num() - 1) < 0) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Failed to dispatch important events"); return EStatus::Error; } return bNotEnoughData ? EStatus::NotEnoughData : EStatus::EndOfStream; } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol5Stage::ParseImportantEvents(FStreamReader& Reader, EventDescArray& OutEventDescs, const FMachineContext& Context) { using namespace Protocol5; while (true) { uint32 Remaining = Reader.GetRemaining(); if (Remaining < sizeof(FImportantEventHeader)) { return 1; } const auto* Header = Reader.GetPointerUnchecked(); if (Remaining < uint32(Header->Size) + sizeof(FImportantEventHeader)) { return 1; } uint32 Uid = Header->Uid; FEventDesc EventDesc; EventDesc.Serial = ESerial::Ignored; EventDesc.Uid = (uint16)Uid; EventDesc.Data = Header->Data; // Special case for new events. It would work to add a 0 type to the // registry but this way avoid raveling things together. if (Uid == EKnownUids::NewEvent) { #if UE_TRACE_ANALYSIS_DEBUG EventDesc.EventSize = sizeof(*Header) + Header->Size; #endif OutEventDescs.Add(EventDesc); Reader.Advance(sizeof(*Header) + Header->Size); continue; } const FTypeRegistry::FTypeInfo* TypeInfo = TypeRegistry.Get(Uid); if (TypeInfo == nullptr) { UE_TRACE_ANALYSIS_DEBUG_LOG("UID %u (0x%X) was not declared yet.", Uid, Uid); return 1; } #if UE_TRACE_ANALYSIS_DEBUG EventDesc.EventSize = sizeof(*Header) + TypeInfo->EventSize; #endif if (TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_MaybeHasAux) { EventDesc.bHasAux = 1; } OutEventDescs.Add(EventDesc); if (TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_MaybeHasAux) { const uint8* Cursor = Header->Data + TypeInfo->EventSize; const uint8* End = Header->Data + Header->Size; while (Cursor <= End) { if (Cursor[0] == uint8(EKnownUids::AuxDataTerminal)) { break; } const auto* AuxHeader = (FAuxHeader*)Cursor; FEventDesc& AuxDesc = OutEventDescs.Emplace_GetRef(); AuxDesc.Uid = uint8(EKnownUids::AuxData); AuxDesc.Data = AuxHeader->Data; AuxDesc.Serial = ESerial::Ignored; Cursor = AuxHeader->Data + (AuxHeader->Pack >> FAuxHeader::SizeShift); #if UE_TRACE_ANALYSIS_DEBUG AuxDesc.EventSize = sizeof(FAuxHeader); AuxDesc.AuxSize = (AuxHeader->Pack >> FAuxHeader::SizeShift); #endif } if (Cursor[0] != uint8(EKnownUids::AuxDataTerminal)) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Expecting AuxDataTerminal event"); Context.EmitMessage(EAnalysisMessageSeverity::Warning, TEXT("Expected an aux data terminal in the stream.")); return -1; } } Reader.Advance(sizeof(*Header) + Header->Size); } } //////////////////////////////////////////////////////////////////////////////// FProtocol5Stage::EStatus FProtocol5Stage::OnDataNormal(const FMachineContext& Context) { // Ordinary events EventDescs.Reset(); bool bNotEnoughData = false; TArray EventDescHeap; EventDescHeap.Reserve(Transport.GetThreadCount()); bSkipSerial = false; for (uint32 i = ETransportTid::Bias, n = Transport.GetThreadCount(); i < n; ++i) { uint32 NumEventDescs = EventDescs.Num(); #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 3 UE_TRACE_ANALYSIS_DEBUG_LOG("Thread:%u Id:%u", i, Transport.GetThreadId(i)); #endif // Extract all the events in the stream for this thread FStreamReader* ThreadReader = Transport.GetThreadStream(i); // Test if analysis has accumulated too much data for this thread. // This can happen on corrupted traces (ex. with serial sync events missing or out of order). constexpr uint32 MaxAccumulatedBytes = 2'000'000'000u; if (ThreadReader->GetRemaining() > MaxAccumulatedBytes) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Trace analysis accumulated too much data (%.2f MiB on thread %u) and will start to skip the missing serial sync events!", (double)ThreadReader->GetRemaining() / (1024.0 * 1024.0), Transport.GetThreadId(i)); if (!bSkipSerialError) { bSkipSerialError = true; Context.EmitMessagef( EAnalysisMessageSeverity::Error, TEXT("Trace analysis accumulated too much data (%.2f MiB on thread %u) and will start to skip the missing serial sync events!"), (double)ThreadReader->GetRemaining() / (1024.0 * 1024.0), Transport.GetThreadId(i) ); } bSkipSerial = true; } if (ParseEvents(*ThreadReader, EventDescs, Context) < 0) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Failed to parse events"); return EStatus::Error; } bNotEnoughData |= !ThreadReader->IsEmpty(); if (uint32(EventDescs.Num()) != NumEventDescs) { // Add a dummy event to delineate the end of this thread's events FEventDesc& EventDesc = EventDescs.Emplace_GetRef(); EventDesc.Serial = ESerial::Terminal; FEventDescStream Out; Out.ThreadId = Transport.GetThreadId(i); Out.TransportIndex = i; Out.ContainerIndex = NumEventDescs; EventDescHeap.Add(Out); } #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 3 UE_TRACE_ANALYSIS_DEBUG_LOG("Thread:%u bNotEnoughData:%d", i, bNotEnoughData); #endif } // Now EventDescs is stable we can convert the indices into pointers for (FEventDescStream& Stream : EventDescHeap) { Stream.EventDescs = EventDescs.GetData() + Stream.ContainerIndex; } #if UE_TRACE_ANALYSIS_DEBUG FAnalysisState& State = Context.Bridge.GetState(); if (EventDescs.Num() > State.MaxEventDescs) { State.MaxEventDescs = EventDescs.Num(); } #endif const bool bSync = (SyncCount != Transport.GetSyncCount()); int32 NumAvailableEvents = EventDescs.Num(); // Try to dispatch the parsed events. { int32 NumDispatchedEvents = DispatchNormalEvents(Context, EventDescHeap); if (NumDispatchedEvents < 0) { return EStatus::Error; } NumAvailableEvents += SerialGaps.Num(); // serial gaps are detected during DispatchNormalEvents #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Dispatched %d normal events (%d --> %d)", NumDispatchedEvents, NumAvailableEvents, NumAvailableEvents - NumDispatchedEvents); #endif NumAvailableEvents -= NumDispatchedEvents; check(NumAvailableEvents >= 0); // Count how many times we dispatched events, but without dispatching any "sync" event. if (OldNextSerial == NextSerial) { ++NextSerialWaitCount; } else { OldNextSerial = NextSerial; NextSerialWaitCount = 0; } } // Test if analysis has accumulated too much data (parsed events not dispatched yet). // But, only enforce the limit after we have received at least one SYNC package // (e.g. server traces can accumulate large amounts of data before first SYNC event). constexpr int32 MaxAvailableEventsHighLimit = 90'000'000; constexpr int32 MaxAvailableEventsLowLimit = 50'000'000; constexpr uint32 MaxNextSerialWaitCount = 20; bool bSkipSerialNow = false; if (SyncCount > 0 && !bSkipSerialError && NumAvailableEvents > MaxAvailableEventsHighLimit && NextSerialWaitCount > MaxNextSerialWaitCount) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Trace analysis accumulated too much data (%d parsed events) and will start to skip the missing serial sync events!", NumAvailableEvents); if (!bSkipSerialError) { bSkipSerialError = true; Context.EmitMessagef( EAnalysisMessageSeverity::Error, TEXT("Trace analysis accumulated too much data (%d parsed events) and will start to skip the missing serial sync events!"), NumAvailableEvents); } bSkipSerialNow = true; } if (bSkipSerialNow || (bSkipSerialError && NumAvailableEvents > MaxAvailableEventsLowLimit)) { do { // Skip serials and continue to dispatch parsed events. bSkipSerial = true; NextSerialWaitCount = 0; int32 NumDispatchedEvents = DispatchNormalEvents(Context, EventDescHeap); if (NumDispatchedEvents < 0) { return EStatus::Error; } #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Skipped serials and dispatched %d normal events (%d --> %d)", NumDispatchedEvents, NumAvailableEvents, NumAvailableEvents - NumDispatchedEvents); #endif NumAvailableEvents -= NumDispatchedEvents; check(NumAvailableEvents >= 0); } while (NumAvailableEvents > MaxAvailableEventsLowLimit); } #if 0 // If the reader is empty (no more incoming trace data) and we still have parsed events not dispatched, // then we'll try to skip the missing serial sync events. if (Transport.GetReader()->IsEmpty() && NumAvailableEvents > 0) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Trace reader is empty, but there are still %d parsed events not dispatched. Starting to skip the missing serial sync events!", NumAvailableEvents); Context.EmitMessagef( EAnalysisMessageSeverity::Error, TEXT("Trace reader is empty, but there are still %d parsed events not dispatched. Starting to skip the missing serial sync events!"), NumAvailableEvents); while (true) { // Skip serials and continue to dispatch parsed events. bSkipSerial = true; NextSerialWaitCount = 0; int32 NumDispatchedEvents = DispatchNormalEvents(Context, EventDescHeap); if (NumDispatchedEvents < 0) { return EStatus::Error; } #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Skipped serials and dispatched %d normal events (%d --> %d)", NumDispatchedEvents, NumAvailableEvents, NumAvailableEvents - NumDispatchedEvents); #endif NumAvailableEvents -= NumDispatchedEvents; check(NumAvailableEvents >= 0); if (NumAvailableEvents == 0) { break; } if (NumDispatchedEvents == 0) { UE_TRACE_ANALYSIS_DEBUG_LOG("Cannot dispatch the remaining %d (incomplete) parsed events!", NumAvailableEvents); break; } } bNotEnoughData = false; bSkipSerial = false; } #endif // If there are any streams left in the heap then we are unable to proceed // until more data is received. We'll rewind the streams until more data is // available. It is not an efficient way to do things, but it is simple way. for (FEventDescStream& Stream : EventDescHeap) { const FEventDesc& EventDesc = Stream.EventDescs[0]; uint32 HeaderSize = 1 + EventDesc.bTwoByteUid + (ESerial::Bits / 8); FStreamReader* Reader = Transport.GetThreadStream(Stream.TransportIndex); Reader->Backtrack(EventDesc.Data - HeaderSize); } if (bSync && SyncCount == Transport.GetSyncCount()) { return EStatus::Sync; } if (bNotEnoughData) { return EStatus::NotEnoughData; } return EStatus::EndOfStream; } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol5Stage::DispatchNormalEvents(const FMachineContext& Context, TArray& EventDescHeap) { #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Queued event descs: %d", EventDescs.Num()); #endif // Process leading unsynchronized events so that each stream starts with a synchronized event. int32 NumDispatchedUnsyncEvents = 0; for (FEventDescStream& Stream : EventDescHeap) { // Extract a run of consecutive unsynchronized events const FEventDesc* EndDesc = Stream.EventDescs; for (; EndDesc->Serial == ESerial::Ignored; ++EndDesc); // Dispatch. const FEventDesc* StartDesc = Stream.EventDescs; int32 DescNum = int32(UPTRINT(EndDesc - StartDesc)); if (DescNum > 0) { NumDispatchedUnsyncEvents += DescNum; Context.Bridge.SetActiveThread(Stream.ThreadId); if (DispatchEvents(Context, StartDesc, DescNum) < 0) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Failed to dispatch events"); return -1; } Stream.EventDescs = EndDesc; } } // Trim off empty streams int32 NumTerminators = EventDescHeap.Num(); EventDescHeap.RemoveAllSwap([] (const FEventDescStream& Stream) { return (Stream.EventDescs->Serial == ESerial::Terminal); }); NumTerminators -= EventDescHeap.Num(); // Early out if there isn't any events available. if (UNLIKELY(EventDescHeap.IsEmpty())) { return NumDispatchedUnsyncEvents + NumTerminators; } // A min-heap is used to peel off groups of events by lowest serial EventDescHeap.Heapify(FSerialDistancePredicate{NextSerial}); #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 { const FEventDescStream& TopStream = EventDescHeap.HeapTop(); UE_TRACE_ANALYSIS_DEBUG_LOG("NextSerial=%u LowestSerial=%d (Tid=%u)", NextSerial, TopStream.EventDescs[0].Serial, TopStream.ThreadId); } #endif // Events must be consumed contiguously. if (bSkipSerial) { uint32 LowestSerial = EventDescHeap.HeapTop().EventDescs[0].Serial; if (LowestSerial != NextSerial) { #if UE_TRACE_ANALYSIS_DEBUG uint32 SerialsToSkip = ((LowestSerial & ESerial::Mask) + ESerial::Range - (NextSerial & ESerial::Mask)) & ESerial::Mask; Context.Bridge.GetState().NumSkippedSerials += SerialsToSkip; UE_TRACE_ANALYSIS_DEBUG_LOG("Warning: NextSerial skips %u events (from %u to %u)", SerialsToSkip, NextSerial, LowestSerial); #endif NextSerial = LowestSerial; } } else if (NextSerial == ~0u) { uint32 LowestSerial = EventDescHeap.HeapTop().EventDescs[0].Serial; if (Transport.GetSyncCount() || LowestSerial == 0) { NextSerial = LowestSerial; UE_TRACE_ANALYSIS_DEBUG_LOG("NextSerial=%u", NextSerial); } } DetectSerialGaps(EventDescHeap); int32 NumDispatchedEvents = DispatchEvents(Context, EventDescHeap); if (NumDispatchedEvents < 0) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Failed to dispatch events"); return -1; } return NumDispatchedUnsyncEvents + NumTerminators + NumDispatchedEvents; } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol5Stage::DispatchEvents( const FMachineContext& Context, TArray& EventDescHeap) { #if UE_TRACE_ANALYSIS_DEBUG FAnalysisState& State = Context.Bridge.GetState(); #endif auto UpdateHeap = [&] (const FEventDescStream& Stream, const FEventDesc* EventDesc) { if (EventDesc->Serial != ESerial::Terminal) { FEventDescStream Next = Stream; Next.EventDescs = EventDesc; EventDescHeap.Add(Next); } EventDescHeap.HeapPopDiscard(FSerialDistancePredicate{NextSerial}, EAllowShrinking::No); }; int32 NumDispatchedEvents = 0; do { const FEventDescStream& Stream = EventDescHeap.HeapTop(); const FEventDesc* StartDesc = Stream.EventDescs; const FEventDesc* EndDesc = StartDesc; // DetectSerialGaps() will add a special stream that communicates gaps // in serial numbers, gaps that will never be resolved. Thread IDs // are uint16 everywhere else so they will never collide with GapThreadId. if (Stream.ThreadId == FEventDescStream::GapThreadId) { NextSerial = EndDesc->Serial + EndDesc->GapLength; NextSerial &= ESerial::Mask; #if UE_TRACE_ANALYSIS_DEBUG if (NextSerial != EndDesc->Serial + EndDesc->GapLength) { State.SerialWrappedCount++; } State.NumSkippedSerialGaps++; UE_TRACE_ANALYSIS_DEBUG_LOG("Skip serial gap (%u +%u) --> NextSerial=%u", EndDesc->Serial, EndDesc->GapLength, NextSerial); #endif UpdateHeap(Stream, EndDesc + 1); NumDispatchedEvents += ((EndDesc + 1)->Serial == ESerial::Terminal) ? 2 : 1;// GapThreadId event + Terminal event continue; } // Extract a run of consecutive events (plus runs of unsynchronized ones). if (EndDesc->Serial == NextSerial) { #if UE_TRACE_ANALYSIS_DEBUG const uint32 CurrentSerial = NextSerial; #endif do { NextSerial = (NextSerial + 1) & ESerial::Mask; do { ++EndDesc; } while (EndDesc->Serial == ESerial::Ignored); } while (EndDesc->Serial == NextSerial); #if UE_TRACE_ANALYSIS_DEBUG if (NextSerial < CurrentSerial) { ++State.SerialWrappedCount; } #endif } else { #if UE_TRACE_ANALYSIS_DEBUG if (uint32(EndDesc->Serial) < NextSerial && NextSerial != ~0u && NextSerial - uint32(EndDesc->Serial) < ESerial::Range/2) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Lowest serial %d (Tid=%u Uid=%u) is too low (NextSerial=%u; %d event descs) !!!", EndDesc->Serial, Stream.ThreadId, uint32(EndDesc->Uid), NextSerial, EventDescs.Num()); } else { #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Lowest serial %d (Tid=%u Uid=%u) is not low enough (NextSerial=%u; %d event descs)", EndDesc->Serial, Stream.ThreadId, uint32(EndDesc->Uid), NextSerial, EventDescs.Num()); #endif } #if UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Available streams (SerialWrappedCount=%u):", State.SerialWrappedCount); for (const FEventDescStream& EventDescStream : EventDescHeap) { uint32 BufferSize = 0; uint32 DataSize = 0; // parsed data size + remaining data size uint32 RemainingSize = 0; FTidPacketTransport* InnerTransport = (FTidPacketTransport*)(&Transport); for (uint32 i = 0, n = InnerTransport->GetThreadCount(); i < n; ++i) { FStreamBuffer* ThreadReader = (FStreamBuffer*)InnerTransport->GetThreadStream(i); uint32 ThreadId = InnerTransport->GetThreadId(i); if (ThreadId == EventDescStream.ThreadId) { BufferSize = ThreadReader->GetBufferSize(); const FEventDesc& EventDesc = EventDescStream.EventDescs[0]; uint32 HeaderSize = 1 + EventDesc.bTwoByteUid + (ESerial::Bits / 8); DataSize = ThreadReader->GetBacktrackSize(EventDesc.Data - HeaderSize); RemainingSize = ThreadReader->GetRemaining(); break; } } UE_TRACE_ANALYSIS_DEBUG_BeginStringBuilder(); UE_TRACE_ANALYSIS_DEBUG_Appendf(" Tid=%u : Serial=%u BufferSize=%u DataSize=%u", EventDescStream.ThreadId, EventDescStream.EventDescs->Serial, BufferSize, DataSize); if (RemainingSize != 0) { UE_TRACE_ANALYSIS_DEBUG_Appendf(" (%u + %u)", DataSize - RemainingSize, RemainingSize); } if (EventDescStream.EventDescs->Serial == NextSerial) { UE_TRACE_ANALYSIS_DEBUG_Append(" (next)"); } UE_TRACE_ANALYSIS_DEBUG_EndStringBuilder(); } #endif // UE_TRACE_ANALYSIS_DEBUG_LEVEL #endif // UE_TRACE_ANALYSIS_DEBUG #if 0 int32 MinSerial = EndDesc->Serial; EventDescHeap.Heapify(FSerialDistancePredicate{NextSerial}); const FEventDescStream& MinStream = EventDescHeap.HeapTop(); const FEventDesc* MinDesc = MinStream.EventDescs; if (MinDesc->Serial < MinSerial) { UE_TRACE_ANALYSIS_DEBUG_LOG("Try one more time with lowest serial %d (Tid=%u Uid=%u)", MinDesc->Serial, MinStream.ThreadId, uint32(MinDesc->Uid)); continue; } #endif // The lowest known serial number is not low enough so we are unable to proceed any further. break; } // Dispatch. Context.Bridge.SetActiveThread(Stream.ThreadId); int32 DescNum = int32(UPTRINT(EndDesc - StartDesc)); check(DescNum > 0); NumDispatchedEvents += DescNum; if (DispatchEvents(Context, StartDesc, DescNum) < 0) { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Failed to dispatch events"); return -1; } UpdateHeap(Stream, EndDesc); NumDispatchedEvents += (EndDesc->Serial == ESerial::Terminal) ? 1 : 0; // Terminal event } while (!EventDescHeap.IsEmpty()); return NumDispatchedEvents; } //////////////////////////////////////////////////////////////////////////////// #if UE_TRACE_ANALYSIS_DEBUG void FProtocol5Stage::PrintParsedEvent(int EventIndex, const FEventDesc& EventDesc, int32 Size) { UE_TRACE_ANALYSIS_DEBUG_BeginStringBuilder(); UE_TRACE_ANALYSIS_DEBUG_Appendf("Event=%-6d Uid=%-4u ", EventIndex, uint32(EventDesc.Uid)); if (EventDesc.Serial >= ESerial::Range) { UE_TRACE_ANALYSIS_DEBUG_Appendf("Serial=0x%07X ", EventDesc.Serial); } else { UE_TRACE_ANALYSIS_DEBUG_Appendf("Serial=%-9d ", EventDesc.Serial); } UE_TRACE_ANALYSIS_DEBUG_Appendf("Size=%d", Size); if (EventDesc.bHasAux) { UE_TRACE_ANALYSIS_DEBUG_Append(" aux"); } if (EventDesc.Uid == EKnownUids::AuxData) { UE_TRACE_ANALYSIS_DEBUG_Append(" data"); } else if (EventDesc.Uid == EKnownUids::AuxDataTerminal) { UE_TRACE_ANALYSIS_DEBUG_Append(" end"); } UE_TRACE_ANALYSIS_DEBUG_EndStringBuilder(); } #endif // UE_TRACE_ANALYSIS_DEBUG //////////////////////////////////////////////////////////////////////////////// int32 FProtocol5Stage::ParseEvents(FStreamReader& Reader, EventDescArray& OutEventDescs, const FMachineContext& Context) { while (!Reader.IsEmpty()) { FEventDesc EventDesc; int32 Size = ParseEvent(Reader, EventDesc, Context); if (Size <= 0) { return Size; } #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 3 PrintParsedEvent(OutEventDescs.Num(), EventDesc, Size); #endif // UE_TRACE_ANALYSIS_DEBUG OutEventDescs.Add(EventDesc); if (EventDesc.bHasAux) { uint32 RewindDescsNum = OutEventDescs.Num() - 1; auto RewindMark = Reader.SaveMark(); Reader.Advance(Size); int Ok = ParseEventsWithAux(Reader, OutEventDescs, Context); if (Ok < 0) { return Ok; } if (Ok == 0) { #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Warning: Incomplete aux stack (Uid=%u)! Rewind %d parsed events.", EventDesc.Uid, OutEventDescs.Num() - RewindDescsNum); #endif OutEventDescs.SetNum(RewindDescsNum); Reader.RestoreMark(RewindMark); break; } continue; } Reader.Advance(Size); } return 0; } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol5Stage::ParseEventsWithAux(FStreamReader& Reader, EventDescArray& OutEventDescs, const FMachineContext& Context) { // We are now "in" the scope of an event with zero or more aux-data blocks. // We will consume events until we leave this scope (a aux-data-terminal). // A running key is assigned to each event with a gap left following events // that may have aux-data blocks. Aux-data blocks are assigned a key that // fits in these gaps. Once sorted by this key, events maintain their order // while aux-data blocks are moved to directly follow their owners. TArray> AuxKeyStack = { 0 }; uint32 AuxKey = 2; uint32 FirstDescIndex = OutEventDescs.Num(); bool bUnsorted = false; while (!Reader.IsEmpty()) { FEventDesc EventDesc; EventDesc.Serial = ESerial::Ignored; int32 Size = ParseEvent(Reader, EventDesc, Context); if (Size <= 0) { return Size; } #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 3 PrintParsedEvent(OutEventDescs.Num(), EventDesc, Size); #endif // UE_TRACE_ANALYSIS_DEBUG Reader.Advance(Size); if (EventDesc.Uid == EKnownUids::AuxDataTerminal) { // Leave the scope of an aux-owning event. if (AuxKeyStack.Pop() == 0) { break; } continue; } else if (EventDesc.Uid == EKnownUids::AuxData) { // Move an aux-data block to follow its owning event EventDesc.AuxKey = AuxKeyStack.Last() + 1; } else { EventDesc.AuxKey = uint16(AuxKey); // Maybe it is time to create a new aux-data owner scope if (EventDesc.bHasAux) { AuxKeyStack.Add(uint16(AuxKey)); } // This event may be in the middle of an earlier event's aux data blocks. bUnsorted = true; } OutEventDescs.Add(EventDesc); ++AuxKey; constexpr uint32 MaxAuxKey = 0x7fff; if (AuxKeyStack.Num() == 1 && AuxKey > MaxAuxKey) { // If an "aux terminal" for the initial event was not detected after // many intermediate events, we can assume it is lost. check(FirstDescIndex > 0); uint32 NumParsedEvents = uint32(OutEventDescs.Num()) - FirstDescIndex; UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Ignoring lost aux terminal for event with uid %u (desc %d), after parsing %u events", OutEventDescs[FirstDescIndex - 1].Uid, FirstDescIndex - 1, NumParsedEvents); Context.EmitMessagef( EAnalysisMessageSeverity::Error, TEXT("Ignoring lost aux terminal for event with uid %u, after parsing %u events."), OutEventDescs[FirstDescIndex - 1].Uid, NumParsedEvents); AuxKeyStack.Pop(); break; } } if (AuxKeyStack.Num() > 0) { // There was not enough data available to complete the outer most scope return 0; } checkf((AuxKey & 0xffff0000) == 0, TEXT("AuxKey overflow (0x%X)"), AuxKey); // Sort to get all aux-blocks contiguous with their owning event if (bUnsorted) { uint32 NumDescs = OutEventDescs.Num() - FirstDescIndex; #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Sorting %u event descs", NumDescs); #endif TArrayView DescsView(OutEventDescs.GetData() + FirstDescIndex, NumDescs); Algo::StableSort( DescsView, [] (const FEventDesc& Lhs, const FEventDesc& Rhs) { return Lhs.AuxKey < Rhs.AuxKey; } ); } return 1; } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol5Stage::ParseEvent(FStreamReader& Reader, FEventDesc& EventDesc, const FMachineContext& Context) { using namespace Protocol5; // No need to aggressively bounds check here. Events are never fragmented // due to the way that data is transported (aux payloads can be though). const uint8* Cursor = Reader.GetPointerUnchecked(); // Parse the event's ID uint32 Uid = *Cursor; if (Uid & EKnownUids::Flag_TwoByteUid) { EventDesc.bTwoByteUid = 1; Uid = *(uint16*)Cursor; ++Cursor; } Uid >>= EKnownUids::_UidShift; ++Cursor; // Calculate the size of the event uint32 Serial = uint32(ESerial::Ignored); uint32 EventSize = 0; if (Uid < EKnownUids::User) { /* Well-known event */ if (Uid == Protocol5::EKnownEventUids::AuxData) { --Cursor; // FAuxHeader includes the one-byte Uid const auto* AuxHeader = (FAuxHeader*)Cursor; uint32 Remaining = Reader.GetRemaining(); uint32 Size = AuxHeader->Pack >> FAuxHeader::SizeShift; if (Remaining < Size + sizeof(FAuxHeader)) { return 0; } EventSize = Size; Cursor += sizeof(FAuxHeader); } else { SetSizeIfKnownEvent(Uid, EventSize); } EventDesc.bHasAux = 0; } else { /* Ordinary events */ const FTypeRegistry::FTypeInfo* TypeInfo = TypeRegistry.Get(Uid); if (TypeInfo == nullptr) { UE_TRACE_ANALYSIS_DEBUG_LOG("Warning: UID %u (0x%X) was not declared yet!", Uid, Uid); return 0; } EventSize = TypeInfo->EventSize; EventDesc.bHasAux = !!(TypeInfo->Flags & FTypeRegistry::FTypeInfo::Flag_MaybeHasAux); if ((TypeInfo->Flags & FDispatch::Flag_NoSync) == 0) { memcpy(&Serial, Cursor, sizeof(int32)); Serial &= ESerial::Mask; Cursor += 3; } } EventDesc.Serial = Serial; EventDesc.Uid = (uint16)Uid; EventDesc.Data = Cursor; uint32 HeaderSize = uint32(UPTRINT(Cursor - Reader.GetPointer())); uint32 TotalEventSize = HeaderSize + EventSize; #if UE_TRACE_ANALYSIS_DEBUG EventDesc.EventSize = TotalEventSize; #endif return TotalEventSize; } //////////////////////////////////////////////////////////////////////////////// template void FProtocol5Stage::ForEachSerialGap( const TArray& EventDescHeap, Callback&& InCallback) { TArray HeapCopy(EventDescHeap); int Serial = HeapCopy.HeapTop().EventDescs[0].Serial; // There might be a gap at the beginning of the heap if some events have // already been consumed. if (NextSerial != Serial) { if (!InCallback(NextSerial, Serial)) { return; } } // A min-heap is used to peel off each stream (thread) with the lowest serial // numbered event. do { const FEventDescStream& Stream = HeapCopy.HeapTop(); const FEventDesc* EventDesc = Stream.EventDescs; // If the next lowest serial number doesn't match where we got up to in // the previous stream we have found a gap. Celebration ensues. if (Serial != EventDesc->Serial) { if (!InCallback(Serial, EventDesc->Serial)) { return; } } // Consume consecutive events (including unsynchronized ones). Serial = EventDesc->Serial; do { do { ++EventDesc; } while (EventDesc->Serial == ESerial::Ignored); Serial = (Serial + 1) & ESerial::Mask; } while (EventDesc->Serial == Serial); // Update the heap if (EventDesc->Serial != ESerial::Terminal) { auto& Out = HeapCopy.Add_GetRef({Stream.ThreadId, Stream.TransportIndex}); Out.EventDescs = EventDesc; } HeapCopy.HeapPopDiscard(FSerialDistancePredicate{NextSerial}, EAllowShrinking::No); } while (!HeapCopy.IsEmpty()); } //////////////////////////////////////////////////////////////////////////////// void FProtocol5Stage::DetectSerialGaps(TArray& EventDescHeap) { // Events that should be synchronized across threads are assigned serial // numbers so they can be analyzed in the correct order. Gaps in the // serials can occur under two scenarios; 1) when packets are dropped from // the trace tail to make space for new trace events, and 2) when Trace's // worker thread ticks, samples all the trace buffers and sends their data. // In late-connect scenarios these gaps need to be skipped over in order to // successfully re-serialize events in the data stream. To further complicate // matters, most of the gaps from (2) will get filled by the following update, // leading to initial false positive gaps. By embedding sync points in the // stream we can reliably differentiate genuine gaps from temporary ones. // // Note that this could be done without sync points but it is an altogether // more complex solution. So unsightly embedded syncs it is... if (SyncCount == Transport.GetSyncCount()) { return; } SyncCount = Transport.GetSyncCount(); UE_TRACE_ANALYSIS_DEBUG_LOG("SyncCount: %d (%d previous serial gaps)", SyncCount, SerialGaps.Num()); if (SyncCount == 1) { // On the first update we will just collect gaps. auto GatherGap = [this] (int32 Lhs, int32 Rhs) { FEventDesc& Gap = SerialGaps.Emplace_GetRef(); Gap.Serial = Lhs; Gap.GapLength = (Rhs - Lhs) & ESerial::Mask; return true; }; ForEachSerialGap(EventDescHeap, GatherGap); } else { // On the second update we detect where gaps from the previous update // start getting filled in. Any gaps preceding that point are genuine. uint32 GapCount = 0; auto RecordGap = [this, &GapCount] (int32 Lhs, int32 Rhs) { if (SerialGaps.IsEmpty() || GapCount >= (uint32)SerialGaps.Num()) { return false; } const FEventDesc& SerialGap = SerialGaps[GapCount]; if (SerialGap.Serial == Lhs) { /* This is the expected case */ ++GapCount; return true; } if (SerialGap.Serial > Lhs) { /* We've started receiving new gaps that are exist because not all * data has been received yet. They're false positives. No need to process * any further */ return false; } // If we're here something's probably gone wrong UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Serial gaps detection failed (SerialGap.Serial=%d, Lhs=%d)!", SerialGap.Serial, Lhs); return false; }; ForEachSerialGap(EventDescHeap, RecordGap); UE_TRACE_ANALYSIS_DEBUG_LOG("Serial gaps: %d", GapCount); if (GapCount == 0) //-V547 { SerialGaps.Empty(); return; } #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 for (uint32 GapIndex = 0; GapIndex < GapCount; ++GapIndex) { const FEventDesc& SerialGap = SerialGaps[GapIndex]; UE_TRACE_ANALYSIS_DEBUG_LOG(" gap %u +%u", SerialGap.Serial, SerialGap.GapLength); } #endif // Turn the genuine gaps into a stream that DispatchEvents() can handle // and use to skip over them. if (GapCount == uint32(SerialGaps.Num())) { SerialGaps.Emplace(); } FEventDesc& Terminator = SerialGaps[GapCount]; Terminator.Serial = ESerial::Terminal; FEventDescStream Out = EventDescHeap[0]; Out.ThreadId = FEventDescStream::GapThreadId; Out.EventDescs = SerialGaps.GetData(); EventDescHeap.HeapPush(Out, FSerialDistancePredicate{NextSerial}); } } //////////////////////////////////////////////////////////////////////////////// void FProtocol5Stage::SetSizeIfKnownEvent(uint32 Uid, uint32& InOutEventSize) { switch (Uid) { case EKnownUids::EnterScope_T: case EKnownUids::LeaveScope_T: InOutEventSize = 7; break; }; } //////////////////////////////////////////////////////////////////////////////// bool FProtocol5Stage::DispatchKnownEvent(const FMachineContext& Context, uint32 Uid, const FEventDesc* Cursor) { // Maybe this is a "well-known" event that is handled a little different? switch (Uid) { case EKnownUids::EnterScope: #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogEnterScopeEvent(Uid, Cursor->EventSize + Cursor->AuxSize); #endif Context.Bridge.EnterScope(); return true; case EKnownUids::LeaveScope: #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogLeaveScopeEvent(Uid, Cursor->EventSize + Cursor->AuxSize); #endif Context.Bridge.LeaveScope(); return true; case EKnownUids::EnterScope_T: { uint64 RelativeTimestamp = *(uint64*)(Cursor->Data - 1) >> 8; #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogEnterScopeEvent(Uid, RelativeTimestamp, Cursor->EventSize + Cursor->AuxSize); #endif Context.Bridge.EnterScope(RelativeTimestamp); return true; } case EKnownUids::LeaveScope_T: { uint64 RelativeTimestamp = *(uint64*)(Cursor->Data - 1) >> 8; #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogLeaveScopeEvent(Uid, RelativeTimestamp, Cursor->EventSize + Cursor->AuxSize); #endif Context.Bridge.LeaveScope(RelativeTimestamp); return true; } case EKnownUids::AuxData: case EKnownUids::AuxDataTerminal: return true; default: return false; } } //////////////////////////////////////////////////////////////////////////////// int32 FProtocol5Stage::DispatchEvents( const FMachineContext& Context, const FEventDesc* EventDesc, uint32 Count) { using namespace Protocol5; FAuxDataCollector AuxCollector; #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 2 UE_TRACE_ANALYSIS_DEBUG_LOG("Dispatch run of %u consecutive events (Tid=%u)", Count, Context.Bridge.GetActiveThreadId()); #endif for (const FEventDesc* Cursor = EventDesc, *End = EventDesc + Count; Cursor < End; ++Cursor) { uint32 Uid = uint32(Cursor->Uid); if (DispatchKnownEvent(Context, Uid, Cursor)) { continue; } if (!TypeRegistry.IsUidValid(Uid)) { UE_TRACE_ANALYSIS_DEBUG_LOG("Warning: Unexpected event with UID %u (0x%X)", Uid, Uid); Context.EmitMessagef(EAnalysisMessageSeverity::Warning, TEXT("An unknown event UID (%u) was encountered."), Uid); #if UE_TRACE_ANALYSIS_DEBUG && UE_TRACE_ANALYSIS_DEBUG_LEVEL >= 3 UE_TRACE_ANALYSIS_DEBUG_BeginStringBuilder(); const uint8* StartCursor = Cursor->Data; for (uint32 i = 0; i < 32 && i < Cursor->EventSize; ++i) { UE_TRACE_ANALYSIS_DEBUG_Appendf("%02X ", StartCursor[i]); } UE_TRACE_ANALYSIS_DEBUG_EndStringBuilder(); UE_TRACE_ANALYSIS_DEBUG_ResetStringBuilder(); UE_TRACE_ANALYSIS_DEBUG_Append("[[["); for (uint32 i = 0; i < 128 && i < Cursor->EventSize; ++i) { UE_TRACE_ANALYSIS_DEBUG_AppendChar((char)StartCursor[i]); } UE_TRACE_ANALYSIS_DEBUG_Append("]]]"); UE_TRACE_ANALYSIS_DEBUG_EndStringBuilder(); #endif // UE_TRACE_ANALYSIS_DEBUG return -1; } // It is a normal event. const FTypeRegistry::FTypeInfo* TypeInfo = TypeRegistry.Get(Uid); FEventDataInfo EventDataInfo = { Cursor->Data, *TypeInfo, &AuxCollector, TypeInfo->EventSize, }; #if UE_TRACE_ANALYSIS_DEBUG uint32 FixedSize = Cursor->EventSize; uint32 AuxSize = Cursor->AuxSize; const FEventDesc* EventCursor = Cursor; #endif // Gather its auxiliary data blocks into a collector. if (Cursor->bHasAux) { while (true) { ++Cursor; if (Cursor->Uid != EKnownUids::AuxData) { --Cursor; // Read off too much. Put it back. break; } const auto* AuxHeader = ((FAuxHeader*)(Cursor->Data)) - 1; FAuxData AuxData = {}; AuxData.Data = AuxHeader->Data; AuxData.DataSize = (AuxHeader->Pack >> FAuxHeader::SizeShift); AuxData.FieldIndex = AuxHeader->FieldIndex_Size & FAuxHeader::FieldMask; // AuxData.FieldSizeAndType = ... - this is assigned on demand in GetData() AuxCollector.Add(AuxData); #if UE_TRACE_ANALYSIS_DEBUG AuxSize += Cursor->EventSize + Cursor->AuxSize; #endif } #if UE_TRACE_ANALYSIS_DEBUG AuxSize += 1; // for AuxDataTerminal #endif } #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogEvent(TypeInfo, FixedSize, AuxSize, EventCursor->Serial); #endif Context.Bridge.OnEvent(EventDataInfo); AuxCollector.Reset(); } return 0; } // {{{1 protocol-6 ------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FProtocol6Stage : public FProtocol5Stage { public: FProtocol6Stage(FTransport* InTransport); virtual void ExitStage(const FMachineContext& Context) override; }; //////////////////////////////////////////////////////////////////////////////// FProtocol6Stage::FProtocol6Stage(FTransport* InTransport) : FProtocol5Stage(InTransport) { EventVersion = 6; } //////////////////////////////////////////////////////////////////////////////// void FProtocol6Stage::ExitStage(const FMachineContext& Context) { // Ensure the transport does not have pending buffers (i.e. event data not yet processed). if (!Transport.IsEmpty()) { Context.EmitMessage(EAnalysisMessageSeverity::Warning, TEXT("Transport buffers are not empty at end of analysis (protocol 6)!")); } #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.GetSerial().Value = NextSerial; Transport.DebugEnd(); #endif } // {{{1 protocol-7 ------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FProtocol7Stage : public FProtocol6Stage { public: FProtocol7Stage(FTransport* InTransport); virtual void ExitStage(const FMachineContext& Context) override; virtual void SetSizeIfKnownEvent(uint32 Uid, uint32& InOutEventSize) override; virtual bool DispatchKnownEvent(const FMachineContext& Context, uint32 Uid, const FEventDesc* Cursor) override; protected: using EKnownUids = Protocol7::EKnownEventUids; }; //////////////////////////////////////////////////////////////////////////////// FProtocol7Stage::FProtocol7Stage(FTransport* InTransport) : FProtocol6Stage(InTransport) { EventVersion = 7; } //////////////////////////////////////////////////////////////////////////////// void FProtocol7Stage::ExitStage(const FMachineContext& Context) { // Ensure the transport does not have pending buffers (i.e. event data not yet processed). if (!Transport.IsEmpty()) { uint64 TotalRemainingDataSize = 0; for (int32 ThreadIndex = 0, ThreadCount = Transport.GetThreadCount(); ThreadIndex < ThreadCount; ++ThreadIndex) { TotalRemainingDataSize += Transport.GetThreadStream(ThreadIndex)->GetRemaining(); } Context.EmitMessagef( EAnalysisMessageSeverity::Warning, TEXT("Transport buffers are not empty at end of analysis (%llu bytes; protocol 7)!"), TotalRemainingDataSize); } #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.GetSerial().Value = NextSerial; Transport.DebugEnd(); #endif } //////////////////////////////////////////////////////////////////////////////// void FProtocol7Stage::SetSizeIfKnownEvent(uint32 Uid, uint32& InOutEventSize) { switch (Uid) { case EKnownUids::EnterScope_TA: case EKnownUids::LeaveScope_TA: InOutEventSize = 8; break; case EKnownUids::EnterScope_TB: case EKnownUids::LeaveScope_TB: InOutEventSize = 7; break; }; } //////////////////////////////////////////////////////////////////////////////// bool FProtocol7Stage::DispatchKnownEvent(const FMachineContext& Context, uint32 Uid, const FEventDesc* Cursor) { // Maybe this is a "well-known" event that is handled a little different? switch (Uid) { case EKnownUids::EnterScope: #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogEnterScopeEvent(Uid, Cursor->EventSize + Cursor->AuxSize); #endif Context.Bridge.EnterScope(); return true; case EKnownUids::LeaveScope: #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogLeaveScopeEvent(Uid, Cursor->EventSize + Cursor->AuxSize); #endif Context.Bridge.LeaveScope(); return true; case EKnownUids::EnterScope_TA: { uint64 AbsoluteTimestamp = *(uint64*)Cursor->Data; #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogEnterScopeAEvent(Uid, AbsoluteTimestamp, Cursor->EventSize + Cursor->AuxSize); #endif Context.Bridge.EnterScopeA(AbsoluteTimestamp); return true; } case EKnownUids::LeaveScope_TA: { uint64 AbsoluteTimestamp = *(uint64*)Cursor->Data; #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogLeaveScopeAEvent(Uid, AbsoluteTimestamp, Cursor->EventSize + Cursor->AuxSize); #endif Context.Bridge.LeaveScopeA(AbsoluteTimestamp); return true; } case EKnownUids::EnterScope_TB: { uint64 BaseRelativeTimestamp = *(uint64*)(Cursor->Data - 1) >> 8; #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogEnterScopeBEvent(Uid, BaseRelativeTimestamp, Cursor->EventSize + Cursor->AuxSize); #endif Context.Bridge.EnterScopeB(BaseRelativeTimestamp); return true; } case EKnownUids::LeaveScope_TB: { uint64 BaseRelativeTimestamp = *(uint64*)(Cursor->Data - 1) >> 8; #if UE_TRACE_ANALYSIS_DEBUG Context.Bridge.DebugLogLeaveScopeBEvent(Uid, BaseRelativeTimestamp, Cursor->EventSize + Cursor->AuxSize); #endif Context.Bridge.LeaveScopeB(BaseRelativeTimestamp); return true; } case EKnownUids::AuxData: case EKnownUids::AuxDataTerminal: return true; default: return false; } } // {{{1 est.-transport --------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FEstablishTransportStage : public FAnalysisMachine::FStage { public: virtual EStatus OnData(FStreamReader& Reader, const FMachineContext& Context) override; }; //////////////////////////////////////////////////////////////////////////////// FEstablishTransportStage::EStatus FEstablishTransportStage::OnData( FStreamReader& Reader, const FMachineContext& Context) { using namespace UE::Trace; const struct { uint8 TransportVersion; uint8 ProtocolVersion; }* Header = decltype(Header)(Reader.GetPointer(sizeof(*Header))); if (Header == nullptr) { return EStatus::NotEnoughData; } uint32 TransportVersion = Header->TransportVersion; UE_TRACE_ANALYSIS_DEBUG_LOG("TransportVersion: %u", TransportVersion); uint32 ProtocolVersion = Header->ProtocolVersion; UE_TRACE_ANALYSIS_DEBUG_LOG("ProtocolVersion: %u", ProtocolVersion); FTransport* Transport = nullptr; switch (TransportVersion) { case ETransport::Raw: Transport = new FTransport(); break; case ETransport::Packet: Transport = new FPacketTransport(); break; case ETransport::TidPacket: Transport = new FTidPacketTransport(); break; case ETransport::TidPacketSync: Transport = new FTidPacketTransportSync(); break; default: { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Invalid transport version %u", TransportVersion); Context.EmitMessagef( EAnalysisMessageSeverity::Error, TEXT("Unknown transport version: %u. You may need to recompile this application"), TransportVersion ); return EStatus::Error; } } #if UE_TRACE_ANALYSIS_DEBUG Transport->DebugBegin(); #endif switch (ProtocolVersion) { case Protocol0::EProtocol::Id: Context.Machine.QueueStage(Transport); Context.Machine.Transition(); break; case Protocol1::EProtocol::Id: case Protocol2::EProtocol::Id: case Protocol3::EProtocol::Id: Context.Machine.QueueStage(ProtocolVersion, Transport); Context.Machine.Transition(); break; case Protocol4::EProtocol::Id: Context.Machine.QueueStage(ProtocolVersion, Transport); Context.Machine.Transition(); break; case Protocol5::EProtocol::Id: Context.Machine.QueueStage(Transport); Context.Machine.Transition(); break; case Protocol6::EProtocol::Id: Context.Machine.QueueStage(Transport); Context.Machine.Transition(); break; case Protocol7::EProtocol::Id: Context.Machine.QueueStage(Transport); Context.Machine.Transition(); break; default: { UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Invalid protocol version %u", ProtocolVersion); Context.EmitMessagef( EAnalysisMessageSeverity::Error, TEXT("Unknown protocol version: %u. You may need to recompile this application"), ProtocolVersion ); return EStatus::Error; } } UE_TRACE_ANALYSIS_DEBUG_LOG(""); Reader.Advance(sizeof(*Header)); #if UE_TRACE_ANALYSIS_DEBUG_API Context.Bridge.OnVersion(TransportVersion, ProtocolVersion); #endif // UE_TRACE_ANALYSIS_DEBUG_API return EStatus::Continue; } // {{{1 metadata --------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FMetadataStage : public FAnalysisMachine::FStage { public: virtual EStatus OnData(FStreamReader& Reader, const FMachineContext& Context) override; }; //////////////////////////////////////////////////////////////////////////////// FMetadataStage::EStatus FMetadataStage::OnData( FStreamReader& Reader, const FMachineContext& Context) { const auto* MetadataSize = Reader.GetPointer(); if (MetadataSize == nullptr) { return EStatus::NotEnoughData; } const uint8* Metadata = Reader.GetPointer(sizeof(*MetadataSize) + *MetadataSize); if (Metadata == nullptr) { return EStatus::NotEnoughData; } #if UE_TRACE_ANALYSIS_DEBUG UE_TRACE_ANALYSIS_DEBUG_BeginStringBuilder(); UE_TRACE_ANALYSIS_DEBUG_Appendf("Metadata: %u + %u bytes (", uint32(sizeof(*MetadataSize)), uint32(*MetadataSize)); const uint32 PrintByteCount = FMath::Min(32u, uint32(*MetadataSize)); Metadata += sizeof(*MetadataSize); for (uint32 Index = 0; Index < PrintByteCount; ++Index, ++Metadata) { if (Index != 0) { UE_TRACE_ANALYSIS_DEBUG_AppendChar(' '); } UE_TRACE_ANALYSIS_DEBUG_Appendf("%02X", uint32(*Metadata)); } if (PrintByteCount != uint32(*MetadataSize)) { UE_TRACE_ANALYSIS_DEBUG_Append("..."); } UE_TRACE_ANALYSIS_DEBUG_AppendChar(')'); UE_TRACE_ANALYSIS_DEBUG_EndStringBuilder(); #endif // UE_TRACE_ANALYSIS_DEBUG Reader.Advance(sizeof(*MetadataSize) + *MetadataSize); Context.Machine.QueueStage(); Context.Machine.Transition(); return EStatus::Continue; } // {{{1 magic ------------------------------------------------------------------ //////////////////////////////////////////////////////////////////////////////// class FMagicStage : public FAnalysisMachine::FStage { public: virtual EStatus OnData(FStreamReader& Reader, const FMachineContext& Context) override; }; //////////////////////////////////////////////////////////////////////////////// FMagicStage::EStatus FMagicStage::OnData( FStreamReader& Reader, const FMachineContext& Context) { const auto* MagicPtr = Reader.GetPointer(); if (MagicPtr == nullptr) { return EStatus::NotEnoughData; } uint32 Magic = *MagicPtr; if (Magic == 'ECRT' || Magic == '2CRT') { // Source is big-endian which we don't currently support UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Invalid magic header (big-endian not supported)"); Context.EmitMessage(EAnalysisMessageSeverity::Error, TEXT("Big endian traces are currently not supported.")); return EStatus::Error; } if (Magic == 'TRCE') { Reader.Advance(sizeof(*MagicPtr)); Context.Machine.QueueStage(); Context.Machine.Transition(); return EStatus::Continue; } if (Magic == 'TRC2') { Reader.Advance(sizeof(*MagicPtr)); Context.Machine.QueueStage(); Context.Machine.Transition(); return EStatus::Continue; } // There was no header on early traces so they went straight into declaring // protocol and transport versions. if (Magic == 0x00'00'00'01) // protocol 0, transport 1 { Context.Machine.QueueStage(); Context.Machine.Transition(); return EStatus::Continue; } UE_TRACE_ANALYSIS_DEBUG_LOG("Error: Invalid magic header"); Context.EmitMessage(EAnalysisMessageSeverity::Error, TEXT("The file or stream was not recognized as trace stream.")); return EStatus::Error; } // {{{1 engine ----------------------------------------------------------------- //////////////////////////////////////////////////////////////////////////////// class FAnalysisEngine::FImpl { public: FImpl(TArray&& Analyzers, FMessageDelegate&& InMessage); void Begin(); void End(); bool OnData(FStreamReader& Reader); FAnalysisBridge Bridge; FAnalysisMachine Machine; }; //////////////////////////////////////////////////////////////////////////////// FAnalysisEngine::FImpl::FImpl(TArray&& Analyzers, FMessageDelegate&& InMessage) : Bridge(Forward>(Analyzers)) , Machine(Bridge, Forward(InMessage)) { } //////////////////////////////////////////////////////////////////////////////// void FAnalysisEngine::FImpl::Begin() { UE_TRACE_ANALYSIS_DEBUG_LOG("FAnalysisEngine::Begin()"); Machine.QueueStage(); Machine.Transition(); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisEngine::FImpl::End() { Machine.Transition(); #if UE_TRACE_ANALYSIS_DEBUG FAnalysisState& State = Bridge.GetState(); UE_TRACE_ANALYSIS_DEBUG_LOG(""); UE_TRACE_ANALYSIS_DEBUG_LOG("SerialWrappedCount: %d", State.SerialWrappedCount); UE_TRACE_ANALYSIS_DEBUG_LOG("Serial.Value: %u (0x%X)", State.Serial.Value, State.Serial.Value); UE_TRACE_ANALYSIS_DEBUG_LOG("MaxEventDescs: %d", State.MaxEventDescs); UE_TRACE_ANALYSIS_DEBUG_LOG("SkippedSerialGaps: %d", State.NumSkippedSerialGaps); UE_TRACE_ANALYSIS_DEBUG_LOG("SkippedSerials: %llu", State.NumSkippedSerials); uint32 Digits = 0; uint64 Value = State.TotalEventSize; do { Value /= 10; ++Digits; } while (Value != 0); uint64 ScopeEventCount = State.EnterScopeEventCount + State.LeaveScopeEventCount; uint64 ScopeTEventCount = State.EnterScopeTEventCount + State.LeaveScopeTEventCount; const int32 NC = Digits; UE_TRACE_ANALYSIS_DEBUG_LOG(""); UE_TRACE_ANALYSIS_DEBUG_LOG("TotalEventCount:%*llu events", NC, State.TotalEventCount); if (State.TotalEventCount > 0) { UE_TRACE_ANALYSIS_DEBUG_LOG(" NewEvent:%*llu events (%.1f%%)", NC, State.NewEventCount, (double)State.NewEventCount / (double)State.TotalEventCount * 100.0); UE_TRACE_ANALYSIS_DEBUG_LOG(" Sync:%*llu events (%.1f%%)", NC, State.SyncEventCount, (double)State.SyncEventCount / (double)State.TotalEventCount * 100.0); UE_TRACE_ANALYSIS_DEBUG_LOG("ImportantNoSync:%*llu events (%.1f%%)", NC, State.ImportantNoSyncEventCount, (double)State.ImportantNoSyncEventCount / (double)State.TotalEventCount * 100.0); UE_TRACE_ANALYSIS_DEBUG_LOG(" OtherNoSync:%*llu events (%.1f%%)", NC, State.OtherNoSyncEventCount, (double)State.OtherNoSyncEventCount / (double)State.TotalEventCount * 100.0); UE_TRACE_ANALYSIS_DEBUG_LOG(" Scope:%*llu events (%.1f%%) = %llu enter + %llu leave", NC, ScopeEventCount, (double)ScopeEventCount / (double)State.TotalEventCount * 100.0, State.EnterScopeEventCount, State.LeaveScopeEventCount); UE_TRACE_ANALYSIS_DEBUG_LOG(" Scope_T:%*llu events (%.1f%%) = %llu enter + %llu leave", NC, ScopeTEventCount, (double)ScopeTEventCount / (double)State.TotalEventCount * 100.0, State.EnterScopeTEventCount, State.LeaveScopeTEventCount); const int64 CountError = State.TotalEventCount - State.NewEventCount - State.SyncEventCount - State.ImportantNoSyncEventCount - State.OtherNoSyncEventCount - ScopeEventCount - ScopeTEventCount; if (CountError != 0) { UE_TRACE_ANALYSIS_DEBUG_LOG(" error: %lld !!!", CountError); } uint64 DispatchedEventCount = State.TotalEventCount - State.NewEventCount - State.EnterScopeEventCount - State.EnterScopeTEventCount; uint64 NormalEventCount = State.SyncEventCount + State.ImportantNoSyncEventCount + State.OtherNoSyncEventCount - State.EnterScopeEventCount - State.EnterScopeTEventCount; check(DispatchedEventCount == NormalEventCount + ScopeEventCount + ScopeTEventCount); UE_TRACE_ANALYSIS_DEBUG_LOG(" Dispatched:%*llu events = %llu normal + %llu scoped", NC, DispatchedEventCount, NormalEventCount, ScopeEventCount + ScopeTEventCount); UE_TRACE_ANALYSIS_DEBUG_LOG("(normal dispatched events = sync events + no sync events - scope enter events)"); UE_TRACE_ANALYSIS_DEBUG_LOG(""); } uint64 ScopeEventSize = State.EnterScopeEventSize + State.LeaveScopeEventSize; uint64 ScopeTEventSize = State.EnterScopeTEventSize + State.LeaveScopeTEventSize; const int32 NS = Digits + 1; UE_TRACE_ANALYSIS_DEBUG_LOG(" TotalEventSize:%*llu bytes (%.1f MiB)", NS, State.TotalEventSize, (double)State.TotalEventSize / (1024.0 * 1024.0)); if (State.TotalEventSize > 0) { UE_TRACE_ANALYSIS_DEBUG_LOG(" NewEvent:%*llu bytes (%.1f%%)", NS, State.NewEventSize, (double)State.NewEventSize / (double)State.TotalEventSize * 100.0); UE_TRACE_ANALYSIS_DEBUG_LOG(" Sync:%*llu bytes (%.1f%%)", NS, State.SyncEventSize, (double)State.SyncEventSize / (double)State.TotalEventSize * 100.0); UE_TRACE_ANALYSIS_DEBUG_LOG("ImportantNoSync:%*llu bytes (%.1f%%)", NS, State.ImportantNoSyncEventSize, (double)State.ImportantNoSyncEventSize / (double)State.TotalEventSize * 100.0); UE_TRACE_ANALYSIS_DEBUG_LOG(" OtherNoSync:%*llu bytes (%.1f%%)", NS, State.OtherNoSyncEventSize, (double)State.OtherNoSyncEventSize / (double)State.TotalEventSize * 100.0); UE_TRACE_ANALYSIS_DEBUG_LOG(" Scope:%*llu bytes (%.1f%%) = %llu enter + %llu leave", NS, ScopeEventSize, (double)ScopeEventSize / (double)State.TotalEventSize * 100.0, State.EnterScopeEventSize, State.LeaveScopeEventSize); UE_TRACE_ANALYSIS_DEBUG_LOG(" Scope_T:%*llu bytes (%.1f%%) = %llu enter + %llu leave", NS, ScopeTEventSize, (double)ScopeTEventSize / (double)State.TotalEventSize * 100.0, State.EnterScopeTEventSize, State.LeaveScopeTEventSize); const int64 SizeError = State.TotalEventSize - State.NewEventSize - State.SyncEventSize - State.ImportantNoSyncEventSize - State.OtherNoSyncEventSize - ScopeEventSize - ScopeTEventSize; if (SizeError != 0) { UE_TRACE_ANALYSIS_DEBUG_LOG(" error: %lld !!!", SizeError); } UE_TRACE_ANALYSIS_DEBUG_LOG(" Dispatched:%*llu bytes (Total - NewEvent)", NS, State.TotalEventSize - State.NewEventSize); } #endif // UE_TRACE_ANALYSIS_DEBUG Bridge.Reset(); UE_TRACE_ANALYSIS_DEBUG_LOG(""); UE_TRACE_ANALYSIS_DEBUG_LOG("FAnalysisEngine::End()"); } //////////////////////////////////////////////////////////////////////////////// bool FAnalysisEngine::FImpl::OnData(FStreamReader& Reader) { bool bRet = (Machine.OnData(Reader) != FAnalysisMachine::EStatus::Error); bRet &= Bridge.IsStillAnalyzing(); return bRet; } //////////////////////////////////////////////////////////////////////////////// FAnalysisEngine::FAnalysisEngine(TArray&& Analyzers, FMessageDelegate&& InMessage) : Impl(new FImpl(Forward>(Analyzers), Forward(InMessage))) { } //////////////////////////////////////////////////////////////////////////////// FAnalysisEngine::~FAnalysisEngine() { delete Impl; } //////////////////////////////////////////////////////////////////////////////// void FAnalysisEngine::Begin() { Impl->Begin(); } //////////////////////////////////////////////////////////////////////////////// void FAnalysisEngine::End() { Impl->End(); } //////////////////////////////////////////////////////////////////////////////// bool FAnalysisEngine::OnData(FStreamReader& Reader) { return Impl->OnData(Reader); } // }}} } // namespace Trace } // namespace UE #undef LOCTEXT_NAMESPACE /* vim: set foldlevel=1 : */