How to correlate RPC calls in ETW traces?

Question

I recorded a trace of an application performing Local RPC calls on Windows. I used xperf with the Microsoft-Windows-RPC provider enabled. After opening the trace, I realized that it's not that simple to correlate client and server calls. It will be easier to explain the problem on an example.

One of the RpcClientCall events sent by the client looks as follows:

<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>

Then comes a number of Debug events (with the same ActivityID), such as this one:

<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>

Later I may find the RpcServerCall event, which probably represents the response from the server:

<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>

This event is again followed by a number of Debug events (with the same 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>

After the call is done, I can see a win:stop events on both the client and the server, but those events have only one field: Status and the ActivityID set to the same value as the win:start event, example:

<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>

Question

Finally, my question is: how can I be 100% sure that a given RpcServerCall is a response to my initial RpcClientCall? I guess that matching by InterfaceUuid, ProcNum, Protocol and Endpoint is not enough, as there might be multiple calls to a given endpoint at the same time. I hope that maybe these Debug events can be in help here. Maybe there is another ETW provider which I should use? Or maybe there is a setting to enable RelativeActivityId?

Are you trying to find out why a RPC call takes so long or what exactly are you after? Normally you do not neet this stuff if you want to know what did block you how long. You can use Context Switch events (CPU Usage Precise) which will tell you exactly how long a thread did wait until something did finish. — Alois Kraus, Jan 06 '17 at 16:54
I'm working on a tool for displaying ETW traces for a given process: https://github.com/lowleveldesign/wtrace, and I would like to have in the output, not only calls made by the client, but also server responses. — Sebastian, Jan 06 '17 at 17:41

Alois Kraus · Accepted Answer · 2017-01-07T16:19:03.843

You can correlate the events by enabling Microsoft-Windows-RPC and group by Activity Id which will be unique for every RPC call. You then only need to correltate the start/stop events for each activity id you can have the duration in the context of your client process to correlate the duration of any RPC call.

For each Acitivity many debug events can be logged but only one start/stop tuple will be there. That should do the trick.

To correlate RPC client and server calls you need first to find the corresponding RPC client and server calls by looking at the start/stop events witht the same activity guid. For a given RpcClient with a RpcServer call you can use Field 5 (Endpoint) to group by them. At least that is what I have found is looking like a reliable indicator if a given endpoint is serving calls synchronously only. Interface might also work but since there can be more than one COM server running at the same time with the same Interface GUID it is not a reliable indicator. I do not think it will get much better than that with the given data. Why are you so keen on the RPC server part? Normally you would only look at very long client times which is sufficient to trigger a deeper analysis anyway. Are you searching for issues inside the RPC infrastructure?

Thanks for your answer. Unfortunately it does not solve the question problem. It works only on the RpcClientCall side, so this way we are able to correlate only the requests made by the client. I would like to correlate the client call with the server answer, so something common between RpcClientCall (both win:start/win:end) and RpcServerCall (both win:start/win:end) — Sebastian, Jan 07 '17 at 14:12
As I stated previously, my point is to implement the automatic detection in my tool. What you wrote is also my final guess. I'm marking your response as an answer, as it's probably not possible to go any further in the investigation. Thanks! — Sebastian, Jan 07 '17 at 16:25

How to correlate RPC calls in ETW traces?

Question

1 Answers1