none
WCF Traces - Clarification RRS feed

  • Question

  • Hello all,

    We currently are investigating performance issues between BizTalk and a call towards a Mainframe. For this, we're gathering as much statistics as possible:

    A. Timestamps from BizTalk tracking.

    B. WCF traces.

    C. Timestamps of the duration of the call on the Mainframe (through a component in-between to call transactions).

    The timings between A and C seem to have a notable difference. At most it is as if there's 200+ milliseconds lost between BizTalk and the component in-between calling the MF transactions. (note, BizTalk and the component are on the same VM, so no real network latency applies)

    I've set the WCF logging to verbose for both Messages and ServiceModel:

    <source name="System.ServiceModel" switchValue="Verbose, ActivityTracing" propagateActivity="true"> <listeners> <add name="traceListenerGeneral" /> </listeners> </source> <source name="System.ServiceModel.MessageLogging" switchValue="Verbose, ActivityTracing"> <listeners> <add name="traceListenerMessages" /> </listeners>

    </source>
          </sources>

    <system.serviceModel>
       <diagnostics wmiProviderEnabled="true">
           <messageLogging 
                logEntireMessage="true" 
                logMalformedMessages="true"
                logMessagesAtServiceLevel="true" 
                logMessagesAtTransportLevel="true"
                maxMessagesToLog="3000" 
            />
       </diagnostics>
      </system.serviceModel>

    The only element that I notice that is taking the most time is the following within the WCF traces:

    

    I am uncertain what exactly this means. I assume that once the message was read, it is sent towards its destination and is further processed. Thus, the second there, is the time it spent at its destination. (executing its action)

    General question: the timestamp between "A message was read" and "To: Executing user callback" contains the time needed to transfer the message or solely the time taken to process the action after the message was sent towards its destination?

    Thanks in advance for any tips in analyzing these traces.


    • Edited by Steven_VM Friday, November 22, 2013 10:31 AM
    Friday, November 22, 2013 10:29 AM

Answers

  • The following configuration taken from MSDN can be applied to enable tracing on your WCF service.

    <configuration>
      <system.diagnostics>
        <sources>
          <source name="System.ServiceModel"
                  switchValue="Information, ActivityTracing"
                  propagateActivity="true" >
            <listeners>
                 <add name="xml"/>
            </listeners>
          </source>
          <source name="System.ServiceModel.MessageLogging">
            <listeners>
                <add name="xml"/>
            </listeners>
          </source>
          <source name="myUserTraceSource"
                  switchValue="Information, ActivityTracing">
            <listeners>
                <add name="xml"/>
            </listeners>
          </source>
        </sources>
        <sharedListeners>
            <add name="xml"
                 type="System.Diagnostics.XmlWriterTraceListener"
                 initializeData="Error.svclog" />
        </sharedListeners>
      </system.diagnostics>
    </configuration>

    To view the log file, you can use "C:\Program Files\Microsoft SDKs\Windows\v7.0A\bin\SvcTraceViewer.exe".

    If "SvcTraceViewer.exe" is not on your system, you can download it from the "Microsoft Windows SDK for Windows 7 and .NET Framework 4" package here:

    Windows SDK Download

    You don't have to install the entire thing, just the ".NET Development / Tools" part.

    When/if it bombs out during installation with a non-sensical error, Petopas' answer to Windows 7 SDK Installation Failure solved my issue.

    Tuesday, November 26, 2013 9:20 AM