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

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

Original Message:
Sent: Fri September 27, 2024 11:08 AM
From: Asim Khan
Subject: DataPower extended latency log analyze

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

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

Original Message:
Sent: Fri September 27, 2024 11:08 AM
From: Asim Khan
Subject: DataPower extended latency log analyze

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

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:
Sent: Fri September 27, 2024 12:00 PM
From: Joseph Morgan
Subject: DataPower extended latency log analyze

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

Original Message:
Sent: Fri September 27, 2024 11:08 AM
From: Asim Khan
Subject: DataPower extended latency log analyze

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

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

Original Message:
Sent: Fri September 27, 2024 11:08 AM
From: Asim Khan
Subject: DataPower extended latency log analyze

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

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:
Sent: Fri September 27, 2024 02:08 PM
From: Hermann Stamm-Wilbrandt
Subject: DataPower extended latency log analyze

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

Original Message:
Sent: Fri September 27, 2024 11:08 AM
From: Asim Khan
Subject: DataPower extended latency log analyze

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

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:
Sent: Thu October 03, 2024 09:37 AM
From: Asim Khan
Subject: DataPower extended latency log analyze

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:
Sent: Fri September 27, 2024 02:08 PM
From: Hermann Stamm-Wilbrandt
Subject: DataPower extended latency log analyze

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

Original Message:
Sent: Fri September 27, 2024 11:08 AM
From: Asim Khan
Subject: DataPower extended latency log analyze

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