DataPower

DataPower

Join this online group to communicate across IBM product users and experts by sharing advice and best practices with peers and staying up to date regarding product enhancements.

 View Only

  • 1.  DataPower extended latency log analyze

    Posted 09/27/24 11:08 AM

    Hello,

    How to read for instance the datapower extended log entry? 

    ExtLatency: TS=0,HR=0,BR=1,PS=1,PS=1,RT=1,PS=1,COR=1,WSDL=1,HTM=1,CI=1,RAL=1,SE=1,PC=1,FC=1,PS=1,XS=1,IV=7001,XC=7001,PC=7001,FC=7001,PC=7001,PS=7001,RES=7001,PC=7001,FC=7001,HS=7001,FNL=7001,PC=7001,BS=7001,TC=7001, 



    ------------------------------
    Asim Khan
    ------------------------------


  • 2.  RE: DataPower extended latency log analyze

    Posted 09/27/24 11:42 AM

    Hi Asim, This appears to be from an APIC apigw "native mode" transaction, I recognize the APIC "preflow" function pattern:
    PS=1,COR=1,WSDL=1,HTM=1,CI=1,RAL=1,SE=1,PC=1,FC=1
    PS is processing start, COR is enforcement check to see if cors is being used
    WSDL is assignment of default WSDL for SOAP APIs, usually NULL
    HTM is a default HTML for assignment, usually NULL
    CI is client-id verification, APIC subscription check
    RAL is rate-limit enforcement 
    SE is security enforcement, generally client-secret
    FC is function complete for the preflow function

    The docs on these log records are found here:
    https://www.ibm.com/docs/en/datapower-gateway/10.6.x?topic=troubleshooting-latency-messages
    The next link is found on the page ^ and I include it here to specifically note the APIGW step definitions are separate
    https://www.ibm.com/docs/en/datapower-gateway/10.5.0?topic=gateway-latency-debug-data-api-assembly-actions

    You read them left to right and the milliseconds are cumulative from step to step.  The data represent the completion time of each successive step.  To determine the latency of step N you subtract the value of step N-1.  In your case the IV step, this is APIC invoke action, took 7000mS.  Your 1 mS BR step is "body received" and represents the front side transport latency.

    For completeness I will add that these records are different when created in a DataPower MultiProtocolGateway(MPGW) versus API gateway(APIGW). 



    ------------------------------
    Ivan Heninger
    ------------------------------



  • 3.  RE: DataPower extended latency log analyze

    Posted 09/27/24 12:00 PM

    Hi Asim,

    I'll give you a hint on what you're seeking, but the ExtLatency log entries can vary widely based upon the processing being reported.   Regardless of the kind of processing indicated by the various abbreviations (TS, BR, HR, etc.), all times are measured cumulatively in milliseconds from the start of the transaction.  So, the transaction you show took 7001ms to the end.   There are certainly some processing symbols I've not seen (RAL, IV..), so I'd have to see then. 

    TS = Transaction Started      I've never seen this one other than 0

    HR = Headers Received        At the beginning of the entry, this is rarely other than 0

    BR = Body Received              This is basically networking time it took to finally receive the body of the message.

    PS = Processing Started       This is when the processing of the transaction began.  This is where things  begin change, because the processing of each transaction can be difference.

    So, what's in between depends upon what your process is actually doing.

    Skipping to the end, you have again:

    PC = 7001 , which means the final processing has completed after 7001ms

    BS= 7001, All the body is returned back to the client

    TC = 7001, Transaction complete.

    You can see in your log there is a pretty significant delay between the IV = 700 and the XC = 7001.  Just subtract one from the other to get the time the XC step is taking, which is 6301ms.   Only the IV step is taking up other significant time of 699ms.

    Hope this helps.



    ------------------------------
    Joseph Morgan
    CEO - Independent
    Joseph Morgan
    Dallas TX
    ------------------------------



  • 4.  RE: DataPower extended latency log analyze

    Posted 09/27/24 02:25 PM

    Morgan,

    Please note the correction, IV is 7001, you have mentioned it has 700. Displaying the steps with significant duration, this tells me the invoke assembly action took 7001 ms, which in other words is the time taken by the backend. Is this interpretation correct? 

    ...

    XS=1,    Completed execute action (Assembly).
    IV=7001,    Invoke action (Assembly).
    XC=7001,    Started execute action (Assembly).

    ...



    ------------------------------
    Asim Khan
    ------------------------------

    Original Message


  • 5.  RE: DataPower extended latency log analyze

    Posted 09/27/24 02:09 PM
    Edited by Hermann Stamm-Wilbrandt 09/27/24 02:09 PM

    Hi,

    I once built a webtool that you can paste an extended latency line into:
    https://stamm-wilbrandt.de/en/blog/Extended_Latency_Record_Display.html

    Below that are all messages from documentation, so that the page is self-contained.



    ------------------------------
    Hermann Stamm-Wilbrandt
    Compiler Level 3 support, IBM DataPower Gateways
    IBM
    Boeblingen
    ------------------------------



  • 6.  RE: DataPower extended latency log analyze

    Posted 10/03/24 09:37 AM
    Edited by Asim Khan 10/03/24 09:37 AM

    Thanks Hermann,

    I did find the extlatency tool while googling around this topic. Based on analysis of the extlatency brek down, it seems to me IV is the time taken by backend i.e., time taken after request leave datapower until datapower gets back the response.

    ...

    XS=1,    Completed execute action (Assembly).
    IV=7001,    Invoke action (Assembly).
    XC=7001,    Started execute action (Assembly).

    ...



    ------------------------------
    Asim Khan
    ------------------------------

    Original Message


  • 7.  RE: DataPower extended latency log analyze

    Posted 10/04/24 02:10 AM

    Hi Asim

    > I did find the extlatency tool while googling around this topic
    >
    good that this tool can be found.


    > Based on analysis of the extlatency brek down, it seems to me IV is the time taken by backend i.e., time taken after request leave datapower until datapower gets back the response.
    >
    Can be, to be sure you need to take a packet capture with logging the SSL key:
    https://github.com/ibm-datapower/datapower-tutorials/blob/master/decrypt-tls-using-master-secret-logging/decrypt-tls-using-master-secret-logging.md

    Then Wireshark will tell you whether the time is spent by DataPower sending data (perhaps because backend is slow on receive), or waiting on backend, or ...



    ------------------------------
    Hermann Stamm-Wilbrandt
    Compiler Level 3 support, IBM DataPower Gateways
    IBM
    Boeblingen
    ------------------------------

    Original Message


Related Content