How to read sla trace logs to understand packet loss and latency calculation

This KB provides a high-level overview of how SLA metrics are calculated and displayed in sla-metrics, and serves as a quick reference to verify—during a call—whether packets are being exchanged and values are computed correctly.

SLA packets are exchanged between devices per access circuit. To analyze them, enable debug logs and packet-trace vxlan-transit on both devices, as outlined in the existing KB.

https://support.versa-networks.com/a/solutions/articles/23000028606?portalId=23000007779

Each SLA session is initiated independently on both sides, using rotating sequence numbers from 0–29, after which they reset to 0. There are two main SLA packet types:

• VSM (request)
• VSR (response)

The three key log lines to observe are: VSM request, VSR response, and Compute metrics.

When a VSR is generated, the sender includes tx_timestampf and tx_framecountf. On the receiver side, the log entry “Processing VSM PDU” displays both the original sender values and additional receiver-side fields: rx_timestampf, tx_timestampb, rx_framecountf, and tx_framecountb. This combined data forms the actual VSR packet sent back to the sender. On the sender, the returned VSR response printed line will also include rx_framecountb added by the sender when the VSR packet is received , completing the SLA measurement.

Legend

When troubleshooting live you can run the below commands on sender and receiver side to extract these values directly in a tail or you can use the second set of commands if you are checking from a debug trace file. Make sure you match the seqn no.

In the below you can clearly see that we have seq 7,8,9,10,11 but the seq number 9 did not receive a response on the sender side , on the reciever side we see that it received the VSR and the VSM was sent out. That is why we see the rev loss value has changed and become nonzero.

Sender 

tail -f /var/log/versa/versa-pkttrace.log | egrep -i " Send SLAM VSM PDU|Received VSR PDU| Compute metrics"

2025-10-23 12:50:49.303 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x10825bcc0/1] vs_eoam_slam_vsm_pdu_generate:1908 Send SLAM VSM PDU:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 fc 0 state 1 seqno 7 tx_timestampf 1761187774319 tx_framecountf 564364

2025-10-23 12:50:49.310 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x10e12d180/1] vs_eoam_slam_vsr_pdu_process:2517 Received VSR PDU oui 42359  src 01:00:00:00:00:02  dest 66:00:00:00:00:02  tenant 1 fc 0 seqno 7 tx_win 3 rx_win 2 tx_timestampf 1761187774319 rx_timestampf 1761204046408 tx_timestampb 1761204046408 rx_timestampb 1761187774326 tx_framecountf 564364 rx_framecountf 564381 tx_framecountb 68433 rx_framecountb 68388

2025-10-23 12:50:49.310 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x10e12d180/1] vs_eoam_slam_compute_delay_loss:2370 Compute metrics:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 seqno: 7 2-way delay: 7 fwd delay var: 0 rev delay var: 1 fwd loss: 0 (sent 20 rcvd 20 loss 0) rev loss: 1 (sent 4 rcvd 3 loss 1)fwd loss ratio: 0 rev loss ratio: 25

2025-10-23 12:50:59.324 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x107e6f640/1] vs_eoam_slam_vsm_pdu_generate:1908 Send SLAM VSM PDU:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 fc 0 state 1 seqno 8 tx_timestampf 1761187784340 tx_framecountf 564542

2025-10-23 12:50:59.331 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x109bc4800/1] vs_eoam_slam_vsr_pdu_process:2517 Received VSR PDU oui 42359  src 01:00:00:00:00:02  dest 66:00:00:00:00:02  tenant 1 fc 0 seqno 8 tx_win 0 rx_win 3 tx_timestampf 1761187784340 rx_timestampf 1761204056429 tx_timestampb 1761204056429 rx_timestampb 1761187784347 tx_framecountf 564542 rx_framecountf 564559 tx_framecountb 68438 rx_framecountb 68392

2025-10-23 12:50:59.331 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x109bc4800/1] vs_eoam_slam_compute_delay_loss:2370 Compute metrics:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 seqno: 8 2-way delay: 7 fwd delay var: 0 rev delay var: 0 fwd loss: 0 (sent 178 rcvd 178 loss 0) rev loss: 1 (sent 5 rcvd 4 loss 1)fwd loss ratio: 0 rev loss ratio: 20

2025-10-23 12:51:09.332 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x10472a6c0/1] vs_eoam_slam_vsm_pdu_generate:1908 Send SLAM VSM PDU:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 fc 0 state 1 seqno 9 tx_timestampf 1761187794348 tx_framecountf 564563

2025-10-23 12:51:19.362 DEBUG [0x101] [Tenant: 1][0x00000000 1][0x10a5c39c0/1] vs_eoam_slam_vsm_pdu_generate:1908 Send SLAM VSM PDU:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 fc 0 state 1 seqno 10 tx_timestampf 1761187804378 tx_framecountf 564580

2025-10-23 12:51:19.369 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x109de6580/1] vs_eoam_slam_vsr_pdu_process:2517 Received VSR PDU oui 42359  src 01:00:00:00:00:02  dest 66:00:00:00:00:02  tenant 1 fc 0 seqno 10 tx_win 2 rx_win 1 tx_timestampf 1761187804378 rx_timestampf 1761204076468 tx_timestampb 1761204076468 rx_timestampb 1761187804385 tx_framecountf 564580 rx_framecountf 564597 tx_framecountb 68447 rx_framecountb 68398

2025-10-23 12:51:19.369 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x109de6580/1] vs_eoam_slam_compute_delay_loss:2370 Compute metrics:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 seqno: 10 2-way delay: 7 fwd delay var: 1 rev delay var: 1 fwd loss: 0 (sent 38 rcvd 38 loss 0) rev loss: 3 (sent 9 rcvd 6 loss 3)fwd loss ratio: 0 rev loss ratio: 33

2025-10-23 12:51:29.378 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x1060d5d00/1] vs_eoam_slam_vsm_pdu_generate:1908 Send SLAM VSM PDU:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 fc 0 state 1 seqno 11 tx_timestampf 1761187814394 tx_framecountf 56460

2025-10-23 12:51:29.385 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x1017c2b80/1] vs_eoam_slam_vsr_pdu_process:2517 Received VSR PDU oui 42359  src 01:00:00:00:00:02  dest 66:00:00:00:00:02  tenant 1 fc 0 seqno 11 tx_win 3 rx_win 2 tx_timestampf 1761187814394 rx_timestampf 1761204086483 tx_timestampb 1761204086483 rx_timestampb 1761187814401 tx_framecountf 564601 rx_framecountf 564618 tx_framecountb 68451 rx_framecountb 68402

2025-10-23 12:51:29.385 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x1017c2b80/1] vs_eoam_slam_compute_delay_loss:2370 Compute metrics:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 seqno: 11 2-way delay: 7 fwd delay var: 1 rev delay var: 1 fwd loss: 0 (sent 21 rcvd 21 loss 0) rev loss: 0 (sent 4 rcvd 4 loss 0)fwd loss ratio: 0 rev loss ratio: 0

Receiver

tail -f versa-pkttrace.log | egrep -i "Processing VSM PDU oui|Send slam vsr response"

2025-10-23 12:50:47.126 DEBUG [0x101] [Tenant: 2][0x00000000 1][0x103fa9c80/1] vs_eoam_slam_vsm_pdu_process:2165 Processing VSM PDU oui 42359  src: 01:00:00:00:00:02  dest: 66:00:00:00:00:02  tenant: 2 fc 0 seqno 7 tx_win 3 rx_win 2  tx_timestampf: 1761187774319 rx_timestampf: 1761204046408   tx_timestampb: 1761204046408   tx_framecountf: 564364   rx_framecountf: 564381 tx_framecountb 68433

2025-10-23 12:50:47.126 DEBUG [0x101] [Tenant: 2][0x00000000 1][0x103fa9c80/1] vs_eoam_slam_send_sdwan_vsr_pdu:1677 Send slam vsr response, ifp:dtvi-0/7318, ack_id:34

2025-10-23 12:50:57.147 DEBUG [0x101] [Tenant: 2][0x00000000 0][0x101347d00/1] vs_eoam_slam_vsm_pdu_process:2165 Processing VSM PDU oui 42359  src: 01:00:00:00:00:02  dest: 66:00:00:00:00:02  tenant: 2 fc 0 seqno 8 tx_win 0 rx_win 3  tx_timestampf: 1761187784340 rx_timestampf: 1761204056429   tx_timestampb: 1761204056429   tx_framecountf: 564542   rx_framecountf: 564559 tx_framecountb 68438

2025-10-23 12:50:57.147 DEBUG [0x101] [Tenant: 2][0x00000000 0][0x101347d00/1] vs_eoam_slam_send_sdwan_vsr_pdu:1677 Send slam vsr response, ifp:dtvi-0/7318, ack_id:34

2025-10-23 12:51:07.154 DEBUG [0x101] [Tenant: 2][0x00000000 0][0x10b12dfc0/1] vs_eoam_slam_vsm_pdu_process:2165 Processing VSM PDU oui 42359  src: 01:00:00:00:00:02  dest: 66:00:00:00:00:02  tenant: 2 fc 0 seqno 9 tx_win 1 rx_win 0  tx_timestampf: 1761187794348 rx_timestampf: 1761204066437   tx_timestampb: 1761204066437   tx_framecountf: 564563   rx_framecountf: 564580 tx_framecountb 68441

2025-10-23 12:51:07.155 DEBUG [0x101] [Tenant: 2][0x00000000 0][0x10b12dfc0/1] vs_eoam_slam_send_sdwan_vsr_pdu:1677 Send slam vsr response, ifp:dtvi-0/7318, ack_id:34

2025-10-23 12:51:17.185 DEBUG [0x101] [Tenant: 2][0x00000000 1][0x10aa67600/1] vs_eoam_slam_vsm_pdu_process:2165 Processing VSM PDU oui 42359  src: 01:00:00:00:00:02  dest: 66:00:00:00:00:02  tenant: 2 fc 0 seqno 10 tx_win 2 rx_win 1  tx_timestampf: 1761187804378 rx_timestampf: 1761204076468   tx_timestampb: 1761204076468   tx_framecountf: 564580   rx_framecountf: 564597 tx_framecountb 68447

2025-10-23 12:51:17.185 DEBUG [0x101] [Tenant: 2][0x00000000 1][0x10aa67600/1] vs_eoam_slam_send_sdwan_vsr_pdu:1677 Send slam vsr response, ifp:dtvi-0/7318, ack_id:34

2025-10-23 12:51:27.201 DEBUG [0x101] [Tenant: 2][0x00000000 1][0x10a8cdcc0/1] vs_eoam_slam_vsm_pdu_process:2165 Processing VSM PDU oui 42359  src: 01:00:00:00:00:02  dest: 66:00:00:00:00:02  tenant: 2 fc 0 seqno 11 tx_win 3 rx_win 2  tx_timestampf: 1761187814394 rx_timestampf: 1761204086483   tx_timestampb: 1761204086483   tx_framecountf: 564601   rx_framecountf: 564618 tx_framecountb 68451

2025-10-23 12:51:27.201 DEBUG [0x101] [Tenant: 2][0x00000000 1][0x10a8cdcc0/1] vs_eoam_slam_send_sdwan_vsr_pdu:1677 Send slam vsr response, ifp:dtvi-0/7318, ack_id:34

Side-note- If looking at logs from the tech support this might make it easier, on the sender side.

cat versa-pkttrace.log| grep -i "Received VSR PDU" | awk '{print $1,$2,$22,$23,$28,$29,$30,$31,$32,$33,$34,$35,$36,$37,$38,$39,$40,$41,$42,$43,$44}' | column -t

cat versa-pkttrace.log | grep -i "compute" |  awk '{print $1,$2,$17,$18,$19,$20,$21,$22,$23,$27,$28,$29,$30,$31,$32,$33,$34,$35,$36,$37,$38,$39,$40,$41,$42,$43,$44,$45,$46,$47,$48,$49,$50,$51,$52,$53,$54,$55,$56}'

• Delay Calculation

2_way_delay = ((rx_timestampb - tx_timestampf) - (tx_timestampb - rx_timestampf))

Key point to note is that when looking at metrics your POV should be from the sender side.Delay is calculated as a feedback loop so the timestamps taken into consideration is our own i.e the time I sent the VSR (Tx-timestampf) and the time that I received the VSM (Rx-timestampb) hence this is taking into consideration only our clock. The second part of the equation is basically the time the reciever took to process and create the response VSR.

Lets take for seq8

2025-10-23 12:50:59.331 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x109bc4800/1] vs_eoam_slam_vsr_pdu_process:2517 Received VSR PDU oui 42359  src 01:00:00:00:00:02  dest 66:00:00:00:00:02  tenant 1 fc 0 seqno 8 tx_win 0 rx_win 3 tx_timestampf 1761187784340 rx_timestampf 1761204056429 tx_timestampb 1761204056429 rx_timestampb 1761187784347 tx_framecountf 564542 rx_framecountf 564559 tx_framecountb 68438 rx_framecountb 68392

For Delay

2-way delay= ((1761187784347 - 1761187784340) - (1761204056429 - 1761204056429)) = (7 - 0) = 7 µs 

2025-10-23 12:50:59.331 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x109bc4800/1] vs_eoam_slam_compute_delay_loss:2370 Compute metrics:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 seqno: 8 2-way delay: 7 fwd delay var: 0 rev delay var: 0 fwd loss: 0 (sent 178 rcvd 178 loss 0) rev loss: 1 (sent 5 rcvd 4 loss 1)fwd loss ratio: 0 rev loss ratio: 20

• Loss Calculation

Loss is calculated based on packets counted between sequences, so when calculating the loss values it will take into consideration the values for seq 7 and seq 8 for calculating the loss for seq8

Fwd loss=(tx_framecountf_curr - tx_framecountf_prev) - (rx_framecountf_curr - rx_framecountf_prev)= (564542 - 564364) - (564559 - 564381)= 178 - 178 = 0

fwd loss ratio = 0 / 178 × 100 = 0 %

Rev loss=(tx_framecountb_curr - tx_framecountb_prev) - (rx_framecountb_curr - rx_framecountb_prev)= (68438 - 68433) - (68392 - 68388)= 5 - 4 = 1

rev loss ratio = (1 / 5) × 100 = 20 %

2025-10-23 12:50:59.331 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x109bc4800/1] vs_eoam_slam_compute_delay_loss:2370 Compute metrics:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 seqno: 8 2-way delay: 7 fwd delay var: 0 rev delay var: 0 fwd loss: 0 (sent 178 rcvd 178 loss 0) rev loss: 1 (sent 5 rcvd 4 loss 1)fwd loss ratio: 0 rev loss ratio: 20

• Lets take another example for seq10 when seq9 was missed, in this case since seq9 was missed it will use value of seq8.

Fwd loss=(tx_framecountf_curr − tx_framecountf_prev) − (rx_framecountf_curr − rx_framecountf_prev)=(564580 − 564542) − (564597 − 564559)= 38 − 38 = 0

Fwd loss ratio= (0 / 38) × 100 = 0 %

Rev loss=(tx_framecountb_curr − tx_framecountb_prev) − (rx_framecountb_curr − rx_framecountb_prev)=(68447 − 68438) − (68398 − 68392)= 9 − 6 = 3

Rev loss ratio = (3 / 9) × 100 = 33.33 %

2025-10-23 12:51:19.369 DEBUG [0x101] [Tenant: 1][0x00000000 0][0x109de6580/1] vs_eoam_slam_compute_delay_loss:2370 Compute metrics:  src: 66:00:00:00:00:02  dest: 01:00:00:00:00:02  tenant: 1 seqno: 10 2-way delay: 7 fwd delay var: 1 rev delay var: 1 fwd loss: 0 (sent 38 rcvd 38 loss 0) rev loss: 3 (sent 9 rcvd 6 loss 3)fwd loss ratio: 0 rev loss ratio: 33