Functionality exists in the QR framework to record timestamps for each request at different points in the lifecycle. This allows developers to investigate the performance of the QR cluster and the solution-specific requests. If enabled, the QR/QP will record timestamps at each point and persist the data to disk after a request is closed. Both components append data to an on-disk binary file (similar to that of a Stream tickerplant) from where it can be replayed to into memory or persisted to a historical database. The processes write to an active file and after a configurable interval, will roll the files to create a new one.
Enabling this functionality is controlled by the
timestampLogging parameter of the QR and QP instances. By default this points at
DS_QR_TIMINGS:DEFAULT which has the logging disabled.
logdir controls where the files get written to and the
rollFreq is a frequency (in seconds) of how often to roll the active log. Any consumers should replay only the rolled files and never the active ones. The filenames are in the format;
The schema used to store the timing data is called
dxQrTimings and is included with the Control package.
|requestID||long||Parent request ID|
|status||symbol||Request final status|
|clientTime||timestamp||Time assigned by client when entering request|
|qrRecv||timestamp||When request was received by QR|
|queueEntry||timestamp||When request appended to the queue|
|queueExit||timestamp||When request removed from queue|
|qrSend||timestamp||When QR dispatched to QP|
|qpRecv||timestamp||When QP receives request|
|qpSend||timestamp||When QP sends request|
|dbRecv||timestamp||When DB receives|
|dbSend||timestamp||When DB responds|
|qpRecv2||timestamp||When QP receives response|
|qpCache||timestamp||When QP caches result|
|qpSend2||timestamp||When QP sends result|
The image above shows the points at which the timestamps are recorded. Some noteworthy points are described below;
|Client Time||An optional timestamp provided by the client. For kdb+ clients, this is specified as
|Queue||Requests are appended to the queue immediately after being received, however they may not be dequeued until resources are available. The difference between the
|QP cache||When the QP receives a result, an aggregation is performed after the result is cached.
|Routed Requests||These are treated as multiple separate sub-requests and recorded as such. After entering the queue, all timestamps up to
|Timeouts||A request may timeout in two ways; either at the QR or at the QP. A timeout at the QR will occur if no sub-requests have been dispatched and at the QP if any have been. For the former case, there will be timestamps recorded up to
Example timing extraction
The following example uses a KX Stream File Watcher template to replay the QR timing logs and publish via messaging.
- Create a new instance of the
- Set up the instance template as in the image below
- Run the instance
The process will register as a publisher of
dxQrTimings and watch the QR logs directory for rolled files. When a rolled file is found, it publishes any replayed records to any subscribed processes and deletes the file when complete. The
.fw.qr.* code can be updated to change the behavior, e.g. to zip the files, you can change the last line of