Fast polling for L1 header subscription

[syntrust]

Addressing #485

Cause 3: A slow rate of polling L1 client

Tested

• downloader get the second latest block with fewer seconds delay (should work with Delay submit the mining transaction to avoid empty blockhash #487 for latest block)
• miner works successfully
• disabled miner works successfully
• can use --l1.rpc ws://65.108.230.142:8546 for possibly better performance.

More test results added as comments.

[syntrust]

Tested with change fc84cbc

WARN [01-20|11:17:10.674] Notifying subscribers of new head        height=10,082,248 headTime=11:17:00 head=63eeae..b92482
WARN [01-20|11:17:10.674] Scheduled next poll                      queryDur=354.399105ms delay=1.880285105s
WARN [01-20|11:17:12.909] Notifying subscribers of new head        height=10,082,249 headTime=11:17:12 head=cc0be3..79d1e7
WARN [01-20|11:17:12.909] Scheduled next poll                      queryDur=354.083328ms delay=11.644535328s
WARN [01-20|11:17:24.912] Notifying subscribers of new head        height=10,082,250 headTime=11:17:24 head=0f8fa4..3428ea
WARN [01-20|11:17:24.912] Scheduled next poll                      queryDur=356.806468ms delay=11.644575468s
WARN [01-20|11:17:36.918] Scheduled next poll                      queryDur=361.455406ms delay=200ms
WARN [01-20|11:17:37.491] Notifying subscribers of new head        height=10,082,251 headTime=11:17:36 head=386fff..8634c3
WARN [01-20|11:17:37.492] Scheduled next poll                      queryDur=372.401541ms delay=11.080396541s
WARN [01-20|11:17:48.932] Notifying subscribers of new head        height=10,082,252 headTime=11:17:48 head=43a4f9..8427f3
WARN [01-20|11:17:48.932] Scheduled next poll                      queryDur=359.917962ms delay=11.627179962s
WARN [01-20|11:18:00.920] Notifying subscribers of new head        height=10,082,253 headTime=11:18:00 head=c84c8d..b11896
WARN [01-20|11:18:00.920] Scheduled next poll                      queryDur=360.382734ms delay=11.639593734s
WARN [01-20|11:18:12.915] Scheduled next poll                      queryDur=354.802627ms delay=200ms
WARN [01-20|11:18:13.467] Notifying subscribers of new head        height=10,082,254 headTime=11:18:12 head=d952be..9ab59b
WARN [01-20|11:18:13.467] Scheduled next poll                      queryDur=351.547972ms delay=11.083905972s
WARN [01-20|11:18:24.903] Notifying subscribers of new head        height=10,082,255 headTime=11:18:24 head=2a6315..07b61f
WARN [01-20|11:18:24.903] Scheduled next poll                      queryDur=350.420548ms delay=11.647192548s
WARN [01-20|11:18:36.903] Notifying subscribers of new head        height=10,082,256 headTime=11:18:36 head=337c09..2d2def
WARN [01-20|11:18:36.903] Scheduled next poll                      queryDur=351.843716ms delay=11.648225716s
WARN [01-20|11:18:48.903] Notifying subscribers of new head        height=10,082,257 headTime=11:18:48 head=71f6e3..6a2dd9
WARN [01-20|11:18:48.903] Scheduled next poll                      queryDur=351.078102ms delay=11.647704102s
WARN [01-20|11:19:00.900] Notifying subscribers of new head        height=10,082,258 headTime=11:19:00 head=bed0ef..8b88a2
WARN [01-20|11:19:00.900] Scheduled next poll                      queryDur=347.944736ms delay=11.647611736s
WARN [01-20|11:19:12.911] Notifying subscribers of new head        height=10,082,259 headTime=11:19:12 head=df5c4f..400f5d
WARN [01-20|11:19:12.911] Scheduled next poll                      queryDur=362.826971ms delay=11.651117971s
WARN [01-20|11:19:24.924] Scheduled next poll                      queryDur=361.136718ms delay=200ms
WARN [01-20|11:19:25.489] Notifying subscribers of new head        height=10,082,260 headTime=11:19:24 head=1b2d3b..165c9c
WARN [01-20|11:19:25.489] Scheduled next poll                      queryDur=363.95773ms  delay=11.07492773s
WARN [01-20|11:19:36.925] Notifying subscribers of new head        height=10,082,261 headTime=11:19:36 head=2febbc..059fd7
WARN [01-20|11:19:36.925] Scheduled next poll                      queryDur=360.936474ms delay=11.635201474s
WARN [01-20|11:19:48.922] Notifying subscribers of new head        height=10,082,262 headTime=11:19:48 head=3d6163..6982b2

Most blocks can be retrieved in under a second, but two polls may be required on occasion.

We can balance '1 poll per slot' and 'block time delay' by adjusting 'minDelay'. For example, when const minDelay = 500 * time.Millisecond, we get every block in 1 poll stably, but the block time delay is 1.2~1.3 seconds:

WARN [01-20|11:12:27.797] Notifying subscribers of new head        height=10,082,225 headTime=11:12:24 head=a89dd0..0e807a
WARN [01-20|11:12:27.797] Scheduled next poll                      queryDur=356.147954ms delay=9.058751954s
INFO [01-20|11:12:28.143] Allocated cache and file handles         database=test/l1/es-data/ethstoragedata cache=2.00GiB handles=8196
INFO [01-20|11:12:28.442] New local node record                    seq=1,760,519,630,143 id=4de1d52678f80436 ip=198.18.192.172 udp=30307 tcp=9224
WARN [01-20|11:12:37.206] Notifying subscribers of new head        height=10,082,226 headTime=11:12:36 head=02d3c7..7679cc
WARN [01-20|11:12:37.206] Scheduled next poll                      queryDur=349.781326ms delay=11.643175326s
WARN [01-20|11:12:49.200] Notifying subscribers of new head        height=10,082,227 headTime=11:12:48 head=e37e59..0e845d
WARN [01-20|11:12:49.200] Scheduled next poll                      queryDur=349.856118ms delay=11.648954118s
WARN [01-20|11:13:01.212] Notifying subscribers of new head        height=10,082,228 headTime=11:13:00 head=9f3e07..f705a4
WARN [01-20|11:13:01.212] Scheduled next poll                      queryDur=361.656314ms delay=11.648938314s
WARN [01-20|11:13:13.222] Notifying subscribers of new head        height=10,082,229 headTime=11:13:12 head=13ecc2..2f1654
WARN [01-20|11:13:13.222] Scheduled next poll                      queryDur=360.545752ms delay=11.637895752s
WARN [01-20|11:13:25.219] Notifying subscribers of new head        height=10,082,230 headTime=11:13:24 head=d01d49..d9f61c
WARN [01-20|11:13:25.219] Scheduled next poll                      queryDur=357.980555ms delay=11.638493555s
WARN [01-20|11:13:37.210] Notifying subscribers of new head        height=10,082,231 headTime=11:13:36 head=596953..05d676
WARN [01-20|11:13:37.210] Scheduled next poll                      queryDur=351.332329ms delay=11.640969329s
WARN [01-20|11:13:49.200] Notifying subscribers of new head        height=10,082,232 headTime=11:13:48 head=992794..f11fd7
WARN [01-20|11:13:49.201] Scheduled next poll                      queryDur=348.729727ms delay=11.647771727s
WARN [01-20|11:14:01.203] Notifying subscribers of new head        height=10,082,233 headTime=11:14:00 head=6233a6..24f2c6
WARN [01-20|11:14:01.203] Scheduled next poll                      queryDur=353.528599ms delay=11.649913599s
WARN [01-20|11:14:13.208] Notifying subscribers of new head        height=10,082,234 headTime=11:14:12 head=9326b9..a99d3d
WARN [01-20|11:14:13.208] Scheduled next poll                      queryDur=354.298669ms delay=11.646151669s
WARN [01-20|11:14:25.210] Notifying subscribers of new head        height=10,082,235 headTime=11:14:24 head=4cbcdc..11c780
WARN [01-20|11:14:25.210] Scheduled next poll                      queryDur=354.717018ms delay=11.644412018s
WARN [01-20|11:14:37.211] Notifying subscribers of new head        height=10,082,236 headTime=11:14:36 head=e34d55..3c22f5
WARN [01-20|11:14:37.211] Scheduled next poll                      queryDur=355.949754ms delay=11.644435754s
WARN [01-20|11:14:49.212] Notifying subscribers of new head        height=10,082,237 headTime=11:14:48 head=b53bf0..b43ecb
WARN [01-20|11:14:49.212] Scheduled next poll                      queryDur=355.064569ms delay=11.642713569s
WARN [01-20|11:15:01.214] Notifying subscribers of new head        height=10,082,238 headTime=11:15:00 head=f54b67..da893b
WARN [01-20|11:15:01.214] Scheduled next poll                      queryDur=358.498651ms delay=11.643840651s
WARN [01-20|11:15:13.221] Notifying subscribers of new head        height=10,082,239 headTime=11:15:12 head=1e8635..20618b
WARN [01-20|11:15:13.221] Scheduled next poll                      queryDur=361.87617ms  delay=11.64071917s
WARN [01-20|11:15:25.221] Notifying subscribers of new head        height=10,082,240 headTime=11:15:24 head=c8ed6d..f6953a
WARN [01-20|11:15:25.221] Scheduled next poll                      queryDur=358.298586ms delay=11.636739586s
WARN [01-20|11:15:37.210] Notifying subscribers of new head        height=10,082,241 headTime=11:15:36 head=51d662..ab22de
WARN [01-20|11:15:37.210] Scheduled next poll                      queryDur=351.353243ms delay=11.640883243s

[syntrust]

Test results on AX101 with the last commit: polling once per slot, and a block time delay of 1 second.

INFO [01-20|11:02:11.832] Allocated cache and file handles         database=es-data/ethstoragedata cache=2.00GiB handles=8196
WARN [01-20|11:02:11.832] Notifying subscribers of new head        height=10,084,244 headTime=11:02:00 head=9de495..9d73c3
WARN [01-20|11:02:11.832] Scheduled next poll                      delay=1.167666824s
INFO [01-20|11:02:11.860] New local node record                    seq=1,757,943,517,291 id=cda2d4200e53994e ip=65.109.50.145 udp=30405 tcp=9333
WARN [01-20|11:02:13.002] Notifying subscribers of new head        height=10,084,245 headTime=11:02:12 head=f163cd..8dd986
WARN [01-20|11:02:13.002] Scheduled next poll                      delay=11.997442287s
WARN [01-20|11:02:25.002] Notifying subscribers of new head        height=10,084,246 headTime=11:02:24 head=77a6d3..d3af0d
WARN [01-20|11:02:25.002] Scheduled next poll                      delay=11.997821465s
WARN [01-20|11:02:37.002] Notifying subscribers of new head        height=10,084,247 headTime=11:02:36 head=0984d6..9f53b4
WARN [01-20|11:02:37.002] Scheduled next poll                      delay=11.997784209s
WARN [01-20|11:02:49.002] Notifying subscribers of new head        height=10,084,248 headTime=11:02:48 head=2c58c8..d55f63
WARN [01-20|11:02:49.002] Scheduled next poll                      delay=11.997780566s
WARN [01-20|11:03:01.002] Notifying subscribers of new head        height=10,084,249 headTime=11:03:00 head=c41f6c..87a12f
WARN [01-20|11:03:01.002] Scheduled next poll                      delay=11.997610082s
WARN [01-20|11:03:13.002] Scheduled next poll                      delay=1s
WARN [01-20|11:03:14.005] Notifying subscribers of new head        height=10,084,250 headTime=11:03:12 head=f083e5..f7a151
WARN [01-20|11:03:14.005] Scheduled next poll                      delay=10.994419737s
WARN [01-20|11:03:25.001] Notifying subscribers of new head        height=10,084,251 headTime=11:03:24 head=c9e64e..567c91
WARN [01-20|11:03:25.001] Scheduled next poll                      delay=11.998207808s
WARN [01-20|11:03:37.001] Notifying subscribers of new head        height=10,084,252 headTime=11:03:36 head=928797..51033a
WARN [01-20|11:03:37.001] Scheduled next poll                      delay=11.998073092s
WARN [01-20|11:03:49.001] Notifying subscribers of new head        height=10,084,253 headTime=11:03:48 head=1e05b6..d7baba
WARN [01-20|11:03:49.001] Scheduled next poll                      delay=11.99840288s
WARN [01-20|11:04:01.002] Notifying subscribers of new head        height=10,084,254 headTime=11:04:00 head=a7cbab..5a651d
WARN [01-20|11:04:01.002] Scheduled next poll                      delay=11.997617111s
WARN [01-20|11:04:13.002] Notifying subscribers of new head        height=10,084,255 headTime=11:04:12 head=34d58e..f34e36
WARN [01-20|11:04:13.002] Scheduled next poll                      delay=11.997841431s
WARN [01-20|11:04:25.001] Notifying subscribers of new head        height=10,084,256 headTime=11:04:24 head=8dd1c5..21cdde
WARN [01-20|11:04:25.002] Scheduled next poll                      delay=11.997999006s

[qzhodl]

Do we have any test results showing the current latency for retrieving downloaded blobs via our RPC?

[syntrust]

Do we have any test results showing the current latency for retrieving downloaded blobs via our RPC?

Will update the issue with the test results.