Can't seem to understand the ledger_time field in ledger

[Quadear 1]

Hello there,

I'm executing this simple snippet of code in order to watch for ledgers:

import WebSocket from 'ws'
import * as microtime from 'microtime'

const socket = new WebSocket('wss://xrpl.ws')
socket.on('open', () => {
  socket.send(JSON.stringify({
    command: 'subscribe',
    streams: [
      'ledger'
    ]
  }))
})

socket.on('message', (event) => {
  const message = JSON.parse(event as string)

  if (message.ledger_time) {
    console.log(`============== New Ledger ${message.ledger_index}`)
    const time = (Number(message.ledger_time) + 946684800) * 1000000 // Get the ledger timestamp at ripple Epoch, converts it to normal epoch, and puts it in μs to be compard with the microtime now
    const start = microtime.now() // gives me a timestamp at the μs
    console.log(`Ledger timestamp:${time}`)
    console.log(`Start           :${start}`)
    console.log(`Delay           :${(start - time) / 1000} Ms`)
  }
})

 

If I've understood it correctly, the ledger_time is the time at which the previous ledger has been closed. So I should have a standard and rather constant delay corresponding to the latency between me and the server. (Ledger closes the server sends the info to me).

But I'm not observing that AT ALL. The Delay varies between - 1s (Yes I know its negative, it's bothering me too) and 8s Roughly. Small exemple below:

============== New Ledger 58088455
Ledger timestamp:1599723590000000
Start           :1599723590028785
Delay           :28.785 Ms
============== New Ledger 58088456
Ledger timestamp:1599723591000000
Start           :1599723594046032
Delay           :3046.032 Ms
============== New Ledger 58088457
Ledger timestamp:1599723592000000
Start           :1599723597731303
Delay           :5731.303 Ms
============== New Ledger 58088458
Ledger timestamp:1599723600000000
Start           :1599723601622806
Delay           :1622.806 Ms
============== New Ledger 58088459
Ledger timestamp:1599723601000000
Start           :1599723605498625
Delay           :4498.625 Ms
============== New Ledger 58088460
Ledger timestamp:1599723610000000
Start           :1599723609473421
Delay           :-526.579 Ms
============== New Ledger 58088461
Ledger timestamp:1599723611000000
Start           :1599723613457028
Delay           :2457.028 Ms

How can I explain those ?

How can the ledger.ledger_time can sometimes be In the future ?

Can I have an event that ticks every new ledger ?

Thanks,

[Lumpy 271]

@mDuo13  ?

[jlr 134]

Hi @Quadear,

Your own time and the node time are not synchronized. Your server and XRPL node time must be different.

If you check only the ledger_time you will see there is no mixing in timestamps.  

jlr@jlr:~$ date -d@1599723590
Thu 10 Sep 09:39:50 CEST 2020
jlr@jlr:~$ date -d@1599723591
Thu 10 Sep 09:39:51 CEST 2020
jlr@jlr:~$ date -d@1599723592
Thu 10 Sep 09:39:52 CEST 2020
jlr@jlr:~$ date -d@1599723600
Thu 10 Sep 09:40:00 CEST 2020
jlr@jlr:~$ date -d@1599723601
Thu 10 Sep 09:40:01 CEST 2020
jlr@jlr:~$ date -d@1599723610
Thu 10 Sep 09:40:10 CEST 2020
jlr@jlr:~$ date -d@1599723611
Thu 10 Sep 09:40:11 CEST 2020
 

[Quadear 1]

Hi @jlr,

Even if my time and the node time aren't synchronised, I expect the gap between them to be linear.

The problem is not in the ledger time, the problem is that I seem to get the information of the new ledger in a completly random delay, and that's what bothering me, since I'm requesting the same server, and such, I should have roughly the same delay each ledger.

The documentation says:

ledger_time 	Number 	The time this ledger was closed, in seconds since the Ripple Epoch

So what i understood is that when I receive a Ledger Event, it's that the ledger was just closed, and such the ledger_time field should in a fixed duration (depending of the network) in my past. I should not have such variations.

1. ====== Ledger n running
2. ====== Ledger n is closed at time ledger_time
3. ====== The information is sent from the server
4. ====== I receive the information

In my example:

Ledger 58088455 timestamp 1599723590000000
Ledger 58088456 timestamp 1599723591000000 => the ledger lasted 1s, and I took 3046.032 Ms to be notified
Ledger 58088457 timestamp 1599723592000000 => the ledger lasted 1s, and I took 5731.303 Ms to be notified
Ledger 58088458 timestamp 1599723600000000 => the ledger lasted 8s, and I took 1622.806 Ms to be notified
Ledger 58088459 timestamp 1599723601000000 => the ledger lasted 1s, and I took 4498.625 Ms to be notified

Why does it varies between 1.6s and almost 6s for me to be notified about a ledger close ? I have a ping of 200 Ms with the server, I'm expecting that delay to be notified, not around 30 times more.

Thanks,

[Sukrim 1,889]

Ledgers get batched together often when there's too much disagreement between validators and timestamps in that case get just incremented instead of re-negotiated (that's the case if a ledger is closed in just a single second, which shouldn't really be possible). I still don't see the issue with that system though, if you want to measure latency of the ledger, I'd first recommend you to run your own node locally to at least remove that hop from the equation.

[Quadear 1]

Quote

Ledgers get batched together often when there's too much disagreement between validators and timestamps in that case get just incremented instead of re-negotiated (that's the case if a ledger is closed in just a single second, which shouldn't really be possible). I still don't see the issue with that system though

There is absolutly no problems with that. The issue is indeed in latency. I can't explain that amount of variations. Running a node locally isn't an option here, I don't think just sheer distance (I usually have around 200ms of ping with my server right now, which is more than acceptable) explains the amplitude of the variations. It juste looks like I've missed something on how ledger publication works.

[mDuo13 2,456]

The close time on a ledger is approximate. This is so that individual servers don't have to have their clocks synced to the exact second. It is rounded to the close_time_resolution (10 seconds) and then incremented if it got rounded to the same close time as a previous ledger. The Ledger Header documentation covers this in a little more detail. (Note to self: link to that doc from the subscribe command and other relevant places.)

If you notice, the end of the official "close time" tends to follow something of a pattern: ...10, ...11, ...12, ....20, ...21, ...30, ...31. That's the close time resolution in effect.

[Sukrim 1,889]

15 hours ago, Quadear said:

There is absolutly no problems with that. The issue is indeed in latency.

Prove it.

Your tests just shows that it is NOT latency, but the fact that timestamps are not exact, especially since ledgers seem to arrive about 3-4 seconds apart which is the expected behavior and likely the actual close time.

[Quadear 1]

54 minutes ago, mDuo13 said:

The close time on a ledger is approximate. This is so that individual servers don't have to have their clocks synced to the exact second. It is rounded to the close_time_resolution (10 seconds) and then incremented if it got rounded to the same close time as a previous ledger. The Ledger Header documentation covers this in a little more detail. (Note to self: link to that doc from the subscribe command and other relevant places.)

Thanks for that info, it exeplains a lot indeed.

 

28 minutes ago, Sukrim said:

Your tests just shows that it is NOT latency, but the fact that timestamps are not exact, especially since ledgers seem to arrive about 3-4 seconds apart which is the expected behavior and likely the actual close time.

Yeah, my latency is calculated using those timestamps. If they are inexacts ... So I assume there is no way to have exact timestamp for that, because every server doesn't have the same clock.