Diagnosing latency issues

Anomalous behaviour on a trading platform may include slow updates on all or some records. The Caplin Platform supports latency chaining which can help you identify the culprit component(s) of such delays. Latency chains calculate the latency incurred by each component in turn as a message passes through the components on the Caplin Platform.

Notice that your price updates includes a "Timestamp" field. This timestamp is the time at which data was received by the Pricing Adapter. In this tutorial we shall configure Liberator and Transformer to calculate time accrued relative to that timestamp as the message is propagated through the platform components.

Follow the steps below:

Before starting this tutorial please download and deploy this Mystery.zip blade.

Modify your Liberator configuration in global_config/overrides/servers/Liberator/etc/rttpd.conf

latency-chain-enable TRUE
latency-chain-name liberator
latency-chain-init-ts-field Timestamp
latency-chain-list-event-field LTY_LIST_EVENT
latency-chain-list-ts-field LTY_LIST_TS

Modify your Transformer configuration in the same way in global_config/overrides/servers/Transformer/etc/transformer.conf (with latency-chain-name = 'transformer').

The LTY_LIST_EVENT and LTY_LIST_TS are two fields which will be added to each message. The value in LTY_LIST_EVENT will be a comma-separated list of all the components through which the message has passed on the platform. That in LTY_LIST_TS will be a corresponding list with the latency (in ms) accrued at each stage. These values are calculated against the existing Timestamp field.
Restart your trading platform and use Liberator Explorer to request /FX/GBPUSD. You will now notice the two new fields added to the data updates. "transformer_E,transformer_X,liberator_E" represent the time the message entered Transformer, exited Transformer and entered Liberator respectively. The latency associated with each should be negligible.
Next, request /FX/JPYAUD. You will notice that data for this record updates at a very slow rate. The latency chain fields will indicate at which point in the messages' transit this is happening:
```
LTY_LIST_EVENT: "transformer_E,transformer_T,transformer_L,transformer_S,transformer_X,liberator_E"
    LTY_LIST_TS: "1,1,2,2405,2405,2405"
```
This latency chain indicates that when the message is received by Transformer, it is processed by a module which introduces approximately 2 seconds delay in the transfer of the message. transformer_T, _L and _S indicate the times at which the message is added to the Lua pipeline queue, pulled off from the queue and processed by the Lua module respectively.
Take a look at Transformer’s pipeline.log file. This log file will reveal which module is acting on the /FX/JPYAUD messages. It is in fact the "Mystery" blade which is introducing this latency:
```
<timestamp>: INFO: Pipeline <Mystery1>, registering as listener for /FX/JPYAUD
...
<timestamp>: INFO: Thread 1: Now entering pipeline <Mystery1> for STATUS </FX/JPYAUD>
```

Configuring latency chaining adds two fields to each data update coming from the Pricing Adapter, for each user. Of course this overhead is not ideal in a production environment.

An alternative is to analyse the log files and track the update. Latency might also be added at the client-end (before display) and, in the case of trading, by the trading system at the backend. When these causes are suspected, it is common to add extra fields at the client and Integration Adapter to indicate more accurately when:

a price is received by the client
the price is displayed on screen
a message is published from the client to Liberator
a request is made from the Integration Adapter to the backend server
data from the backend server is received by the Integration Adapter

When trying to detect latency through the logs, where different components, the servers, and the client are running on different machines, it is necessary to identify whether the clocks of each machine are in sync. One way to identify this is:

via the SYNC messages between the client and the server in the StreamLink and RTTP logs respectively
```
>>> <time_RTTP_server> SYNC+OK 1380817896263 2
<time_client> - FINER : < 4r SYNC+OK 1380817896263 2
```

and via the HEARTBEAT messages between Liberator, Transformer, and the Integration Adapter

<time_transformer_to_liberator>: 127.0.0.1 > HEARTBEAT 101 15 0
<time_liberator_from_transformer>: 127.0.0.1 < HEARTBEAT 102 15 0

Try this yourself

Try tracing the latency for JPYAUD through the packet and RTTP logs.