如何关联 ETW 跟踪中的 RPC 调用？
How to correlate RPC calls in ETW traces?
我记录了一个应用程序在 Windows 上执行本地 RPC 调用的踪迹。我在启用 Microsoft-Windows-RPC 提供程序的情况下使用 xperf。打开trace后，才发现要把client和server的调用关联起来并没有那么简单。用一个例子来解释问题会更容易。
客户端发送的 RpcClientCall 事件之一如下所示：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-RPC" Guid="{6ad52b32-d609-4be9-ae07-ce8dae937e39}" />
<EventID>5</EventID>
<Version>1</Version>
<Level>4</Level>
<Task>1</Task>
<Opcode>1</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2017-01-02T18:21:54.825009200+0059" />
<Correlation ActivityID="{f9ace53a-28fe-4129-ac24-8d04ea0a79a9}" />
<Execution ProcessID="10688" ThreadID="5384" ProcessorID="7" KernelTime="30" UserTime="15" />
<Channel>Microsoft-Windows-RPC/Debug</Channel>
<Computer />
</System>
<EventData>
<Data Name="InterfaceUuid">{e60c73e6-88f9-11cf-9af1-0020af6e72f4}</Data>
<Data Name="ProcNum">0x8</Data>
<Data Name="Protocol"> 3</Data>
<Data Name="NetworkAddress">NULL</Data>
<Data Name="Endpoint">epmapper</Data>
<Data Name="Options">NULL</Data>
<Data Name="AuthenticationLevel"> 6</Data>
<Data Name="AuthenticationService"> 20</Data>
<Data Name="ImpersonationLevel"> 3</Data>
</EventData>
<RenderingInfo Culture="en-US">
<Level>Information </Level>
<Opcode>Start </Opcode>
<Task>RpcClientCall</Task>
<Message>Client RPC call started. InterfaceUuid: {e60c73e6-88f9-11cf-9af1-0020af6e72f4} OpNum: 0x8 Protocol: LRPC NetworkAddress NULL Endpoint epmapper Binding Options NULL Authentication Level 7 Authentication Service 8 Impersonation Level 9 </Message>
<Channel>Debug </Channel>
<Provider>Microsoft-Windows-RPC </Provider>
</RenderingInfo>
</Event>
然后是一些 Debug 事件（具有相同的 ActivityID），比如这个：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-RPC" Guid="{6ad52b32-d609-4be9-ae07-ce8dae937e39}" />
<EventID>4</EventID>
<Version>1</Version>
<Level>5</Level>
<Task>3</Task>
<Opcode>0</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2017-01-02T18:21:54.825028400+0059" />
<Correlation ActivityID="{f9ace53a-28fe-4129-ac24-8d04ea0a79a9}" />
<Execution ProcessID="10688" ThreadID="5384" ProcessorID="7" KernelTime="30" UserTime="15" />
<Channel>Microsoft-Windows-RPC/Debug</Channel>
<Computer />
</System>
<EventData>
<Data Name="Subject">76</Data>
<Data Name="Verb">75</Data>
<Data Name="SubjectPointer">0x24F9A52CAF0</Data>
<Data Name="ObjectPointer">0x180</Data>
<Data Name="DataPointer">0x22000130</Data>
</EventData>
<RenderingInfo Culture="en-US">
<Level>Verbose </Level>
<Task>Debug</Task>
<Message>RPC Log Event.
Subject: ALPC Verb: PKT_OUT SubjectPointer: 0x24F9A52CAF0 ObjectPointer: 0x180 Data: 0x22000130 </Message>
<Channel>Debug </Channel>
<Provider>Microsoft-Windows-RPC </Provider>
</RenderingInfo>
</Event>
稍后我可能会发现 RpcServerCall 事件，它可能代表来自服务器的响应：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-RPC" Guid="{6ad52b32-d609-4be9-ae07-ce8dae937e39}" />
<EventID>6</EventID>
<Version>1</Version>
<Level>4</Level>
<Task>2</Task>
<Opcode>1</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2017-01-02T18:21:56.786737300+0059" />
<Correlation ActivityID="{11bb1d8d-336f-44e3-b853-b903f4fd2651}" />
<Execution ProcessID="652" ThreadID="15348" ProcessorID="4" KernelTime="90" UserTime="195" />
<Channel>Microsoft-Windows-RPC/Debug</Channel>
<Computer />
</System>
<EventData>
<Data Name="InterfaceUuid">{e60c73e6-88f9-11cf-9af1-0020af6e72f4}</Data>
<Data Name="ProcNum">0x8</Data>
<Data Name="Protocol"> 3</Data>
<Data Name="NetworkAddress">NULL</Data>
<Data Name="Endpoint">epmapper</Data>
<Data Name="Options">NULL</Data>
<Data Name="AuthenticationLevel"> 6</Data>
<Data Name="AuthenticationService"> 20</Data>
<Data Name="ImpersonationLevel"> 0</Data>
</EventData>
<RenderingInfo Culture="en-US">
<Level>Information </Level>
<Opcode>Start </Opcode>
<Task>RpcServerCall</Task>
<Message>Server RPC call started. InterfaceUuid: {e60c73e6-88f9-11cf-9af1-0020af6e72f4} OpNum: 0x4 Protocol: LRPC Endpoint epmapper Authentication Level 7 Authentication Service 8 </Message>
<Channel>Debug </Channel>
<Provider>Microsoft-Windows-RPC </Provider>
</RenderingInfo>
</Event>
此事件之后又发生了一些 Debug 事件（具有相同的 ActivityID）：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-RPC" Guid="{6ad52b32-d609-4be9-ae07-ce8dae937e39}" />
<EventID>4</EventID>
<Version>1</Version>
<Level>5</Level>
<Task>3</Task>
<Opcode>0</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2017-01-02T18:21:56.786747500+0059" />
<Correlation ActivityID="{11bb1d8d-336f-44e3-b853-b903f4fd2651}" />
<Execution ProcessID="652" ThreadID="15348" ProcessorID="4" KernelTime="90" UserTime="195" />
<Channel>Microsoft-Windows-RPC/Debug</Channel>
<Computer />
</System>
<EventData>
<Data Name="Subject">105</Data>
<Data Name="Verb">43</Data>
<Data Name="SubjectPointer">0x15B5283A110</Data>
<Data Name="ObjectPointer">0x0</Data>
<Data Name="DataPointer">0x1</Data>
</EventData>
<RenderingInfo Culture="en-US">
<Level>Verbose </Level>
<Task>Debug</Task>
<Message>RPC Log Event.
Subject: IF Verb: INC SubjectPointer: 0x15B5283A110 ObjectPointer: 0x0 Data: 0x1 </Message>
<Channel>Debug </Channel>
<Provider>Microsoft-Windows-RPC </Provider>
</RenderingInfo>
</Event>
调用完成后，我可以在客户端和服务器上看到一个 win:stop 事件，但这些事件只有一个字段：Status 和 ActivityID 集合与 win:start 事件相同的值，例如：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-RPC" Guid="{6ad52b32-d609-4be9-ae07-ce8dae937e39}" />
<EventID>8</EventID>
<Version>1</Version>
<Level>4</Level>
<Task>2</Task>
<Opcode>2</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2017-01-02T18:21:56.786835000+0059" />
<Correlation ActivityID="{11bb1d8d-336f-44e3-b853-b903f4fd2651}" />
<Execution ProcessID="652" ThreadID="15348" ProcessorID="4" KernelTime="90" UserTime="195" />
<Channel>Microsoft-Windows-RPC/Debug</Channel>
<Computer />
</System>
<EventData>
<Data Name="Status">0x0</Data>
</EventData>
<RenderingInfo Culture="en-US">
<Level>Information </Level>
<Opcode>Stop </Opcode>
<Task>RpcServerCall</Task>
<Message>Server RPC call was completed. Status: 0x0 </Message>
<Channel>Debug </Channel>
<Provider>Microsoft-Windows-RPC </Provider>
</RenderingInfo>
</Event>
问题
最后，我的问题是：我怎么能 100% 确定给定的 RpcServerCall 是对我最初的 RpcClientCall 的响应？ 我猜匹配 InterfaceUuid 、ProcNum、Protocol 和 Endpoint 是不够的，因为可能同时有多个调用给定端点。我希望这些 Debug 事件可能对您有所帮助。也许我应该使用另一个 ETW 提供程序？或者可能有启用 RelativeActivityId 的设置？
您可以通过启用 Microsoft-Windows-RPC 和按每个 RPC 调用唯一的 Activity ID 分组来关联事件。然后，您只需要为每个 activity id 关联 start/stop 事件，您可以在客户端进程的上下文中使用持续时间来关联任何 RPC 调用的持续时间。
对于每个 Acitivity，可以记录许多调试事件，但只有一个 start/stop 元组会在那里。这应该可以解决问题。
要关联 RPC 客户端和服务器调用，您首先需要通过查看具有相同 activity GUID 的 start/stop 事件来找到相应的 RPC 客户端和服务器调用。对于带有 RpcServer 调用的给定 RpcClient，您可以使用字段 5（端点）按它们分组。至少我发现，如果给定的端点仅同步提供呼叫服务，那么它看起来像是一个可靠的指标。接口也可能有效，但由于可以同时有多个 COM 服务器 运行 使用相同的接口 GUID，因此它不是一个可靠的指标。我认为它不会比给定数据好多少。为什么您如此热衷于 RPC 服务器部分？通常，您只会查看很长的客户端时间，这无论如何都足以触发更深入的分析。您是否正在寻找 RPC 基础设施内部的问题？
我记录了一个应用程序在 Windows 上执行本地 RPC 调用的踪迹。我在启用 Microsoft-Windows-RPC 提供程序的情况下使用 xperf。打开trace后，才发现要把client和server的调用关联起来并没有那么简单。用一个例子来解释问题会更容易。
客户端发送的 RpcClientCall 事件之一如下所示：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-RPC" Guid="{6ad52b32-d609-4be9-ae07-ce8dae937e39}" />
<EventID>5</EventID>
<Version>1</Version>
<Level>4</Level>
<Task>1</Task>
<Opcode>1</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2017-01-02T18:21:54.825009200+0059" />
<Correlation ActivityID="{f9ace53a-28fe-4129-ac24-8d04ea0a79a9}" />
<Execution ProcessID="10688" ThreadID="5384" ProcessorID="7" KernelTime="30" UserTime="15" />
<Channel>Microsoft-Windows-RPC/Debug</Channel>
<Computer />
</System>
<EventData>
<Data Name="InterfaceUuid">{e60c73e6-88f9-11cf-9af1-0020af6e72f4}</Data>
<Data Name="ProcNum">0x8</Data>
<Data Name="Protocol"> 3</Data>
<Data Name="NetworkAddress">NULL</Data>
<Data Name="Endpoint">epmapper</Data>
<Data Name="Options">NULL</Data>
<Data Name="AuthenticationLevel"> 6</Data>
<Data Name="AuthenticationService"> 20</Data>
<Data Name="ImpersonationLevel"> 3</Data>
</EventData>
<RenderingInfo Culture="en-US">
<Level>Information </Level>
<Opcode>Start </Opcode>
<Task>RpcClientCall</Task>
<Message>Client RPC call started. InterfaceUuid: {e60c73e6-88f9-11cf-9af1-0020af6e72f4} OpNum: 0x8 Protocol: LRPC NetworkAddress NULL Endpoint epmapper Binding Options NULL Authentication Level 7 Authentication Service 8 Impersonation Level 9 </Message>
<Channel>Debug </Channel>
<Provider>Microsoft-Windows-RPC </Provider>
</RenderingInfo>
</Event>
然后是一些 Debug 事件（具有相同的 ActivityID），比如这个：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-RPC" Guid="{6ad52b32-d609-4be9-ae07-ce8dae937e39}" />
<EventID>4</EventID>
<Version>1</Version>
<Level>5</Level>
<Task>3</Task>
<Opcode>0</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2017-01-02T18:21:54.825028400+0059" />
<Correlation ActivityID="{f9ace53a-28fe-4129-ac24-8d04ea0a79a9}" />
<Execution ProcessID="10688" ThreadID="5384" ProcessorID="7" KernelTime="30" UserTime="15" />
<Channel>Microsoft-Windows-RPC/Debug</Channel>
<Computer />
</System>
<EventData>
<Data Name="Subject">76</Data>
<Data Name="Verb">75</Data>
<Data Name="SubjectPointer">0x24F9A52CAF0</Data>
<Data Name="ObjectPointer">0x180</Data>
<Data Name="DataPointer">0x22000130</Data>
</EventData>
<RenderingInfo Culture="en-US">
<Level>Verbose </Level>
<Task>Debug</Task>
<Message>RPC Log Event.
Subject: ALPC Verb: PKT_OUT SubjectPointer: 0x24F9A52CAF0 ObjectPointer: 0x180 Data: 0x22000130 </Message>
<Channel>Debug </Channel>
<Provider>Microsoft-Windows-RPC </Provider>
</RenderingInfo>
</Event>
稍后我可能会发现 RpcServerCall 事件，它可能代表来自服务器的响应：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-RPC" Guid="{6ad52b32-d609-4be9-ae07-ce8dae937e39}" />
<EventID>6</EventID>
<Version>1</Version>
<Level>4</Level>
<Task>2</Task>
<Opcode>1</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2017-01-02T18:21:56.786737300+0059" />
<Correlation ActivityID="{11bb1d8d-336f-44e3-b853-b903f4fd2651}" />
<Execution ProcessID="652" ThreadID="15348" ProcessorID="4" KernelTime="90" UserTime="195" />
<Channel>Microsoft-Windows-RPC/Debug</Channel>
<Computer />
</System>
<EventData>
<Data Name="InterfaceUuid">{e60c73e6-88f9-11cf-9af1-0020af6e72f4}</Data>
<Data Name="ProcNum">0x8</Data>
<Data Name="Protocol"> 3</Data>
<Data Name="NetworkAddress">NULL</Data>
<Data Name="Endpoint">epmapper</Data>
<Data Name="Options">NULL</Data>
<Data Name="AuthenticationLevel"> 6</Data>
<Data Name="AuthenticationService"> 20</Data>
<Data Name="ImpersonationLevel"> 0</Data>
</EventData>
<RenderingInfo Culture="en-US">
<Level>Information </Level>
<Opcode>Start </Opcode>
<Task>RpcServerCall</Task>
<Message>Server RPC call started. InterfaceUuid: {e60c73e6-88f9-11cf-9af1-0020af6e72f4} OpNum: 0x4 Protocol: LRPC Endpoint epmapper Authentication Level 7 Authentication Service 8 </Message>
<Channel>Debug </Channel>
<Provider>Microsoft-Windows-RPC </Provider>
</RenderingInfo>
</Event>
此事件之后又发生了一些 Debug 事件（具有相同的 ActivityID）：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-RPC" Guid="{6ad52b32-d609-4be9-ae07-ce8dae937e39}" />
<EventID>4</EventID>
<Version>1</Version>
<Level>5</Level>
<Task>3</Task>
<Opcode>0</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2017-01-02T18:21:56.786747500+0059" />
<Correlation ActivityID="{11bb1d8d-336f-44e3-b853-b903f4fd2651}" />
<Execution ProcessID="652" ThreadID="15348" ProcessorID="4" KernelTime="90" UserTime="195" />
<Channel>Microsoft-Windows-RPC/Debug</Channel>
<Computer />
</System>
<EventData>
<Data Name="Subject">105</Data>
<Data Name="Verb">43</Data>
<Data Name="SubjectPointer">0x15B5283A110</Data>
<Data Name="ObjectPointer">0x0</Data>
<Data Name="DataPointer">0x1</Data>
</EventData>
<RenderingInfo Culture="en-US">
<Level>Verbose </Level>
<Task>Debug</Task>
<Message>RPC Log Event.
Subject: IF Verb: INC SubjectPointer: 0x15B5283A110 ObjectPointer: 0x0 Data: 0x1 </Message>
<Channel>Debug </Channel>
<Provider>Microsoft-Windows-RPC </Provider>
</RenderingInfo>
</Event>
调用完成后，我可以在客户端和服务器上看到一个 win:stop 事件，但这些事件只有一个字段：Status 和 ActivityID 集合与 win:start 事件相同的值，例如：
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="Microsoft-Windows-RPC" Guid="{6ad52b32-d609-4be9-ae07-ce8dae937e39}" />
<EventID>8</EventID>
<Version>1</Version>
<Level>4</Level>
<Task>2</Task>
<Opcode>2</Opcode>
<Keywords>0x4000000000000000</Keywords>
<TimeCreated SystemTime="2017-01-02T18:21:56.786835000+0059" />
<Correlation ActivityID="{11bb1d8d-336f-44e3-b853-b903f4fd2651}" />
<Execution ProcessID="652" ThreadID="15348" ProcessorID="4" KernelTime="90" UserTime="195" />
<Channel>Microsoft-Windows-RPC/Debug</Channel>
<Computer />
</System>
<EventData>
<Data Name="Status">0x0</Data>
</EventData>
<RenderingInfo Culture="en-US">
<Level>Information </Level>
<Opcode>Stop </Opcode>
<Task>RpcServerCall</Task>
<Message>Server RPC call was completed. Status: 0x0 </Message>
<Channel>Debug </Channel>
<Provider>Microsoft-Windows-RPC </Provider>
</RenderingInfo>
</Event>
问题
最后，我的问题是：我怎么能 100% 确定给定的 RpcServerCall 是对我最初的 RpcClientCall 的响应？ 我猜匹配 InterfaceUuid 、ProcNum、Protocol 和 Endpoint 是不够的，因为可能同时有多个调用给定端点。我希望这些 Debug 事件可能对您有所帮助。也许我应该使用另一个 ETW 提供程序？或者可能有启用 RelativeActivityId 的设置？
您可以通过启用 Microsoft-Windows-RPC 和按每个 RPC 调用唯一的 Activity ID 分组来关联事件。然后，您只需要为每个 activity id 关联 start/stop 事件，您可以在客户端进程的上下文中使用持续时间来关联任何 RPC 调用的持续时间。
对于每个 Acitivity，可以记录许多调试事件，但只有一个 start/stop 元组会在那里。这应该可以解决问题。
要关联 RPC 客户端和服务器调用，您首先需要通过查看具有相同 activity GUID 的 start/stop 事件来找到相应的 RPC 客户端和服务器调用。对于带有 RpcServer 调用的给定 RpcClient，您可以使用字段 5（端点）按它们分组。至少我发现，如果给定的端点仅同步提供呼叫服务，那么它看起来像是一个可靠的指标。接口也可能有效，但由于可以同时有多个 COM 服务器 运行 使用相同的接口 GUID，因此它不是一个可靠的指标。我认为它不会比给定数据好多少。为什么您如此热衷于 RPC 服务器部分？通常，您只会查看很长的客户端时间，这无论如何都足以触发更深入的分析。您是否正在寻找 RPC 基础设施内部的问题？