Unreal 日志系统调研

tubal · 发表于 2023-9-6 14:27

摘要

本文用于调研 Unreal 中日志系统的具体实现细节，旨在研究当软件崩溃时，如何保证日志信息及时被写入到文件中。由于 Unreal 日志系统架构复杂，分支众多，因此本文以宏 UE_LOG 为切入点，考虑最简单情况：只输出日志到文件，通过调用代码 UE_LOG(LogTemp, Log, TEXT(”Hello World”)) 进行调试。
得出以下结论：
1. UE 日志系统写入文件采用按时写入机制。基于 UE 的线程机制，UE 在法式启动时会另起两个线程，持续监测各自缓存中是否有新数据生成，并采纳相应的措置法子。
2. 当法式发生崩溃时，UE 日志系统并不能完全措置法式崩溃时的日志写入问题，但对比于缓存满写入机制，理论上按时写入机制损掉信息更少。
文章中有什么不合错误的处所，欢迎在评论区斧正！
UE 日志系统基本思想

Unreal Engine （以下简称为 “UE” ）的日志系统采用按时写入文件的思想，每隔一段时间（0.2s）会将缓存写入到文件中，当法式崩溃时，日志文件最多丢掉崩溃前（0.2s）内发生的信息，其他信息城市被写入；但如果使用缓存慢写入的方式却会丢掉缓存中所有信息，缓冲区越大，丢掉的信息越多。
UE 日志系统输出日志流程

从用户调用 UE_LOG 宏开始，直到 UE 将日志写入文件，共有 3 个线程参与到这个过程中，分袂为：
1. GameThread 线程：UE 的主线程，UE_LOG 宏大多在主线程被调用，每次调用时该线程负责接收日志携带的数据，将其存到缓存中，并通知输出设备措置日志信息，文件输出类 OutputDeviceFile 会将信息存在本身的 Buffer 中；
2. OutputDeviceRedirector 子线程：在软件启动时创建，循环检测缓存中是否有数据，如果有数据，则通知输出设备措置日志信息；
3. FAsyncWriter 子线程：在软件启动时创建，循环检测输出设备 OutputDeviceFile 的缓存中是否有数据，有数据则将数据存在 FArchiveFileWriterGeneric 类中，无数据就按时将 FArchiveFileWriterGeneric 类中的数据写入文件。
主线程 GameThread

在主线程中，软件启动时会将文件输出设备添加到输出设备打点类中。当用户调用 UE_LOG 宏发出日志时，软件会按照日志等级决定是否输出到控制台，随后调用 GLog->Serialize() 函数措置日志信息，该函数主要做两件事：
1. 将日志信息存储在 GLog 类的缓存 BufferedItems 中
2. 通知被添加进来的各输出设备措置该条日志信息，不需要缓存的日志设备必然会被通知到，需要缓存的设备则可能会在 OutputDeviceRedirector 子线程才被通知
GameThread 的业务流程图如下：

GameThread业务流程图

如上图所示，从软件启动开始，用户调用 `UE_Log` 输出日志到软件将日志输出到文件，整个流程共分为 `5` 个法式，本章将基于该流程图进行阐述。
1、日志系统初始化

UE 自身设置了多种输出日志的方式，每一种输出方式由分歧的 FOutputDevice 派生类（以下称为“输出设备”）来实现，此中输出日志到文件功能由 FOutputDeviceFile 类实现。
在软件启动时，各种输出设备会被添加到 FOutputDeviceRedirector 类中进行统一打点，FOutputDeviceRedirector 类是 UE 中打点各种输出设备的类，UE 为其设置了获取其单例的宏 G_LOG 。
void FGenericPlatformOutputDevices::SetupOutputDevices()
{
check(GLog);

ResetCachedAbsoluteFilename();

// Add the default log device (typically file) unless the commandline says otherwise.
if (!FParse::Param(FCommandLine::Get(), TEXT(”NODEFAULTLOG”)))
{
GLog->AddOutputDevice(FPlatformOutputDevices::GetLog());
}

TArray<FOutputDevice*> ChannelFileOverrides;
FPlatformOutputDevices::GetPerChannelFileOverrides(ChannelFileOverrides);

for (FOutputDevice* ChannelFileOverride : ChannelFileOverrides)
{
GLog->AddOutputDevice(ChannelFileOverride);
}

#if !NO_LOGGING
// if console is enabled add an output device, unless the commandline says otherwise...
if (GLogConsole && !FParse::Param(FCommandLine::Get(), TEXT(”NOCONSOLE”)))
{
GLog->AddOutputDevice(GLogConsole);
}

#if USE_DEBUG_LOGGING
// If the platform has a separate debug output channel (e.g. OutputDebugString) then add an output device
// unless logging is turned off
if (FPlatformMisc::HasSeparateChannelForDebugOutput() && !FParse::Param(FCommandLine::Get(), TEXT(”NODEBUGOUTPUT”)))
{
GLog->AddOutputDevice(new FOutputDeviceDebug());
}
#endif // USE_DEBUG_LOGGING
#endif

GLog->AddOutputDevice(FPlatformOutputDevices::GetEventLog());
};
以上代码是在 UE 初始化时执行的，各种输出设备通过 GLog->AddOutputDevice(FOutputDevice* OutputDeveice) 函数被添加到 FOutputDeviceRedirector 类中， AddOutputDevice 函数的第一次调用便是添加写入文件的输出设备。
GLog->AddOutputDevice(FOutputDevice* OutputDeveice) 的本质是操作其成员变量 TPimplPtr<UE::Private::FOutputDeviceRedirectorState> State 中的 FOutputDeviceRedirectorState::AddOutputDevice(FOutputDevice* OutputDeveice) 函数来完成业务：
void FOutputDeviceRedirectorState::AddOutputDevice(FOutputDevice* OutputDevice)
{
const auto AddTo = [OutputDevice](TArray<FOutputDevice*>& OutputDevices, TBitArray<TInlineAllocator<1>>& Flags)
{
const int32 Count = OutputDevices.Num();
if (OutputDevices.AddUnique(OutputDevice) == Count)
{
Flags.Add(OutputDevice->CanBeUsedOnPanicThread());
}
};
UE::Private::FOutputDevicesWriteScopeLock ScopeLock(*this);
if (OutputDevice->CanBeUsedOnMultipleThreads())
{
AddTo(UnbufferedOutputDevices, UnbufferedOutputDevicesCanBeUsedOnPanicThread);
}
else
{
AddTo(BufferedOutputDevices, BufferedOutputDevicesCanBeUsedOnPanicThread);
}
}
FOutputDeviceRedirectorState 会维护两个 FOutputDevice 类指针数列 BufferedOutputDevices 和 UnbufferedOutputDevices，分袂对应需要缓存的输出设备和无需缓存的设备，写入到文件的日志输出设备需要缓存，因此被添加到 `BufferedOutputDevices` 数组中。
2、UE_LOG宏输出日志

UE 为用户提供了接口 UE_LOG(CategoryName, Verbosity, Format, ...) 来输出日志，各参数意义如下：
1. CategoryName ：日志的类别，说明日志是由软件哪一部门功能发出；
2. Verbosity ：日志的等级，分为 Fatal 、Error 、Warning 、Display 等共 `12` 类，每种等级有分歧的效果，此中 Fatal 、Error 、Warning 、Display 是输出信息到控制台和日志文件，Log 是只输出信息到日志文件，不输出到控制台；
3. Format ：格式化字符串，暗示日志的内容。
3、FMsg::LogV

在默认情况下（直接输出日志信息，不将日志转换为记录）， UE_LOG 会调用静态函数 void FMsg::LogV() 输出日志，函数会按照日志等级分袂采用分歧类进行措置，具体内容如下：
void FMsg::LogV(const ANSICHAR* File, int32 Line, const FLogCategoryName& Category, ELogVerbosity::Type Verbosity, const TCHAR* Fmt, va_list Args)
{
#if !NO_LOGGING
QUICK_SCOPE_CYCLE_COUNTER(STAT_FMsgLogf);
CSV_CUSTOM_STAT(FMsgLogf, FMsgLogfCount, 1, ECsvCustomStatOp::Accumulate);

if (LIKELY(Verbosity != ELogVerbosity::Fatal))
{
TStringBuilder<512> Buffer;
Buffer.AppendV(Fmt, Args);
const TCHAR* Message = *Buffer;
FOutputDevice* OutputDevice = nullptr;
switch (Verbosity)
{
case ELogVerbosity::Error:
case ELogVerbosity::Warning:
case ELogVerbosity::Display:
case ELogVerbosity::SetColor:
OutputDevice = GWarn;
break;
default:
break;
}
(OutputDevice ? OutputDevice : GLog)->Serialize(Message, Verbosity, Category);
}
else
{
StaticFailDebugV(TEXT(”Fatal error:”), ””, File, Line, /*bIsEnsure*/ false, PLATFORM_RETURN_ADDRESS(), Fmt, Args);
}
#endif
}
在上述代码中，GWarn 和 GLog 都是 FOutputDevice 的派生类，分袂用于警告和普通日志的输出，选择哪种输出方式由日志等级 Verbosity 决定。
如果使用 GWarn 输出日志，GWarn 会先将日志输出到控制台，之后调用 GLog->Serialize() 输出日志：
void FFeedbackContext::Serialize(const TCHAR* V, ELogVerbosity::Type Verbosity, const FName& Category, double Time)
{
if (IsRunningCommandlet())
{
if (Verbosity == ELogVerbosity::Error || Verbosity == ELogVerbosity::Warning)
{
AddToHistory(V, Verbosity, Category, Time);
}
if (GLogConsole && !GLog->IsRedirectingTo(GLogConsole))
{
GLogConsole->Serialize(V, Verbosity, Category, Time);
}
}
if (!GLog->IsRedirectingTo(this))
{
GLog->Serialize(V, Verbosity, Category, Time);
}
}
本文只考虑输出日志到文件的情况，日志等级 Verbosity 为 Log ，所以直接采用 GLog->Serialize() 输出日志。
4、GLog->Serialize()

FOutputDeviceRedirector 类会将派生类分为两类：需要缓存的输出设备和无需缓存的设备，分歧的类别在输出日志函数 FOutputDeviceRedirector::Serialize() 采用分歧的措置方式，调用方式也不是简单的循环遍历，而是通过广播函数 BroadcastTo() 命令数组中所有输出设备执行各自的 Serialize() 函数。
在 UE 中，存在各种 Serialize() 函数用于对象和数据的序列化和反序列化。这些函数可以将对象或数据转换为字节流，以便进行存储、网络传输或其他用途。
FOutputDeviceRedirector::Serialize() 接收 FMsg::LogV() 传入的日志信息，主要有两种措置方式：
1. 通过成员变量 State 的 BroadcastTo 函数将日志信息广播到各个输出设备，让他们调用各自的 Serialize() 函数直接措置日志信息；
2. 将日志信息存入 FOutputDeviceRedirector 类的缓存 BufferedItems 中，在其他线程检测缓存并措置。
函数具体内容如下：
void FOutputDeviceRedirector::Serialize(const TCHAR* const Data, const ELogVerbosity::Type Verbosity, const FName& Category, const double Time)
{
using namespace UE::Private;

const double RealTime = Time == -1.0 ? FPlatformTime::Seconds() - GStartTime : Time;

FOutputDevicesReadScopeLock Lock(*State);

#if PLATFORM_DESKTOP
// Print anything that arrives after logging has shut down to at least have it in stdout.
if (UNLIKELY(State->BufferedOutputDevices.IsEmpty() && IsEngineExitRequested()))
{
#if PLATFORM_WINDOWS
_tprintf(_T(”%s\n”), Data);
#endif
FGenericPlatformMisc::LocalPrint(Data);
return;
}
#endif

const uint32 ThreadId = FPlatformTLS::GetCurrentThreadId();

// Serialize directly to any output devices which don't require buffering
State->BroadcastTo(ThreadId, State->UnbufferedOutputDevices, State->UnbufferedOutputDevicesCanBeUsedOnPanicThread,
UE_PROJECTION_MEMBER(FOutputDevice, Serialize),
Data, Verbosity, Category, RealTime);

// Serialize to the backlog when not in panic mode. This will deadlock in panic mode when the
// FPlatformMallocCrash allocator has been enabled and logging occurs on a non-panic thread.
if (UNLIKELY(State->bEnableBacklog && !State->HasPanicThread()))
{
State->AddToBacklog(Data, Verbosity, Category, RealTime);
}

// Serialize to buffered output devices from the primary logging thread.
// Lines are queued until buffered output devices are added to avoid missing early log lines.
if (State->IsPrimaryThread(ThreadId) && !State->BufferedOutputDevices.IsEmpty())
{
// Verify that this is the primary thread again because another thread may have become
// the primary thread between the previous check and the lock.
if (FOutputDevicesPrimaryScopeLock PrimaryLock(*State); PrimaryLock.IsLocked() && State->IsPrimaryThread(ThreadId))
{
State->FlushBufferedItems();
State->BroadcastTo(ThreadId, State->BufferedOutputDevices, State->BufferedOutputDevicesCanBeUsedOnPanicThread,
UE_PROJECTION_MEMBER(FOutputDevice, Serialize),
Data, Verbosity, Category, RealTime);
if (UNLIKELY(State->IsPanicThread(ThreadId)))
{
Flush();
}
return;
}
}

// Queue the line to serialize to buffered output devices from the primary thread.
if (State->BufferedItems.EnqueueAndReturnWasEmpty(Data, Category, Verbosity, RealTime))
{
if (FEvent* WakeEvent = State->ThreadWakeEvent.load(std::memory_order_acquire))
{
WakeEvent->Trigger();
}
}
}
在上述代码中， FOutputDeviceRedirector 类措置日志主要有三处：
1. 第一次调用 BroadcastTo() ：通知无需缓存的输出设备直接措置日志信息，信息采用参数的方式传递过去；
2. 第二次调用 BroadcastTo() ：代码执行线程为主线程时，会直接进入到第二个 BroadcastTo() 地址的 if 判断中，通知所有需要缓存的设备执行他们的 Serialize() 函数；
3. 调用 State->BufferedItems.EnqueueAndReturnWasEmpty(Data, Category, Verbosity, RealTime) 函数，将日志信息存入缓存 BufferedItems 中，等待另一个线程措置缓存数据。
对于 UE 启动时输出的初始化相关的日志，会采用方式 2 进行输出，对于后续用户手动输入的各种日志，则再也没有进入到 if 语句中，采用方式 3 输出。
5、BroadcastTo

BroadcastTo() 函数用于通知输出设备数组中所有成员调用指定的函数，具体函数内容如下：
template <typename OutputDevicesType, typename FunctionType, typename... ArgTypes>
FORCEINLINE void BroadcastTo(
const uint32 ThreadId,
const OutputDevicesType& OutputDevices,
const TBitArray<TInlineAllocator<1>>& CanBeUsedOnPanicThread,
FunctionType&& Function,
ArgTypes&&... Args)
{
int32 Index = 0;
const bool bIsPanicThread = IsPanicThread(ThreadId);
for (FOutputDevice* OutputDevice : OutputDevices)
{
if (!bIsPanicThread || CanBeUsedOnPanicThread[Index++])
{
Invoke(Function, OutputDevice, Forward<ArgTypes>(Args)...);
}
}
}
函数输入参数中存在一个输出设备数组以及函数类，在 FOutputDeviceRedirector::Serialize() 中的调用便是通知所有输出设备执行 Serialize() 函数。
对于 FOutputDeviceFile 类而言，它也有本身的 Serialize() 函数，并通过 BroadcastTo() 函数进行调用。
需要注意的是，FOutputDeviceFile::Serialize() 函数也并不会直接将日志写入文件中，而只是将日志写入缓存中，真正写入文件是在 FAsyncWriter 子线程中完成。
子线程 OutputDeviceRedirector

UE 启动时会另起一个线程 OutputDeviceRedirector ，该线程会循环检测 BufferedItems 是否为空，如果不为空，则通知各个输出设备措置日志信息。OutputDeviceRedirector 的业务流程图如下：

OutputDeviceRedirector线程流程图

如图所示，子线程 OutputDeviceRedirector 的核心工作就是一直运行 FOutputDeviceRedirectorState::ThreadLoop() 函数，该函数循环检测并措置日志缓存，本章将讲解 ThreadLoop() 和 FOutputDeviceRedirectorState::FlushBufferedItems() 两个函数。
ThreadLoop() 函数

OutputDeviceRedirector 线程是在 UE 初始化函数 FEngineLoop::PreInitPreStartupScreen() 中创建的，最终会运行到 FOutputDeviceRedirectorState::ThreadLoop() 函数主体，函数具体内容如下：
void FOutputDeviceRedirectorState::ThreadLoop()
{
const uint32 ThreadId = FPlatformTLS::GetCurrentThreadId();

if (FOutputDevicesPrimaryScopeLock Lock(*this); Lock.IsLocked())
{
PrimaryThreadId.store(ThreadId, std::memory_order_relaxed);
}

while (FEvent* WakeEvent = ThreadWakeEvent.load(std::memory_order_acquire))
{
WakeEvent->Wait();
while (!BufferedItems.IsEmpty() && IsPrimaryThread(ThreadId))
{
if (FOutputDevicesPrimaryScopeLock Lock(*this); Lock.IsLocked())
{
FlushBufferedItems();
}
}
ThreadIdleEvents.ConsumeAllLifo([](FEvent* Event) { Event->Trigger(); });
}
}
在完成初始化后，函数便会进入 while 循环中，持续检测 BufferedItems 是否为空，如果缓存不为空，则调用 FlushBufferedItems() 函数清空缓存。
FlushBufferedItems() 函数

FlushBufferedItems() 函数负责通知所有需要缓存的输出设备措置 BufferedItems 中的日志信息，并消耗掉缓存的日志信息，函数具体内容如下：
void FOutputDeviceRedirectorState::FlushBufferedItems()
{
using namespace UE;
using namespace UE::Private;

if (BufferedItems.IsEmpty())
{
return;
}

TRACE_CPUPROFILER_EVENT_SCOPE(FOutputDeviceRedirector::FlushBufferedItems);

const uint32 ThreadId = FPlatformTLS::GetCurrentThreadId();
BufferedItems.Deplete([this, ThreadId](FOutputDeviceItem&& Item)
{
Visit([this, ThreadId](auto&& Value)
{
using ValueType = std::decay_t<decltype(Value)>;
if constexpr (std::is_same_v<ValueType, FOutputDeviceLine>)
{
const FOutputDeviceLine& Line = Value;
BroadcastTo(ThreadId, BufferedOutputDevices, BufferedOutputDevicesCanBeUsedOnPanicThread,
UE_PROJECTION_MEMBER(FOutputDevice, Serialize),
Line.Data, Line.Verbosity, Line.Category, Line.Time);
}
else if constexpr (std::is_same_v<ValueType, FLogRecord>)
{
const FLogRecord& Record = Value;
BroadcastTo(ThreadId, BufferedOutputDevices, BufferedOutputDevicesCanBeUsedOnPanicThread,
UE_PROJECTION_MEMBER(FOutputDevice, SerializeRecord), Record);
}
}, Item.Value);
});
}
上述代码中，BufferedItems.Deplete() 函数用于遍历缓存中所有数据，对每一条数据通知所有需要缓存的输出设备执行 Serialize() 函数，在不将日志转化成记录的情况下，代码只会运行进第一个 if 语句中，随后将 BufferedItems 的内容清空。
子线程 FAsyncWriter

将日志写入到文件业务由 FOutputDeviceFile 类完成，FOutputDeviceFile 类又依赖于 FAsyncWriter 类， FAsyncWriter 类操作 `FArchiveFileWriterGeneri 类将日志写入文件， FOutputDeviceFile 类类图如下：

上图中的 4 个类具体功能如下：
1、FOutputDeviceFile ：FOutputDevice 的派生类，在法式启动时被插手到 `GLog` 类中，用于接收外部广播到的日志信息；
2、FAsyncWriter ：FOutputDeviceFile 的成员变量，维护一个 Buffer ，存储 FOutputDeviceFile 接收到的日志信息，并调用 Ar 按时将日志写入文件；
3、FArchiveFileWriterGeneric ：FAsyncWriter 的成员变量，维护一个 BufferArray ，按时将缓存数据写入文件中并清空缓存；
4、 FArchive ：FArchiveFileWriterGeneric 的基类，用于对象序列化和反序列化。
当外部调用 BroadcastTo() 函数通知 FOutputDeviceFile 类调用自身的 Serialize() 函数时，FOutputDeviceFile 类便会将通知中附带的日志信息存入在本身的缓存 Buffer 中，子线程 FAsyncWriter 同样是一个循环过程，主要做三件事：
1、将 Buffer 中的数据序列化到文件写入类 FArchiveFileWriterGeneric 的 BufferArray 中；
2、检测距离上次写入时刻是否超时，如果超时，则要求 FArchiveFileWriterGeneric 类将缓存数据接入到文件；
3、重置按时器，继续循环。
FAsyncWriter 子线程流程图如下：

FAsyncWriter 子线程流程图

本章节将讲述 FOutputDeviceFile::Serialize() 和 FAsyncWriter::Run() 两个函数。
FOutputDeviceFile::Serialize()

当其他线程调用 BroadcastTo() 函数时，如果通知的对象是 BufferedOutputDevices ，那么 FOutputDeviceFile 类便会接收到通知，调用本身的 Serialize() 函数，函数具体内容如下：
void FOutputDeviceFile::Serialize( const TCHAR* Data, ELogVerbosity::Type Verbosity, const class FName& Category, const double Time )
{
#if ALLOW_LOG_FILE && !NO_LOGGING
if (CategoryInclusionInternal && !CategoryInclusionInternal->IncludedCategories.Contains(Category))
{
return;
}

static bool Entry = false;
if( !GIsCriticalError || Entry )
{
if (!AsyncWriter && !Dead)
{
// Open log file and create the worker thread.
if (!CreateWriter())
{
Dead = true;
}
}

if (AsyncWriter && Verbosity != ELogVerbosity::SetColor)
{
FOutputDeviceHelper::FormatCastAndSerializeLine(*AsyncWriter, Data, Verbosity, Category, Time, bSuppressEventTag, bAutoEmitLineTerminator);

static bool GForceLogFlush = false;
static bool GTestedCmdLine = false;
if (!GTestedCmdLine)
{
GTestedCmdLine = true;
// Force a log flush after each line
GForceLogFlush = FParse::Param( FCommandLine::Get(), TEXT(”FORCELOGFLUSH”) );
}
if (GForceLogFlush)
{
AsyncWriter->Flush();
}
}
}
else
{
Entry = true;
Serialize(Data, Verbosity, Category, Time);
Entry = false;
}
#endif
}
函数最为关键的指令是 FOutputDeviceHelper::FormatCastAndSerializeLine(*AsyncWriter, Data, Verbosity, Category, Time, bSuppressEventTag, bAutoEmitLineTerminator); 这句话将从外部接收到的日志数据和成员变量 AsyncWriter 全部传入静态函数中，旨在调用 FAsyncWriter::Serialize() 函数，将日志数据存储在 AsyncWriter 的缓存 Buffer 中。
虽然 FOutputDeviceFile::Serialize() 函数并不在 FAsyncWriter 子线程中执行，而是处于 BroadcastTo() 地址的线程中，但是它为 FAsyncWriter 子线程提供了缓存数据，FAsyncWriter 子线程就是在持续检测是否有新的缓存数据到来并进行措置。
FAsyncWriter::Run

和 FOutputDeviceRedirectorState::ThreadLoop() 相似，FAsyncWriter::Run 函数在软件启动时便在子线程 FAsyncWriter 中执行，具体内容如下：
uint32 FAsyncWriter::Run()
{
FScopeLock RunLock(&RunCritical);

while (StopTaskCounter.GetValue() == 0)
{
if (SerializeRequestCounter.GetValue() > 0)
{
SerializeBufferToArchive();
}
else if ((FPlatformTime::Seconds() - LastArchiveFlushTime) > GetLogFlushIntervalSec() )//写入时机
{
FlushArchiveAndResetTimer();//将日志写入文件
}
else
{
FPlatformProcess::SleepNoStats(0.01f);
}
}
return 0;
}
在 while 循环中，首先按照 SerializeRequestCounter 检测 `Buffer` 中是否有新数据发生，如果有，便需要先将新数据写入到 Ar 中的 BufferArray 中，否则就检测按时器是否超时。
UE 日志缓存写入到文件的时机是当前时间距离上一次写入文件的时间超过指按时间（0.2s），如果超时，便要求 Ar 将缓存中数据写入到文件中，并清空缓存，等待下一次新数据的写入。

wbsyb · 发表于 2023-9-6 14:28

博主写得好系统好全面! 帮助很大![赞同]

AngelKiss · 发表于 2023-9-6 14:28

里面有些图片配色太暗，里面黑色字体看不清，更新了一下

		自动登录	找回密码
密码			立即注册

Unreal 日志系统调研

本帖子中包含更多资源