We performed load testing a of new application with a client recently and a recurring question repeatedly came up: “How long was the transaction in OLS.Switch and how long was it at the endpoint ?”

It is an important question – one that is used to monitor application performance as well as to assist in troubleshooting purposes – and one we can clearly answer – the transaction took – a total of 5.6 seconds – and we waited up to our configured endpoint timeout of 5 seconds before we timed-out the transaction. Or – the transaction took 156 ms – 26 ms of those against a local response simulator.

In our application we use a profiler to trace execution time of each of our Transaction Participants: In which we see in our application logs as:

A normal transaction:

  open [0/0]
  parse-request [7/7]
  create-*******-tranlog [9/16]
  populate-********-tranlog [1/17]
  validate-********* [42/59]
  validate-********* [1/60]
  validate-******** [0/60]
  create-*********-request [24/84]
  query-****** [26/110]
  prepare-**********-response [40/150]
  close [6/156]
  send-response [0/156]
  end [157/157]

A timed-out transaction:

  open [2/2]
  parse-request [23/25]
  create-*******-tranlog [91/116]
  populate-*******-tranlog [1/117]
  validate-******* [67/184]
  validate-*******-card [31/215]
  validate-************** [1/216]
  create-********-request [32/248]
  query-******* [5000/5248]
  prepare-***********-response [67/5315]
  close [284/5599]
  send-response [0/5599]
  end [5600/5600]

(* note these traces are from a test app running on my macbook and are for illustrative purposes only *)

While we can answer the question by reviewing application logs – it is harder to perform any analysis on a series of transactions, specifically for external duration. We can do currently for total duration, however – this is valuable from the device perspective for how long a transaction took to process.

Logging the external duration along with our total duration for switched-out transactions and we now have: