windowsipcetwmsrpc

How to correlate RPC calls in ETW traces?

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?

Solution

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

    enter image description here

    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?

    enter image description here