ET debugger v2 (#3143)

CHANGELOG.md

@@ -10,11 +10,17 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ## [`x.y.z`] - Unreleased
 
 ## [`0.13.1`] - 2021-05-21
+### Breaking changes:
+- Event tracing has been optimised to reduce overhead when tracing events in general and in particular when events are not sampled. The tracing API has been modified to accomidate these improvements. You will have to modify your project if you use the API.
+
 ### Features:
 - Added `SpatialExecServerCmd` console command with one command `StartInsights` to dynamically enable insights capturing.
   - Format: SpatialExecServerCmd < server > < command > < args >
   - Example usage: "SpatialExecServerCmd local StartInsights -trace=CustomChannel -tracefile=MyNewTrace"
 - Visual Logger now supports multi-worker environments.
+- The Unreal GDK has been updated to run against SpatialOS 15.1.0, older version of SpatialOS will no longer work with the Unreal GDK.
+- Event tracing rotating log support (via `bEnableEventTracingRotatingLogs`, `EventTracingRotatingLogsMaxFileSizeBytes` and `EventTracingRotatingLogsMaxFileCount`). 
+- Event tracing filter support (configured via `UEventTracingSamplingSettings`).
 
 ## [`0.13.0`] - 2021-05-17
 ### Breaking changes:

SetupIncTraceLibs.bat

@@ -18,8 +18,8 @@ call :MarkStartOfBlock "Create folders"
 call :MarkEndOfBlock "Create folders"
 
 call :MarkStartOfBlock "Retrieve dependencies"	
-	spatial package retrieve internal        trace-dynamic-x86_64-vc141_md-win32        %PINNED_CORE_SDK_VERSION% 	"%CORE_SDK_DIR%\trace_lib\trace-win32.zip"
-	spatial package retrieve internal        trace-dynamic-x86_64-clang1000-linux       %PINNED_CORE_SDK_VERSION% 	"%CORE_SDK_DIR%\trace_lib\trace-linux.zip"
+	spatial package retrieve internal        trace-dynamic-x86_64-vc141_md-win32        15.0.1        "%CORE_SDK_DIR%\trace_lib\trace-win32.zip"
+	spatial package retrieve internal        trace-dynamic-x86_64-clang1000-linux       15.0.1        "%CORE_SDK_DIR%\trace_lib\trace-linux.zip"
 call :MarkEndOfBlock "Retrieve dependencies"
 
 REM There is a race condition between retrieve and unzip, add version call to stall briefly

SpatialGDK/Extras/core-sdk.version

@@ -1,2 +1,2 @@
-15.0.1
+15.1.0
 // If changing version, update SpatialGDK/Source/SpatialGDK/Public/Utils/WorkerVersionCheck.h too

SpatialGDK/Source/SpatialGDK/Private/Interop/ActorSystem.cpp

@@ -573,7 +573,7 @@ void ActorSystem::ComponentUpdated(const Worker_EntityId EntityId, const Worker_
 		EventTracer->TraceEvent(COMPONENT_UPDATE_EVENT_NAME, "", Causes, CauseSpanIds.Num(),
 								[Object, TargetObject, EntityId, ComponentId](FSpatialTraceEventDataBuilder& EventBuilder) {
 									EventBuilder.AddObject(Object);
-									EventBuilder.AddObject(TargetObject, "TargetObject");
+									EventBuilder.AddObject(TargetObject, "target_object");
 									EventBuilder.AddEntityId(EntityId);
 									EventBuilder.AddComponentId(ComponentId);
 								});
@@ -1838,7 +1838,7 @@ void ActorSystem::SendComponentUpdates(UObject* Object, const FClassInfo& Info,
 											GDK_PROPERTY(Property)* Property = *Itr;
 											EventBuilder.AddObject(Object);
 											EventBuilder.AddEntityId(EntityId);
-											EventBuilder.AddKeyValue("PropertyName", Property->GetName());
+											EventBuilder.AddKeyValue("property_name", Property->GetName());
 											EventBuilder.AddLinearTraceId(EventTraceUniqueId::GenerateForProperty(EntityId, Property));
 										});
 

SpatialGDK/Source/SpatialGDK/Private/Interop/Connection/SpatialEventTracer.cpp

@@ -2,8 +2,6 @@
 
 #include "Interop/Connection/SpatialEventTracer.h"
 
-#include <string>
-
 #include "HAL/PlatformFile.h"
 #include "HAL/PlatformFilemanager.h"
 #include "SpatialGDKSettings.h"
@@ -12,6 +10,25 @@ DEFINE_LOG_CATEGORY(LogSpatialEventTracer);
 
 namespace SpatialGDK
 {
+TraceQueryPtr ParseOrDefault(const FString& Str, const TCHAR* FilterForLog)
+{
+	TraceQueryPtr Ptr;
+	if (Str.Len() > 0)
+	{
+		Ptr.Reset(Trace_ParseSimpleQuery(TCHAR_TO_ANSI(*Str)));
+		UE_LOG(LogSpatialEventTracer, Log, TEXT("Applied %s query: %s"), FilterForLog, *Str);
+	}
+
+	if (!Ptr.IsValid())
+	{
+		UE_LOG(LogSpatialEventTracer, Warning, TEXT("The specified query \"%s\" is invalid; defaulting to \"false\" query. %s"),
+			   FilterForLog, Trace_GetLastError());
+		Ptr.Reset(Trace_ParseSimpleQuery("false"));
+	}
+
+	return Ptr;
+}
+
 void SpatialEventTracer::TraceCallback(void* UserData, const Trace_Item* Item)
 {
 	SpatialEventTracer* EventTracer = static_cast<SpatialEventTracer*>(UserData);
@@ -23,27 +40,34 @@ void SpatialEventTracer::TraceCallback(void* UserData, const Trace_Item* Item)
 	}
 
 	uint32_t ItemSize = Trace_GetSerializedItemSize(Item);
-	if (EventTracer->BytesWrittenToStream + ItemSize <= EventTracer->MaxFileSize)
+	// Depends whether we are using rotating logs or single-log mode (where we track max size).
+	const bool bTrackFileSize = EventTracer->MaxFileSize != 0;
+	if (!bTrackFileSize || (EventTracer->BytesWrittenToStream + ItemSize <= EventTracer->MaxFileSize))
 	{
-		EventTracer->BytesWrittenToStream += ItemSize;
+		if (bTrackFileSize) 
+		{
+			EventTracer->BytesWrittenToStream += ItemSize;
+		}
+
 		int Code = Trace_SerializeItemToStream(Stream, Item, ItemSize);
-		if (Code != 1)
+		if (Code == WORKER_RESULT_FAILURE)
 		{
-			UE_LOG(LogSpatialEventTracer, Error, TEXT("Failed to serialize to with error code %d (%s)"), Code, Trace_GetLastError());
+			UE_LOG(LogSpatialEventTracer, Error, TEXT("Failed to serialize to with error code %d (%s)"), Code,
+				   ANSI_TO_TCHAR(Trace_GetLastError()));
 		}
 
 		if (FPlatformAtomics::AtomicRead_Relaxed(&EventTracer->FlushOnWriteAtomic))
 		{
-			int64_t Flushresult = Io_Stream_Flush(Stream);
-			if (Flushresult == -1)
+			if (Io_Stream_Flush(Stream) == -1)
 			{
 				UE_LOG(LogSpatialEventTracer, Error, TEXT("Failed to flush stream with error code %d (%s)"), Code,
-					   Io_Stream_GetLastError(Stream));
+					   ANSI_TO_TCHAR(Io_Stream_GetLastError(Stream)));
 			}
 		}
 	}
 	else
 	{
+		// Went over max capacity so stop writing here.
 		EventTracer->BytesWrittenToStream = EventTracer->MaxFileSize;
 	}
 }
@@ -72,39 +96,50 @@ SpatialScopedActiveSpanId::~SpatialScopedActiveSpanId()
 SpatialEventTracer::SpatialEventTracer(const FString& WorkerId)
 {
 	const USpatialGDKSettings* Settings = GetDefault<USpatialGDKSettings>();
-	MaxFileSize = Settings->MaxEventTracingFileSizeBytes;
+	MaxFileSize = Settings->bEnableEventTracingRotatingLogs ? 0 : Settings->EventTracingSingleLogMaxFileSizeBytes; // 0 indicates unbounded.
 
-	Trace_EventTracer_Parameters parameters = {};
-	parameters.user_data = this;
-	parameters.callback = &SpatialEventTracer::TraceCallback;
-	EventTracer = Trace_EventTracer_Create(&parameters);
+	Trace_EventTracer_Parameters Parameters = {};
+	Parameters.user_data = this;
+	Parameters.callback = &SpatialEventTracer::TraceCallback;
+	Parameters.enabled = true;
 
-	Trace_SamplingParameters SamplingParameters = {};
-	SamplingParameters.sampling_mode = Trace_SamplingMode::TRACE_SAMPLING_MODE_PROBABILISTIC;
+	UE_LOG(LogSpatialEventTracer, Log, TEXT("Spatial event tracing enabled."));
 
 	UEventTracingSamplingSettings* SamplingSettings = Settings->GetEventTracingSamplingSettings();
 
-	UE_LOG(LogSpatialEventTracer, Log, TEXT("Setting event tracing sampling probability. Probability: %f."),
+	TArray<Trace_SpanSamplingProbability> SpanSamplingProbabilities;
+	// Storage for strings passed to the worker SDK Worker requires ansi const char*
+	FSpatialTraceEventDataBuilder::FStringCache AnsiStrings;
+
+	Parameters.span_sampling_parameters.sampling_mode = Trace_SamplingMode::TRACE_SAMPLING_MODE_PROBABILISTIC;
+
+	UE_LOG(LogSpatialEventTracer, Log, TEXT("Setting event tracing span sampling probabalistic. Probability: %f."),
 		   SamplingSettings->SamplingProbability);
 
-	TArray<Trace_SpanSamplingProbability> SpanSamplingProbabilities;
-	TArray<std::string> AnsiStrings; // Worker requires ansi const char*
+	SpanSamplingProbabilities.Reserve(SamplingSettings->EventSamplingModeOverrides.Num());
 	for (const auto& Pair : SamplingSettings->EventSamplingModeOverrides)
 	{
 		const FString& EventName = Pair.Key.ToString();
 		UE_LOG(LogSpatialEventTracer, Log, TEXT("Adding trace event sampling override. Event: %s Probability: %f."), *EventName,
 			   Pair.Value);
-		int32 Index = AnsiStrings.Add(TCHAR_TO_ANSI(*EventName));
-		SpanSamplingProbabilities.Add({ AnsiStrings[Index].c_str(), Pair.Value });
+		SpanSamplingProbabilities.Add({ AnsiStrings.Get(AnsiStrings.AddFString(EventName)), Pair.Value });
 	}
 
-	SamplingParameters.probabilistic_parameters.default_probability = SamplingSettings->SamplingProbability;
-	SamplingParameters.probabilistic_parameters.probability_count = SpanSamplingProbabilities.Num();
-	SamplingParameters.probabilistic_parameters.probabilities = SpanSamplingProbabilities.GetData();
+	Parameters.span_sampling_parameters.probabilistic_parameters.default_probability = SamplingSettings->SamplingProbability;
+	Parameters.span_sampling_parameters.probabilistic_parameters.probability_count = SpanSamplingProbabilities.Num();
+	Parameters.span_sampling_parameters.probabilistic_parameters.probabilities = SpanSamplingProbabilities.GetData();
 
-	Trace_EventTracer_SetSampler(EventTracer, &SamplingParameters);
+	// Filters
+	TraceQueryPtr PreFilter = ParseOrDefault(SamplingSettings->GDKEventPreFilter, TEXT("pre-filter"));
+	TraceQueryPtr PostFilter = ParseOrDefault(SamplingSettings->GDKEventPostFilter, TEXT("post-filter"));
 
-	UE_LOG(LogSpatialEventTracer, Log, TEXT("Spatial event tracing enabled."));
+	checkf(PreFilter.Get() != nullptr, TEXT("Pre-filter is invalid."));
+	checkf(PostFilter.Get() != nullptr, TEXT("Post-filter is invalid."));
+
+	Parameters.filter_parameters.event_pre_filter_parameters.simple_query = PreFilter.Get();
+	Parameters.filter_parameters.event_post_filter_parameters.simple_query = PostFilter.Get();
+
+	EventTracer = Trace_EventTracer_Create(&Parameters);
 
 	// Open a local file
 	FString EventTracePath = FPaths::Combine(FPaths::ProjectSavedDir(), TEXT("EventTracing"));
@@ -115,14 +150,38 @@ SpatialEventTracer::SpatialEventTracer(const FString& WorkerId)
 	}
 
 	FolderPath = EventTracePath;
-	const FString FullFileName = FString::Printf(TEXT("EventTrace_%s_%s.trace"), *WorkerId, *FDateTime::Now().ToString());
-	const FString FilePath = FPaths::Combine(FolderPath, FullFileName);
+	const FString FolderWorkerPath = FPaths::Combine(EventTracePath, WorkerId);
 
 	IPlatformFile& PlatformFile = FPlatformFileManager::Get().GetPlatformFile();
-	if (PlatformFile.CreateDirectoryTree(*FolderPath))
+	const FString FileName = TEXT("gdk");
+	const FString FileExt = TEXT(".etlog");
+	if (PlatformFile.CreateDirectoryTree(*FolderWorkerPath))
+	{
+		UE_LOG(LogSpatialEventTracer, Log, TEXT("Capturing trace file%s to %s."),
+			   (Settings->bEnableEventTracingRotatingLogs) ? TEXT("s") : TEXT(""), *FolderWorkerPath);
+
+		if (Settings->bEnableEventTracingRotatingLogs)
+		{
+			FString FullFilePathPrefix = FString::Printf(TEXT("%s-"), *FPaths::Combine(FolderWorkerPath, FileName));
+			const FString FullFilePathSuffix = FileExt;
+
+			Io_RotatingFileStreamParameters FileParamters;
+			FileParamters.filename_prefix = AnsiStrings.Get(AnsiStrings.AddFString(FullFilePathPrefix));
+			FileParamters.filename_suffix = AnsiStrings.Get(AnsiStrings.AddFString(FullFilePathSuffix));
+			FileParamters.max_file_size_bytes = Settings->EventTracingRotatingLogsMaxFileSizeBytes;
+			FileParamters.max_file_count = Settings->EventTracingRotatingLogsMaxFileCount;
+			Stream.Reset(Io_CreateRotatingFileStream(&FileParamters));
+		}
+		else
+		{
+			const FString FullFilename = FString::Printf(TEXT("%s%s"), *FileName, *FileExt);
+			const FString FullFilePath = FPaths::Combine(FolderWorkerPath, FullFilename);
+			Stream.Reset(Io_CreateFileStream(TCHAR_TO_ANSI(*FullFilePath), Io_OpenMode::IO_OPEN_MODE_WRITE));
+		}
+	}
+	else
 	{
-		UE_LOG(LogSpatialEventTracer, Log, TEXT("Capturing trace to %s."), *FilePath);
-		Stream.Reset(Io_CreateFileStream(TCHAR_TO_ANSI(*FilePath), Io_OpenMode::IO_OPEN_MODE_WRITE));
+		UE_LOG(LogSpatialEventTracer, Error, TEXT("Error creating directory tree to %s"), *FolderWorkerPath);
 	}
 }
 
@@ -152,11 +211,6 @@ FSpatialGDKSpanId SpatialEventTracer::UserSpanIdToGDKSpanId(const FUserSpanId& U
 	return TraceSpanId;
 }
 
-void SpatialEventTracer::StreamDeleter::operator()(Io_Stream* StreamToDestroy) const
-{
-	Io_Stream_Destroy(StreamToDestroy);
-}
-
 void SpatialEventTracer::BeginOpsForFrame()
 {
 	for (auto& ConsumedKey : EntityComponentsConsumed)

SpatialGDK/Source/SpatialGDK/Private/Interop/Connection/SpatialEventTracerUserInterface.cpp

@@ -5,7 +5,6 @@
 #include "Engine/Engine.h"
 #include "EngineClasses/SpatialNetDriver.h"
 #include "EngineClasses/SpatialPackageMapClient.h"
-
 #include "Interop/Connection/SpatialWorkerConnection.h"
 #include "Interop/SpatialClassInfoManager.h"
 

SpatialGDK/Source/SpatialGDK/Private/Interop/Connection/SpatialTraceEventDataBuilder.cpp

@@ -86,76 +86,76 @@ FSpatialTraceEventDataBuilder::~FSpatialTraceEventDataBuilder()
 	Trace_EventData_Destroy(EventData);
 }
 
-void FSpatialTraceEventDataBuilder::AddObject(const UObject* Object, const char* Key /*="Object"*/)
+void FSpatialTraceEventDataBuilder::AddObject(const UObject* Object, const char* Key /*="object"*/)
 {
 	if (Object != nullptr)
 	{
 		if (const AActor* Actor = Cast<AActor>(Object))
 		{
 			FString PositionString = Actor->GetTransform().GetTranslation().ToString();
-			AddKeyValue(StringConverter.CombineStrings(Key, "ActorPosition"), StringConverter.AddFString(PositionString));
+			AddKeyValue(StringConverter.CombineStrings(Key, "actor_position"), StringConverter.AddFString(PositionString));
 		}
 		if (UWorld* World = Object->GetWorld())
 		{
 			if (USpatialNetDriver* NetDriver = Cast<USpatialNetDriver>(World->GetNetDriver()))
 			{
-				FString NetGuidString = NetDriver->PackageMap->GetNetGUIDFromObject(Object).ToString();
-				AddKeyValue(StringConverter.CombineStrings(Key, "NetGuid"), StringConverter.AddFString(NetGuidString));
+				AddKeyValue(StringConverter.CombineStrings(Key, "entity_id"),
+							StringConverter.AddInt64((NetDriver->PackageMap->GetEntityIdFromObject(Object))));
 			}
 		}
 		AddKeyValue(Key, Object->GetName());
 	}
 }
 
-void FSpatialTraceEventDataBuilder::AddFunction(const UFunction* Function, const char* Key /*="Function"*/)
+void FSpatialTraceEventDataBuilder::AddFunction(const UFunction* Function, const char* Key /*="function"*/)
 {
 	if (Function != nullptr)
 	{
 		AddKeyValue(Key, Function->GetName());
 	}
 }
 
-void FSpatialTraceEventDataBuilder::AddEntityId(const Worker_EntityId EntityId, const char* Key /*="EntityId"*/)
+void FSpatialTraceEventDataBuilder::AddEntityId(const Worker_EntityId EntityId, const char* Key /*="entiy_id"*/)
 {
 	AddKeyValue(Key, static_cast<int64>(EntityId));
 }
 
-void FSpatialTraceEventDataBuilder::AddComponentId(const Worker_ComponentId ComponentId, const char* Key /*="ComponentId"*/)
+void FSpatialTraceEventDataBuilder::AddComponentId(const Worker_ComponentId ComponentId, const char* Key /*="component_id"*/)
 {
 	AddKeyValue(Key, static_cast<uint32>(ComponentId));
 }
 
-void FSpatialTraceEventDataBuilder::AddComponentSetId(const Worker_ComponentSetId ComponentSetId, const char* Key /*="ComponentSetId"*/)
+void FSpatialTraceEventDataBuilder::AddComponentSetId(const Worker_ComponentSetId ComponentSetId, const char* Key /*="component_set_id"*/)
 {
 	AddKeyValue(Key, static_cast<uint32>(ComponentSetId));
 }
 
-void FSpatialTraceEventDataBuilder::AddFieldId(const uint32 FieldId, const char* Key /*="FieldId"*/)
+void FSpatialTraceEventDataBuilder::AddFieldId(const uint32 FieldId, const char* Key /*="field_id"*/)
 {
 	AddKeyValue(Key, FieldId);
 }
 
-void FSpatialTraceEventDataBuilder::AddWorkerId(const uint32 WorkerId, const char* Key /*="WorkerId"*/)
+void FSpatialTraceEventDataBuilder::AddWorkerId(const uint32 WorkerId, const char* Key /*="worker_id"*/)
 {
 	AddKeyValue(Key, WorkerId);
 }
 
-void FSpatialTraceEventDataBuilder::AddCommand(const char* Command, const char* Key /*="Command"*/)
+void FSpatialTraceEventDataBuilder::AddCommand(const char* Command, const char* Key /*="command"*/)
 {
 	AddKeyValue(Key, Command);
 }
 
-void FSpatialTraceEventDataBuilder::AddRequestId(const int64 RequestId, const char* Key /*="RequestId"*/)
+void FSpatialTraceEventDataBuilder::AddRequestId(const int64 RequestId, const char* Key /*="request_id"*/)
 {
 	AddKeyValue(Key, RequestId);
 }
 
-void FSpatialTraceEventDataBuilder::AddAuthority(const Worker_Authority Authority, const char* Key /*="Authority"*/)
+void FSpatialTraceEventDataBuilder::AddAuthority(const Worker_Authority Authority, const char* Key /*="authority"*/)
 {
 	AddKeyValue(Key, AuthorityToString(Authority));
 }
 
-void FSpatialTraceEventDataBuilder::AddLinearTraceId(const EventTraceUniqueId LinearTraceId, const char* Key /*="LinearTraceId"*/)
+void FSpatialTraceEventDataBuilder::AddLinearTraceId(const EventTraceUniqueId LinearTraceId, const char* Key /*="linear_trace_id"*/)
 {
 	AddKeyValue(Key, LinearTraceId.Get());
 }
@@ -197,7 +197,7 @@ void FSpatialTraceEventDataBuilder::AddKeyValue(const char* Key, const int64 Val
 
 void FSpatialTraceEventDataBuilder::AddKeyValue(const char* Key, const bool bValue)
 {
-	AddKeyValue(StringConverter.AddString(Key), StringConverter.AddString(bValue ? "True" : "False"));
+	AddKeyValue(StringConverter.AddString(Key), StringConverter.AddString(bValue ? "true" : "false"));
 }
 
 void FSpatialTraceEventDataBuilder::AddKeyValue(int32 KeyHandle, int32 ValueHandle)
@@ -212,11 +212,11 @@ const char* FSpatialTraceEventDataBuilder::AuthorityToString(Worker_Authority Au
 	switch (Authority)
 	{
 	case Worker_Authority::WORKER_AUTHORITY_NOT_AUTHORITATIVE:
-		return "NotAuthoritative";
+		return "not_authoritative";
 	case Worker_Authority::WORKER_AUTHORITY_AUTHORITATIVE:
-		return "Authoritative";
+		return "authoritative";
 	default:
-		return "Unknown";
+		return "unknown";
 	}
 }
 

SpatialGDK/Source/SpatialGDK/Private/Interop/DebugMetricsSystem.cpp

@@ -92,11 +92,11 @@ void DebugMetricsSystem::ProcessOps(const TArray<Worker_Op>& Ops) const
 
 				if (EventTracer != nullptr)
 				{
-						SpanId = EventTracer->TraceEvent(SEND_COMMAND_RESPONSE_EVENT_NAME, "", CauseSpanId.GetConstId(), /* NumCauses */ 1,
-														 [RequestId](FSpatialTraceEventDataBuilder& EventBuilder) {
-															 EventBuilder.AddRequestId(RequestId);
-															 EventBuilder.AddKeyValue("Success", true);
-														 });
+					SpanId = EventTracer->TraceEvent(SEND_COMMAND_RESPONSE_EVENT_NAME, "", CauseSpanId.GetConstId(), /* NumCauses */ 1,
+													 [RequestId](FSpatialTraceEventDataBuilder& EventBuilder) {
+														 EventBuilder.AddRequestId(RequestId);
+														 EventBuilder.AddKeyValue("success", true);
+													 });
 				}
 
 				Connection.SendCommandResponse(RequestId, &Response, SpanId);