调试实时系统
禁止断点和在控制台滴漏！
引言
在开发过程中，设置断点和向控制台写入信息可能是最常用的两种调试技术。但一旦软件发布并在客户的系统上运行，这些技术就不再适用了。本文介绍的替代方法可以用于调试实时系统，并且在开发过程中也很有用。事实上，它们在开发过程中必须是足够的，因为在实时系统中它们将是唯一可用的方法。
当已发布的软件包含错误时，目标是在离线状态下重现该错误并开发修复程序。有时客户可以告诉您如何重现问题。但当客户无法做到时，您需要收集足够的数据来找出如何重现它。有时客户甚至不知道存在错误，但您的软件知道。它应该自行收集必要的数据。
跟踪点调试有时可在实时系统中进行。许多调试器都支持跟踪点和断点。当调试器命中跟踪点时，它会收集信息并继续执行，而不会暂停。通常，您会指示它收集某些数据结构的内容。由于这项技术与断点调试密切相关，因此本文不再详细讨论。
演练
本文中的代码摘自 Robust Services Core (RSC)。如果您是第一次阅读有关 RSC 的某个方面文章，请花几分钟时间阅读这篇 前言。
软件错误日志
当 Thread::Start 捕获到异常时，RSC 会生成一个软件错误日志。此函数被所有从 RSC 的 Thread 类派生的线程继承。异常会带来显著的开销，因此应用程序应该非常谨慎地抛出它们，并且更少地捕获它们。绝大多数情况下，异常代表一个需要修复的错误。
当 Thread::Start 捕获到异常时，它生成的日志包含一个堆栈跟踪，如 异常发生时捕获线程堆栈 中所述。RSC 中的所有异常都派生自 Exception，其构造函数在抛出异常时捕获堆栈。这使得 Thread::LogTrap 在生成日志时能够包含堆栈跟踪。例如，在使用错误指针时会发生此日志。
THR902 2-Aug-2019 09:45:43.183 on Reigi {5}
in NodeTools.RecoveryTestThread (tid=15, nid=0x0000bc60): trap number 2
type=Signal
signal : 11 (SIGSEGV: Invalid Memory Reference)
errval : 0xc0000005
Function Traceback:
NodeBase.SignalException.SignalException @ signalexception.cpp + 40[12]
NodeBase.Thread.HandleSignal @ thread.cpp + 1801[16]
NodeBase.SE_Handler @ systhread.win.cpp + 126[13]
_unDNameEx @ <unknown file> (err=487)
is_exception_typeof @ <unknown file> (err=487)
is_exception_typeof @ <unknown file> (err=487)
is_exception_typeof @ <unknown file> (err=487)
_CxxFrameHandler3 @ <unknown file> (err=487)
RtlInterlockedCompareExchange64 @ <unknown file> (err=487)
RtlInterlockedCompareExchange64 @ <unknown file> (err=487)
KiUserExceptionDispatcher @ <unknown file> (err=487)
NodeTools.RecoveryTestThread.Enter @ ntincrement.cpp + 3584[0]
NodeBase.Thread.Start @ thread.cpp + 2799[15]
NodeBase.Thread.EnterThread @ thread.cpp + 1564[0]
BaseThreadInitThunk @ <unknown file> (err=487)
RtlGetAppContainerNamedObjectPath @ <unknown file> (err=487)
RtlGetAppContainerNamedObjectPath @ <unknown file> (err=487)
堆栈必须在异常抛出时捕获，而不是在捕获时捕获。到它被捕获时，堆栈已经展开（在本例中一直展开到 Thread::Start），因此不再有任何有用的东西可以捕获。这就是为什么 Exception 的构造函数会捕获堆栈。与 STL 中抛出的异常相比，您只能得到像“invalid string position”这样的字符串，这根本没有说明谁导致了问题。堆栈跟踪至关重要，因为它不仅可以识别错误发生的位置（例如，在未检查 nullptr 参数的函数中），还可以识别代码是如何被到达的（即，从一个实际提供了错误参数的函数）。
当错误非常严重以至于应中止正在进行的工作时，应用程序应执行以下任一操作：
- 调用函数
Debug::Assert，或 throw一个SoftwareException或其子类。
这两种方法都会生成包含堆栈跟踪的日志。RSC 以与其他所有日志相同的方式处理这些异常日志。它将它们放入一个日志缓冲区，该缓冲区很快会写入文件，也可选地写入控制台。在已发布的软件中，用户可以收集这些日志并将其发送给您。更好的是，您的软件可以包含代码，通过互联网自动将它们发送给您。这些日志中的每一个都突出了一个需要修复的错误。
捕获堆栈是平台特定的；Windows 目标位于 SysThreadStack.win.cpp 中。上述日志仅捕获了导致异常的函数调用链。一个有用的增强功能是还可以捕获每个堆栈帧和 CPU 的寄存器。在日志中，这些仅显示为十六进制值，但一个离线工具可以连接到编译器的对象文件并解释原始十六进制值，以便在异常发生时可以研究每个函数参数和局部变量的值。但这需要更多的平台特定代码。
软件警告日志
与在问题发生后生成的软件错误日志不同，软件警告日志在主动检测到问题时使用。应用程序软件生成这些日志，最常见的是在收到无效输入时。它调用 Debug::SwLog 来生成它们。
static void SwLog(fn_name_arg func,
const std::string& errstr, debug64_t errval, bool stack = true);
func标识生成日志的函数errstr解释日志的原因errval是一个辅助调试的值（debug64_t是uint64_t的别名）stack通常为true，以便日志包含堆栈跟踪以辅助调试
让我们看一个软件警告日志的例子。RSC 的命令行界面 (CLI) 框架定义了基类 CliParm，所有 CLI 参数最终都派生自它。当参数注册到 CLI 时，它必须提供一个 help 字符串，以便 CLI 的 help 命令可以解释 CLI 命令所期望的每个参数。我们希望限制这些字符串的长度，以便在加上一些其他信息后，它们仍然可以适合 80 个字符宽的控制台。因此，CliParm 的构造函数如下所示：
CliParm::CliParm(c_string help, bool opt, c_string tag) :
help_(help),
opt_(opt),
tag_(tag)
{
Debug::Assert(help_ != nullptr);
auto size = strlen(help_);
auto total = ParmWidth + strlen(ParmExplPrefix) + size;
if(size == 0)
Debug::SwLog(CliParm_ctor, "help string empty", size);
else if(total >= COUT_LENGTH_MAX)
Debug::SwLog
(CliParm_ctor, "help string too long", total - COUT_LENGTH_MAX + 1);
}
如果未提供 help，Debug::Assert 将抛出 AssertionException。这实际上会导致系统初始化失败，因此它不会在已发布的软件中发生：开发人员必须先提供该值，代码才能被签入。之后，如果 help 为空或太长而无法在一行控制台上显示，代码将生成一个警告日志。因此，如果我们通过更改NbIncrement.cpp 来编辑：
fixed_string LogsListTextExpl =
"shows info for all logs or the logs in a specific group";
改为这样。
fixed_string LogsListTextExpl =
"shows information for all logs or the logs in a specific group";
然后，系统初始化期间会出现以下日志：
SW900 19-Feb-2020 18:08:29.915 on Reigi {1}
in CliParm.ctor
errval=help string too long offset=0x3
Function Traceback:
NodeBase.Debug.GenerateSwLog @ debug.cpp + 102[22]
NodeBase.Debug.SwLog @ debug.cpp + 214[25]
NodeBase.CliParm.CliParm @ cliparm.cpp + 65[45]
NodeBase.CliText.CliText @ clitext.cpp + 42[19]
NodeBase.LogsListText.LogsListText @ nbincrement.cpp + 1435[25]
NodeBase.LogsAction.LogsAction @ nbincrement.cpp + 1560[31]
NodeBase.LogsCommand.LogsCommand @ nbincrement.cpp + 1575[39]
NodeBase.NbIncrement.NbIncrement @ nbincrement.cpp + 3700[33]
NodeBase.Singleton<NodeBase.NbIncrement>.Instance @ singleton.h + 81[34]
NodeBase.NbModule.Startup @ nbmodule.cpp + 149[5]
NodeBase.ModuleRegistry.Startup @ moduleregistry.cpp + 434[19]
NodeBase.ModuleRegistry.Restart @ moduleregistry.cpp + 263[22]
NodeBase.InitThread.InitializeSystem @ initthread.cpp + 354[0]
NodeBase.InitThread.Enter @ initthread.cpp + 225[0]
NodeBase.Thread.Start @ thread.cpp + 3232[15]
NodeBase.Thread.EnterThread @ thread.cpp + 1755[0]
BaseThreadInitThunk @ <unknown file> (err=487)
RtlGetAppContainerNamedObjectPath @ <unknown file> (err=487)
RtlGetAppContainerNamedObjectPath @ <unknown file> (err=487)
日志抱怨 help 字符串太长，并且罪魁祸首很容易确定为 LogsCommand 使用的参数。查看代码，0x3 是需要从字符串中修剪的字符数。
RSC 存储库中的 225K 行代码包括超过 700 个对 Debug::SwLog 的调用。它应该经常使用！但与软件错误日志一样，软件警告日志的每一次出现都突显了一个需要修复的错误。
对象转储
有些线程一次服务一个工作项队列。当线程的某个事务期间发生错误时，包含事务中所有对象的转储在调试过程中可能非常有帮助。记录对象需要相当长的时间，因此通常只与软件错误日志结合使用。
以下设计方法支持在软件错误场景中进行对象转储：
- 应用程序线程必须跟踪其当前事务涉及的对象。
- 基类
Thread必须捕获所有异常，如 Robust C++：安全网 中所述。 - 在处理异常期间，
Thread必须调用一个虚函数，允许应用程序线程生成包含事务中对象的日志。 - 事务中涉及的每个对象都必须实现一个虚函数
Display（除非您乐于解密十六进制转储或编写一个将十六进制转换为符号值的离线工具）。
以下是对象转储跟随软件错误日志的演练。初始日志发生在测试用例期间，该测试用例提示 RSC 附带的电信应用程序在收到表示远端已接听呼叫的消息时抛出异常。InvokerThread 是计划处理电信应用程序事务的线程：
THR902 2-Feb-2020 13:04:23.037 on Reigi {3}
in SessionBase.InvokerThread (tid=11, nid=0x000089b0): trap number 1
type=SessionBase Exception
errstr : trap recovery test
offset : 0x0
context : 000001D15B508178
Function Traceback:
SessionBase.SbException.SbException @ context.cpp + 113[25]
SessionBase.Context.Kill @ context.cpp + 608[26]
CallBase.BcOaAnalyzeRemoteMessage.ProcessEvent @ bchandlers.cpp + 131[30]
SessionBase.SbAnalyzeMessage.ProcessEvent @ sbhandlers.cpp + 74[40]
SessionBase.ServiceSM.ProcessEvent @ servicesm.cpp + 559[46]
SessionBase.SsmContext.ProcessIcMsg @ ssmcontext.cpp + 211[30]
SessionBase.Context.ProcessMsg @ context.cpp + 700[0]
SessionBase.Context.ProcessWork @ context.cpp + 773[40]
SessionBase.InvokerPool.ProcessWork @ invokerpool.cpp + 554[0]
SessionBase.InvokerThread.Enter @ invokerthread.cpp + 176[0]
NodeBase.Thread.Start @ thread.cpp + 3235[0]
NodeBase.Thread.EnterThread @ thread.cpp + 1755[0]
BaseThreadInitThunk @ <unknown file> (err=487)
RtlUserThreadStart @ <unknown file> (err=487)
提供对象转储的日志非常冗长，因此您可能需要点击“收缩”按钮。日志显示了 9 个对象：
- 处理上下文（
SsmContext），它聚合了呼叫中涉及的对象； - 用于与用户电话之间消息的协议状态机（
PotsCallPsm）； - 用于与呼叫远端之间消息的协议状态机（
CipPsm）； - 来自呼叫远端的消息（
CipMessage）及其内容（SbIpBuffer）； - 协议状态机接收和发送消息的两个端口（
MsgPort）； - 基本呼叫的服务状态机（
PotsBcSsm）；和 - 状态机当前正在处理的事件（
AnalyzeMsgEvent）。
SESS900 2-Feb-2020 13:04:23.037 on Reigi {4}
SessionBase.SsmContext
this : 000001D15B508178
patchArea : 0x0
pid : 6
seq : 1
link : 0000000000000000
assigned : true
orphaned : 0
corrupt : false
logged : false
whichq : 0000000000000000
link :
next : 0000000000000000
prev : 0000000000000000
priMsgq :
tail : 0000000000000000
diff : 16
stdMsgq :
tail : 0000000000000000
diff : 16
enqTime : 3505468504310
pool : 000001D15B0F4AD0
thread : 000001D15C8113C8
faction : 5
state : 3
prio : 2
traceOn : true
trans : 000001D15C8DBB00
trace : 4,9> 4,9> 3,2> 4,9>
portq :
tail : 000001D15D4E02D0
diff : 16
[->]: 000001D15D4E0218 SessionBase.MsgPort
[->]: 000001D15D4E02C0 SessionBase.MsgPort
psmq :
tail : 000001D15DC126B0
diff : 16
[->]: 000001D15DC12438 PotsBase.PotsCallPsm
[->]: 000001D15DC126A0 CallBase.CipPsm
root : 000001D15EB2A3F8
--------------------------------------------------------
PotsBase.PotsCallPsm
this : 000001D15DC12438
patchArea : 0x0
pid : 9
seq : 1
link : 000001D15DC126B0
assigned : true
orphaned : 0
corrupt : false
logged : false
ctx : 000001D15B508178
upper : 0000000000000000
lower : 000001D15D4E0218
rcvdMsgq :
tail : 0000000000000000
diff : 16
ogMsgq :
tail : 0000000000000000
diff : 16
sentMsgq :
tail : 0000000000000000
diff : 16
timerq :
tail : 0000000000000000
diff : 16
fid : 7
state : 1
ogMsg : 0000000000000000
sendRing : false
sendScan : false
sendCause : false
sendFacility : false
header :
signal : 0 (nullptr)
port : 11 (POTS 20000)
ring :
on : false
scan :
digits : false
flash : false
cause :
cause : 0 (Invalid Cause)
facility :
sid : 0 (nullptr)
ind : 0
--------------------------------------------------------
CallBase.CipPsm
this : 000001D15DC126A0
patchArea : 0x0
pid : 9
seq : 1
link : 000001D15DC12448
assigned : true
orphaned : 0
corrupt : false
logged : false
ctx : 000001D15B508178
upper : 0000000000000000
lower : 000001D15D4E02C0
rcvdMsgq :
tail : 000001D15D8F4288
diff : 16
[->]: 000001D15D8F4278 CallBase.CipMessage
ogMsgq :
tail : 0000000000000000
diff : 16
sentMsgq :
tail : 0000000000000000
diff : 16
timerq :
tail : 0000000000000000
diff : 16
fid : 2
state : 8
edge : false
ogPsm : 000001D15DC12438
ogTone : 255
icTone : 255
icMedia :
rxFrom : 12 (POTS 20001)
ogMediaSent :
rxFrom : 11 (POTS 20000)
ogMediaCurr :
rxFrom : 11 (POTS 20000)
mep : 0000000000000000
iamTimer : false
--------------------------------------------------------
CallBase.CipMessage
this : 000001D15D8F4278
patchArea : 0x0
pid : 7
seq : 1
link : 000001D15D8F4288
assigned : true
orphaned : 0
corrupt : false
logged : false
buff : 000001D15B0CBE78
bt : 0000000000000000
handled : false
saves : 0
psm : 000001D15DC126A0
whichq : 000001D15DC126D8
--------------------------------------------------------
SessionBase.SbIpBuffer
this : 000001D15B0CBE78
patchArea : 0x0
pid : 4
seq : 1
link : 0000000000000000
assigned : true
orphaned : 0
corrupt : false
logged : false
rxTicks : 3505468487443
buff : 000001D15ED27A90
hdrSize : 24
buffSize : 42
txAddr : 192.168.0.10: 40000
rxAddr : 192.168.0.10: 40000
dir : 0
external : false
queued : false
length : 8
00: 03 00 00 00 01 08 03 00 - 02 00 00 00 01 08 02 00 ................
01: 02 80 03 00 04 00 08 00 - 00 00 02 00 0c 00 0b 00 .€..............
MsgHeader:
txAddr : bid=3 seq=1 pid=8 fid=3
rxAddr : bid=2 seq=1 pid=8 fid=2
priority=2 initial=0 final=0 join=0 self=0
injected=0 kill=0 route=2 length=8 spare=0x0
protocol=3 (CipProtocol) signal=4 (CipAnmSignal)
Parameters:
Deleted parameter: pid=0, length=2
--------------------------------------------------------
SessionBase.MsgPort
this : 000001D15D4E0218
patchArea : 0x0
pid : 8
seq : 1
link : 000001D15D4E02D0
assigned : true
orphaned : 0
corrupt : false
logged : false
ctx : 000001D15B508178
upper : 000001D15DC12438
lower : 0000000000000000
locAddr :
SessionBase.GlobalAddress
this : 000001D15D4E0250
patchArea : 0x0
v4Addr : 192.168.0.10: 40002
port : 40002
proto : Any
socket : 0000000000000000
sbAddr : bid=1 seq=1 pid=8 fid=7
remAddr :
SessionBase.GlobalAddress
this : 000001D15D4E0280
patchArea : 0x0
v4Addr : 192.168.0.10: 40001
port : 40001
proto : Any
socket : 0000000000000000
sbAddr : bid=0 seq=0 pid=0 fid=6
msgRcvd : true
msgSent : true
--------------------------------------------------------
SessionBase.MsgPort
this : 000001D15D4E02C0
patchArea : 0x0
pid : 8
seq : 1
link : 000001D15D4E0228
assigned : true
orphaned : 0
corrupt : false
logged : false
ctx : 000001D15B508178
upper : 000001D15DC126A0
lower : 0000000000000000
locAddr :
SessionBase.GlobalAddress
this : 000001D15D4E02F8
patchArea : 0x0
v4Addr : 192.168.0.10: 40000
port : 40000
proto : Any
socket : 0000000000000000
sbAddr : bid=2 seq=1 pid=8 fid=2
remAddr :
SessionBase.GlobalAddress
this : 000001D15D4E0328
patchArea : 0x0
v4Addr : 192.168.0.10: 40000
port : 40000
proto : Any
socket : 0000000000000000
sbAddr : bid=3 seq=1 pid=8 fid=3
msgRcvd : true
msgSent : true
--------------------------------------------------------
PotsBase.PotsBcSsm
this : 000001D15EB2A3F8
patchArea : 0x0
pid : 12
seq : 1
link : 0000000000000000
assigned : true
orphaned : 0
corrupt : false
logged : false
sid : 2
currState : 8
nextState : 8
idled : false
nextSap : 0
nextSnp : 0
triggered :
1 2 4 5 7 8 9 12 13 15 16 18 19 20 23 24
ssmq :
tail : 0000000000000000
diff : 16
parentSsm : 0000000000000000
eventq[Active] :
tail : 000001D15ECA0BF8
diff : 16
[->]: 000001D15ECA0BE8 SessionBase.AnalyzeMsgEvent
eventq[Pending] :
tail : 0000000000000000
diff : 16
eventq[Saved] :
tail : 0000000000000000
diff : 16
ctx : 000001D15B508178
mgwPsm : 0000000000000000
model : 1
upsm : 000001D15DC12438
npsm : 000001D15DC126A0
dialed :
count : 5
digits : 20001
analysis :
selector : 1 (Directory Number)
identifier : 20001
route :
selector : 7 (PotsCallFactory)
identifier : 20001
proxyCount : 0
prof : 000001D15B162310
tid : 0
trmt : 0000000000000000
--------------------------------------------------------
SessionBase.AnalyzeMsgEvent
this : 000001D15ECA0BE8
patchArea : 0x0
pid : 11
seq : 1
link : 000001D15ECA0BF8
assigned : true
orphaned : 0
corrupt : false
logged : false
eid : 1
owner : 000001D15EB2A3F8
location : 0
msg : 000001D15D8F4278
在处理异常时，Thread::Start 调用 InvokerThread::Recover 时生成了对象转储。InvokerThread 在其 ctx_ 成员中跟踪正在运行的上下文。在转储上下文及其对象后，它会删除它们。
bool InvokerThread::Recover()
{
if(ctx_ != nullptr)
{
ctx_->Dump();
// The implementation of unique_ptr.reset may be equivalent to this:
// item = this->ptr_;
// this->ptr_ = nullptr;
// delete item;
// That is, the unique_ptr does not point to the item being deleted while
// its destructor is executing. Consequently, Context::RunningContext,
// which depends on our ctx_ field, cannot find the running context (the
// one being deleted). So instead of simply invoking ctx_.reset, we do
// the following so that ctx_ will be valid during deletion:
//
auto ctx = ctx_.get();
delete ctx;
ctx_.release();
}
return true;
}
Context::Dump 创建日志并使用 Base::LogSubtended 来转储所有对象。
void Context::Dump() const
{
auto log = Log::Create(SessionLogGroup, SessionError);
if(log == nullptr) return;
LogSubtended(*log, Log::Tab, NoFlags);
Log::Submit(log);
}
Base::LogSubtended 使用 Base::GetSubtended 将根对象及其所有传递拥有的对象填充到一个数组中，然后将其写入日志。
void Base::LogSubtended(ostream& stream,
const string& prefix, const Flags& options) const
{
std::vector<Base*> objects;
GetSubtended(objects);
for(size_t i = 0; i < objects.size(); ++i)
{
if(i > 0) stream << prefix << string(60 - prefix.size(), '-') << CRLF;
objects[i]->Display(stream, prefix, options);
}
}
拥有其他对象的类的对象会重写 Base::GetSubtended。它首先调用基类版本将自身添加到数组中，然后调用它拥有的对象的 GetSubtended，以便它们也可以添加它们自己和它们的对象到数组中。
void Base::GetSubtended(std::vector<Base*>& objects) const
{
objects.push_back(const_cast<Base*>(this));
}
跟踪缓冲区
到目前为止我们研究的调试技术——软件错误日志、软件警告日志和对象转储——被动地收集信息。但当它们证明不足时，下一步就是访问客户系统以启用跟踪工具。尽管可以默认启用跟踪工具，但它们在实时系统中的开销通常是过高的，除非在特定场景之外使用，因此它们仅在可能有助于揭示错误发生方式时使用。一个 数据包嗅探器 是一个您可能熟悉的跟踪工具的例子。
为了支持跟踪工具，RSC 提供了一个框架，其关键类是：
TraceRecord，一个用于定义可记录事件的虚拟基类，以及TraceBuffer，用于保存记录的事件。
TraceBuffer 最近被重写为非阻塞的。它是一个简单的循环缓冲区，包含指向一系列 TraceRecord 的指针。在应用程序构造了 TraceRecord 的一个子类后，它会调用 TraceBuffer::Insert 将记录添加到缓冲区。默认情况下，当缓冲区已满时，TraceRecord 会被删除。但是，可以启用循环覆盖，以便新记录覆盖旧记录。
bool TraceBuffer::Insert(TraceRecord* record)
{
// Delete the record if no slot is available.
//
auto slot = AllocSlot();
if(slot == SIZE_MAX)
{
delete record;
return false;
}
// If wraparound is allowed, there could already be a record
// in the slot. If so, delete it.
//
auto prev = buff_[slot];
if(prev != nullptr)
{
buff_[slot] = nullptr;
delete prev;
}
record->slot_ = slot;
buff_[slot] = record;
return true;
}
是 TraceBuffer::AllocSlot 使跟踪成为非阻塞且线程安全的，它在分配缓冲区中的下一个槽时原子地递增索引 bnext_。
size_t TraceBuffer::AllocSlot()
{
// This fails if
// o the buffer is not allocated
// o the buffer is locked
// o the buffer is full and wraparound is not enabled
//
if(buff_ == nullptr) return SIZE_MAX;
if(softLocks_ > 0)
{
++blocks_;
return SIZE_MAX;
}
auto slot = bnext_.fetch_add(1);
if(bnext_ >= size_)
{
ovfl_ = true;
if(wrap_) return (slot & (size_ - 1));
bnext_ = size_;
return SIZE_MAX;
}
return slot;
}
缓冲区可以被锁定（softLocks_），但这只由迭代缓冲区记录的代码完成，而这在需要跟踪的应用程序运行时从不发生。
为了控制跟踪，RSC 的 CLI 提供了 tools、query、set、include、exclude、start、stop、save 和 clear 命令。这些命令以及所有其他 CLI 命令都记录在 docs/help.cli 文件中。include 和 exclude 命令允许将跟踪限制在特定的线程、IP 端口、IP 地址、协议或服务，从而避免浪费时间构建快速填满跟踪缓冲区的无关跟踪记录。尽管此功能在开发过程中也很重要，但在实时系统中使用跟踪工具之前，它至关重要。
虚拟基类 TraceRecord 非常简单，包含三个数据成员：
- 记录的所有者，它标识一个特定的跟踪工具。
- 记录在添加到跟踪缓冲区后的槽（索引）。
- 一个标识符，其解释是工具特定的，它允许工具使用
switch而不是dynamic_cast来显示它收集的不同类型的事件。
函数跟踪器
RSC 的函数跟踪器是跟踪工具的一个示例。它是一个很好的例子，因为它用途广泛。它也是一个糟糕的例子，因为它如果被滥用，会将系统速度减慢大约 4 倍。但如果使用适当的过滤或在非高峰时段使用，它就可以用于实时系统。在开发过程中，它确实是一个非常有用的工具。
函数跟踪器的接口是 Debug::ft，大多数 RSC 函数在其第一个语句中调用它。这些调用已从本文前面所示的代码中删除，但如果我们回到第一个代码示例并查看 CliParm 构造函数的完整版本，我们会看到：
fn_name CliParm_ctor = "CliParm.ctor";
CliParm::CliParm(c_string help, bool opt, c_string tag) :
help_(help),
opt_(opt),
tag_(tag)
{
Debug::ft(CliParm_ctor); // followed by the code previously shown
}
对 Debug::ft 的调用仅表示调用了一个函数。
void Debug::ft(fn_name_arg func)
{
if(FcFlags_.none()) return;
Thread::FunctionInvoked(func);
}
很简单。如果没人关心函数调用，就什么也不做。否则，调用 Thread::FunctionInvoked。
谁关心一个函数被调用了？
- 函数跟踪工具，它记录一系列函数调用。
Thread类，当它需要向当前正在运行的线程发送信号时。Thread类，当它想检查运行的线程是否存在堆栈溢出的风险时。
Debug::ft 的普遍性使其能够支持后两种功能，否则这些功能将无法实现。这引出了：
void Thread::FunctionInvoked(fn_name_arg func)
{
Thread* thr = nullptr;
// This handles the following:
// (a) Adding FUNC to a trace.
// (b) Causing a trap after a thread is scheduled in.
// (c) Causing a trap before a thread overflows its stack.
//
if(Debug::FcFlags_.test(Debug::TracingActive))
{
auto& lock = AccessFtLock();
if(!lock.test_and_set())
{
if(TraceRunningThread(thr))
FunctionTrace::Capture(func);
lock.clear();
}
}
if(Debug::FcFlags_.test(Debug::TrapPending))
{
if(thr == nullptr) thr = RunningThread(std::nothrow);
if(thr == nullptr) return;
thr->TrapCheck();
}
if(Debug::FcFlags_.test(Debug::StackChecking))
{
if(StackCheckCounter_ <= 1)
{
if(thr == nullptr) thr = RunningThread(std::nothrow);
if(thr == nullptr) return;
thr->StackCheck();
}
else
{
--StackCheckCounter_;
}
}
}
第一个 if 语句检查函数跟踪工具是否已启用。如果是，它会在检查运行的线程是否应被跟踪之前设置一个每个线程的锁。如果应该，它会将函数调用添加到跟踪缓冲区。其余代码用于向运行的线程传递信号以及检查它是否即将堆栈溢出。
每个线程的锁可防止对 Debug::ft 的嵌套调用。如果不对这些调用进行阻止，比如在 Debug::ft 中调用的函数也调用了 Debug::ft，结果将是堆栈溢出。如果您不相信，可以删除锁自己尝试一下。当它崩溃时，我看到线程堆栈，我拍了拍自己的脸。最近，我添加了对 Debug::noft 的调用到在 Debug::ft 中调用的函数，以表明它们不必调用 Debug::ft，因为这样做是浪费时间。此外，谁想跟踪调用以跟踪函数的函数？
假设 FunctionTrace::Capture 被调用了，它做了什么？
void FunctionTrace::Capture(fn_name_arg func)
{
// The actual trace is
// func
// Debug::ft
// Thread::FunctionInvoked
// FunctionTrace::Capture
// FUNC is therefore three levels above the current depth.
//
if(Scope_ == CountsOnly)
{
auto buff = Singleton<TraceBuffer>::Instance();
buff->RecordInvocation(func);
return;
}
auto buff = Singleton<TraceBuffer>::Instance();
auto depth = SysThreadStack::FuncDepth() - 3;
auto rec = new FunctionTrace(func, depth);
buff->Insert(rec);
}
函数跟踪器有两种模式。其中一种模式 CountsOnly 非常高效，因为它只计算每个函数被调用的次数。这在决定优化哪些函数时很有用，因为在一个频繁调用的函数中微小的速度提升通常比在一个很少调用的函数中的巨大速度提升能带来更大的收益。
如果我们想记录每个函数的调用次数以上的信息，则使用平台特定的 SysThreadStack 来查找函数在堆栈上的深度。这与函数名一起被传递给 FunctionTrace 构造函数，该构造函数还记录了运行线程的标识符和当前滴答时间（即函数被调用时的时间）。
跟踪停止并将跟踪记录流式传输后，将处理 FunctionTrace 记录以计算在每个函数中花费的总时间和净时间。函数被调用时的堆栈帧数（深度）支持“阶梯式”输出，显示函数调用是如何嵌套的。如果跟踪了多个线程，则可以查看在调用每个函数时是哪个线程在运行。
这是函数跟踪的摘录。这实际上是 RSC 初始化期间捕获的第一段代码，甚至在进入 main 之前。它显示了三个互斥体（mutex）的创建，这些互斥体向 MutexRegistry 注册，而 MutexRegistry 必须先被创建才能注册第一个互斥体。
START OF TRACE: 30-Jan-2020 18:36:00.492 on Reigi
mm:ss.ttt Thr Event TotalTime NetTime Function
--------- --- ----- --------- ------- --------
36:00.492 1> 134 1 : : : SysMutex.ctor
36:00.492 1 44 44 : : : Permanent.ctor
36:00.492 1 47 5 : : : Singleton.Instance
36:00.492 1 17 3 : : : : Permanent.operator new
36:00.492 1 14 4 : : : : Memory.Alloc
36:00.492 1 10 10 : : : : : SysHeap.Alloc
36:00.492 1 24 2 : : : : MutexRegistry.ctor
36:00.492 1 7 7 : : : : Permanent.ctor
36:00.492 1 9 9 : : : : Registry.ctor
36:00.492 1 6 2 : : : : Registry.Init
36:00.492 1 4 2 : : : : : Memory.Alloc
36:00.492 1 2 2 : : : : : SysHeap.Alloc
36:00.492 1 1 1 : : : : Singletons.BindInstance
36:00.492 1 42 18 : : : MutexRegistry.BindMutex
36:00.492 1 24 24 : : : : MutexRegistry.Find
36:00.492 1 26 0 : : : SysMutex.ctor
36:00.492 1 7 7 : : : Permanent.ctor
36:00.492 1 19 4 : : : MutexRegistry.BindMutex
36:00.492 1 15 15 : : : : MutexRegistry.Find
36:00.492 1 149 0 : : : SysMutex.ctor
36:00.492 1 6 6 : : : Permanent.ctor
36:00.492 1 143 11 : : : MutexRegistry.BindMutex
36:00.492 1 132 132 : : : : MutexRegistry.Find
整个初始化的跟踪相当长，可以在 这里 查看，以及跟踪中出现的每个函数的调用计数。如果您在跟踪中搜索“>”，您会在 Thr 列中找到条目。该列显示了运行线程的标识符，在发生上下文切换时会附加一个“>”。每当 RSC 在初始化期间创建线程时，Windows 都会以一种疯狂的速度开始启动上下文切换！它只会减缓，因为新线程在进入后很快会暂停执行，只有在初始化完成后才会收到恢复信号。
大多数非平凡的函数都会调用 Debug::ft，以便它们出现在函数跟踪中。那些不这样做的通常属于以下类别之一：
- 在头文件中定义的函数
- 简单的
const函数，例如“getter” - 向流写入数据的函数
- 迭代器（例如，
First、Next、Prev、Last） - 构造或处理跟踪记录的函数
- 调用频率过高以至于会用噪声填充跟踪的函数
其他跟踪工具
函数跟踪器是 RSC 的众多跟踪工具之一。以下是其他跟踪工具的简要描述：
MemoryTracer记录堆的分配和释放事件，通常与其他跟踪工具结合使用。ObjPoolTracer记录对象池中块的出队、入队、领取和恢复事件。NetworkTracer记录套接字上 18 种不同类型的事件。TransTracer记录通过网络接收消息然后处理它的成本。BufferTracer记录传入和传出消息的完整内容。ContextTracer记录 RSC 状态机框架内 20 种不同类型的事件。ParserTracer记录 RSC 的 C++ 静态分析工具中的解析器/解释器中的 14 种不同类型的事件，从而产生类似堆栈机伪代码的跟踪。
您可以在开始跟踪之前启用任意子集工具。停止跟踪后，您可以使用 CLI 的 >save 命令生成跟踪文件，在生成之前禁用其中一些工具以排除其记录。每个跟踪文件都包含来自所有已启用工具的事件，并按发生的顺序排列。例如，此跟踪是 RSC 电信应用程序中的一个基本呼叫，其中 A 调用 B，B 接听，然后他们都断开连接。Event 列包含 NetworkTracer、TransTracer 和 ContextTracer 记录的事件，BufferTracer 记录的完整消息也出现在跟踪中。当 TransTracer 和 ContextTracer 都用于记录事件时，它们的事件也可以处理以生成消息顺序图。
在实验室
上述跟踪工具在实验室中也很有用，可以在其中更谨慎地使用。另外两个工具在集中调试期间也很有用：
- 要查找内存泄漏，请使用 CLI 的
>heap trace命令提供的子命令。 - 要查看上下文切换，请使用 CLI 的
>sched命令提供的子命令，该命令生成一个线程时间线，如下所示：此。
关注点
培训
尽管跟踪工具主要用于调试，但它们也是有用的教学辅助工具，可以帮助新开发人员理解代码的工作原理。例如，函数跟踪器可以轻松地看到哪个虚函数覆盖被调用。消息顺序图与状态机跟踪结合使用，可以极好地展示反应式系统的组件如何协作。
编译器优化
编译器积极的代码优化会使调试发布版本变得非常困难。内联一个在头文件中定义的函数是一回事，但内联不相关的函数并消除局部变量又是另一回事。即使是函数跟踪器的输出也很难理解。如果您需要在实时系统中调试您的软件，强烈建议您禁用许多编译器优化。其中一些优化带来的改进很小，但会使代码变得晦涩难懂。
函数跟踪和对象创建/删除
如果您查看 FunctionTrace::Capture 的完整版本，您会遇到一些代码，它会在析构函数链的开头插入对“C++.delete”的调用。此函数表示编译器生成的代码，它调用析构函数链，然后调用适当的 operator delete。当调用第一个析构函数时，函数跟踪器不知道之后是否会调用 delete 运算符，因此它会插入一个 C++.delete。之后，在将跟踪记录流式传输之前进行处理时，会从跟踪中删除虚假的 C++.delete 调用（即那些后面没有 delete 运算符的调用）。
这是一个添加到跟踪中的 C++.delete：
36:01.304 3 39 1 : : C++.delete
36:01.304 3 18 6 : : FileRequest.dtor
36:01.304 3 12 7 : : : StreamRequest.dtor
36:01.304 3 5 5 : : : MsgBuffer.dtor
36:01.304 3 20 7 : : Pooled.operator delete
36:01.304 3 13 7 : : : ObjectPool.EnqBlock
36:01.304 3 6 6 : : : Q1Way.Enq
构造函数更成问题。首先，一系列构造函数调用从下往上捕获，从基类到叶类。这有些令人困惑，并在计算每个函数花费的总时间和净时间时导致误导性的时间信息。因此，处理阶段通过将叶类放在前面，然后是基类，再向上移动到类层次结构来重新排序构造函数。这更清晰地显示了正在构造哪个类，并为其构造函数提供了正确的总时间。
另一个混淆的来源是，在成员初始化列表中调用的函数出现在其所属的构造函数之前。与基本构造函数链一样，这种倒序发生是因为必须在 Debug::ft 记录其调用之前进入构造函数的主体。
最后，当构造函数从基类到叶类（按深度）退出时，在某些情况下无法确定正确的叶类。只要链中的任何构造函数都不失败调用 Debug::ft，那么它们中的每一个（从基类到叶类）的深度都比前一个构造函数少一。但如果另一个构造函数紧随真正的叶构造函数之后，并且深度也少一，那么它将显示为叶类。似乎没有通用的方法可以修复此问题，而无需了解类层次结构。（然而，当对象在堆上分配时，总是可以确定正确的叶类，因为它的构造函数必须与调用 operator new 的深度相同。）
这是跟踪中没有进行任何处理来重新排序构造函数的摘录。
00:32.972 1 1011 63 : : : CxxStrLiteral.CreateRef
00:32.972 1 155 122 : : : Base.operator new
00:32.972 1 23 23 : : : : CxxToken.ctor
00:32.972 1 33 33 : : : : CxxNamed.ctor
00:32.972 1 169 11 : : : QualName.ctor(string)
00:32.972 1 29 22 : : : : Base.operator new
00:32.972 1 6 6 : : : : : CxxToken.ctor
00:32.972 1 7 7 : : : : CxxNamed.ctor
00:32.972 1 129 129 : : : : TypeName.ctor
00:32.972 1 104 54 : : : Base.operator new
00:32.972 1 10 10 : : : : : CxxToken.ctor
00:32.972 1 17 17 : : : : CxxNamed.ctor
00:32.972 1 44 44 : : : : TypeSpec.ctor
00:32.972 1 6 6 : : : : TypeTags.ctor
00:32.972 1 43 43 : : : DataSpec.ctor
00:32.972 1 5 5 : : : TypeTags.SetPointer
00:32.972 1 305 213 : : : Base.operator new
00:32.972 1 9 9 : : : : : : CxxToken.ctor
00:32.972 1 17 17 : : : : : CxxNamed.ctor
00:32.972 1 21 21 : : : : : CxxScoped.ctor
00:32.972 1 75 75 : : : : CxxScope.ctor
00:32.972 1 92 24 : : : : Data.ctor
00:32.972 1 68 8 : : : : DataSpec.SetUserType
00:32.972 1 23 23 : : : : : TypeSpec.SetUserType
00:32.972 1 37 15 : : : : : QualName.SetUserType
00:32.972 1 22 22 : : : : : TypeName.SetUserType
00:32.972 1 53 53 : : : FuncData.ctor
00:32.972 1 114 8 : : : Singleton.Instance
00:32.972 1 54 54 : : : : Base.operator new
00:32.972 1 13 13 : : : : CxxRoot.ctor
00:32.972 1 39 39 : : : : Singletons.BindInstance
这是同一摘录的“更正”版本。
36:00.493 1 710 61 : : : CxxStrLiteral.CreateRef
36:00.493 1 41 41 : : : Base.operator new
36:00.493 1 192 21 : : : QualName.ctor(string)
36:00.493 1 20 20 : : : : CxxToken.ctor
36:00.493 1 39 39 : : : : CxxNamed.ctor
36:00.493 1 13 13 : : : : Base.operator new
36:00.493 1 119 4 : : : : TypeName.ctor
36:00.493 1 3 3 : : : : : CxxToken.ctor
36:00.493 1 115 115 : : : : CxxNamed.ctor
36:00.493 1 14 14 : : : Base.operator new
36:00.493 1 80 7 : : : DataSpec.ctor
36:00.493 1 3 3 : : : : : CxxToken.ctor
36:00.493 1 3 3 : : : : CxxNamed.ctor
36:00.493 1 34 34 : : : : TypeSpec.ctor
36:00.493 1 39 39 : : : : TypeTags.ctor
36:00.493 1 3 3 : : : TypeTags.SetPointer
36:00.493 1 47 47 : : : Base.operator new
36:00.493 1 195 82 : : : FuncData.ctor
36:00.493 1 3 3 : : : : : : CxxToken.ctor
36:00.493 1 11 11 : : : : : CxxNamed.ctor
36:00.493 1 10 10 : : : : : CxxScoped.ctor
36:00.493 1 56 56 : : : : CxxScope.ctor
36:00.493 1 113 9 : : : : Data.ctor
36:00.493 1 104 8 : : : : DataSpec.SetUserType
36:00.493 1 9 9 : : : : : TypeSpec.SetUserType
36:00.493 1 87 13 : : : : : QualName.SetUserType
36:00.493 1 74 74 : : : : : TypeName.SetUserType
36:00.493 1 77 3 : : : Singleton.Instance
36:00.493 1 41 41 : : : : Base.operator new
36:00.493 1 6 6 : : : : CxxRoot.ctor
36:00.493 1 27 27 : : : : Singletons.BindInstance
历史
- 17日2020 年 8 月：添加“在实验室”部分
- 4日2020 年 2 月：初始版本