flow-cli
flow-cli copied to clipboard
Published
20 hours ago •
onflow
onflow
New command line options to flow cli; `-debug` & `-tail`
I've written a simple wrapper script around the flow cli to monitor block production on internal networks. However, just for fun I ran it on mainnet but was disturbed to see very different performance in how long the results take to get dished up.
The wrapper script algorithm is as follows:
- Initially get the latest block height using flow cli.
- Then use flow cli to poll for each new block height, one by one.
- If flow cli fails to get the next block then sleep a little and try again.
- For each block height retrieved, output a line consisting of:
- Retrieval / poll timestamp.
- Block height.
- Block proposal time.
- Number of collections and transactions in the block.
- Blocks, collections, and transactions per second based upon the last 10 wall-clock seconds.
- Total wall-clock time for poll sleeps and flow cli invocations, excluding...
- ...wall-clock time for the last flow cli invocation.
Reasons to request the new -tail command line option for flow cli:
- Rather than having the overhead of the TCP connection and disconnection to the access node for each poll, it would be great if flow cli just remained connected in order to receive the info for the next block when it becomes available.
- Rather than having the overhead of flow cli polling unnecessarily for the next block, it would be great if once connected, the access node can just push updates to flow cli.
Reasons to request the new -debug command line option for flow cli:
- When polling for the next block then the
delayis suspiciously variable ranging in the example below from zero to 14.41 seconds. - When polling for the next block then the
cliseconds is suspiciously variable ranging in the example below from 0.30 to 0.86 seconds. Whereas the ping and dig times are consistently only 0.039 and 0.014 seconds. - Ideally the
-debugoption would be an aid to debug performance and return a mini-log showing where the time is spent retrieving the block data -- e.g. in various node to node communication or processing? -- fordelayand/orcliseconds.
I realize that these might be non-trivial to implement / so called 'big ticket' items. But there might be many benefits?
Example running the wrapper script against mainnet showing the variable delay and cli seconds:
$ perl ./flow-performance-tests/via-tmux/flow-cli-block-tail.pl host=access.mainnet.nodes.onflow.org:9000
1642440224.869201 Mon Jan 17 17:23:44 2022 contacting access node: access.mainnet.nodes.onflow.org:9000
1642440224.870971 Mon Jan 17 17:23:44 2022 found flow cli here: ../flow-cli/cmd/flow/flow
1642440224.871011 Mon Jan 17 17:23:44 2022 running flow cli to discover latest block using command: /home/simon_hardy_francis_dapperlabs_c/20220104-tmux/flow-cli/cmd/flow/flow blocks get latest --host access.mainnet.nodes.onflow.org:9000 --include transactions 2>&1
1642440225.413105 Mon Jan 17 17:23:45 2022 latest block height is 22899240
1642440225.413154 Mon Jan 17 17:23:45 2022 note: BPS & CPS & TPS are the average from the last 10 seconds of latest block polling activity
1642440225.413180 Mon Jan 17 17:23:45 2022 note: delay is how long the script had to re-poll before the latest block is available
1642440225.413189 Mon Jan 17 17:23:45 2022 note: cli is how long the final invocation of flow cli took to get the latset block
1642440225.413197 Mon Jan 17 17:23:45 2022 note: all time is "+0000 UTC"
1642440225.413204 poll time height proposed CX TX BPS CPS TPS delay cli
1642440225.906186 Mon Jan 17 17:23:45 2022 22899240 17:26:28.950 7 7 0.1 0.7 0.7 0.00s 0.49s
1642440226.833753 Mon Jan 17 17:23:46 2022 22899241 17:26:32.886 18 18 0.2 2.5 2.5 0.00s 0.93s
1642440227.265220 Mon Jan 17 17:23:47 2022 22899242 17:26:34.740 5 7 0.3 3.0 3.2 0.00s 0.43s
1642440227.639734 Mon Jan 17 17:23:47 2022 22899243 17:26:36.565 4 6 0.4 3.4 3.8 0.00s 0.37s
1642440230.475858 Mon Jan 17 17:23:50 2022 22899244 17:26:38.348 5 7 0.5 3.9 4.5 2.40s 0.43s
1642440245.556683 Mon Jan 17 17:24:05 2022 22899245 17:26:40.218 7 9 0.1 0.7 0.9 14.41s 0.67s
1642440245.975883 Mon Jan 17 17:24:05 2022 22899246 17:26:42.209 5 5 0.2 1.2 1.4 0.00s 0.42s
1642440247.845950 Mon Jan 17 17:24:07 2022 22899247 17:26:46.290 14 21 0.3 2.6 3.5 1.09s 0.78s
1642440248.681583 Mon Jan 17 17:24:08 2022 22899248 17:26:50.420 15 20 0.4 4.1 5.5 0.00s 0.84s
1642440249.193550 Mon Jan 17 17:24:09 2022 22899249 17:26:52.352 7 8 0.5 4.8 6.3 0.00s 0.51s
1642440249.610471 Mon Jan 17 17:24:09 2022 22899250 17:26:54.511 5 10 0.6 5.3 7.3 0.00s 0.42s
1642440252.687934 Mon Jan 17 17:24:12 2022 22899251 17:26:56.475 6 8 0.7 5.9 8.1 2.59s 0.49s
1642440253.140948 Mon Jan 17 17:24:13 2022 22899252 17:26:58.358 6 10 0.8 6.5 9.1 0.00s 0.45s
1642440253.558071 Mon Jan 17 17:24:13 2022 22899253 17:27:00.235 4 5 0.9 6.9 9.6 0.00s 0.42s
1642440254.886694 Mon Jan 17 17:24:14 2022 22899254 17:27:02.109 5 6 1.0 7.4 10.2 0.92s 0.41s
1642440255.300870 Mon Jan 17 17:24:15 2022 22899255 17:27:04.001 4 4 1.1 7.8 10.6 0.00s 0.41s
1642440257.331444 Mon Jan 17 17:24:17 2022 22899256 17:27:05.901 5 6 1.0 7.1 9.8 1.61s 0.42s
1642440259.390939 Mon Jan 17 17:24:19 2022 22899257 17:27:08.048 6 10 0.8 4.1 5.9 1.59s 0.47s
1642440269.164444 Mon Jan 17 17:24:29 2022 22899258 17:27:10.250 8 18 0.2 1.4 2.8 9.24s 0.53s
1642440269.556389 Mon Jan 17 17:24:29 2022 22899259 17:27:12.215 4 6 0.2 1.2 2.4 0.00s 0.39s
1642440270.265380 Mon Jan 17 17:24:30 2022 22899260 17:27:16.602 12 14 0.3 2.4 3.8 0.00s 0.71s
1642440270.720049 Mon Jan 17 17:24:30 2022 22899261 17:27:18.348 6 10 0.4 3.0 4.8 0.00s 0.45s
1642440271.206999 Mon Jan 17 17:24:31 2022 22899262 17:27:20.119 6 10 0.5 3.6 5.8 0.00s 0.49s
1642440280.085628 Mon Jan 17 17:24:40 2022 22899263 17:27:22.278 6 6 0.4 3.0 4.0 8.41s 0.47s
1642440280.573200 Mon Jan 17 17:24:40 2022 22899264 17:27:24.359 7 8 0.4 2.5 3.4 0.00s 0.49s
1642440281.298120 Mon Jan 17 17:24:41 2022 22899265 17:27:28.430 12 14 0.3 2.5 2.8 0.00s 0.72s
1642440291.576934 Mon Jan 17 17:24:51 2022 22899266 17:27:30.250 6 10 0.1 0.6 1.0 9.81s 0.47s
1642440293.022330 Mon Jan 17 17:24:53 2022 22899267 17:27:32.375 7 12 0.2 1.3 2.2 0.93s 0.51s
1642440293.686112 Mon Jan 17 17:24:53 2022 22899268 17:27:36.354 11 17 0.3 2.4 3.9 0.00s 0.66s
1642440294.541799 Mon Jan 17 17:24:54 2022 22899269 17:27:40.890 16 22 0.4 4.0 6.1 0.00s 0.86s
1642440300.699707 Mon Jan 17 17:25:00 2022 22899270 17:27:42.790 3 4 0.5 4.3 6.5 5.79s 0.36s
1642440301.091324 Mon Jan 17 17:25:01 2022 22899271 17:27:44.529 4 5 0.6 4.7 7.0 0.00s 0.39s
1642440301.625762 Mon Jan 17 17:25:01 2022 22899272 17:27:48.844 8 12 0.6 4.9 7.2 0.00s 0.53s
1642440303.706397 Mon Jan 17 17:25:03 2022 22899273 17:27:50.677 4 6 0.5 3.5 4.9 1.68s 0.40s
1642440304.843796 Mon Jan 17 17:25:04 2022 22899274 17:27:52.486 3 4 0.5 2.2 3.1 0.80s 0.34s
1642440306.214497 Mon Jan 17 17:25:06 2022 22899275 17:27:54.734 7 8 0.6 2.9 3.9 0.88s 0.49s
1642440308.295071 Mon Jan 17 17:25:08 2022 22899276 17:27:56.593 5 7 0.7 3.4 4.6 1.62s 0.46s
1642440308.681342 Mon Jan 17 17:25:08 2022 22899277 17:27:58.618 4 5 0.8 3.8 5.1 0.00s 0.39s
1642440314.584970 Mon Jan 17 17:25:14 2022 22899278 17:28:00.646 6 12 0.5 2.5 3.6 5.39s 0.52s
1642440314.958168 Mon Jan 17 17:25:14 2022 22899279 17:28:02.539 3 3 0.5 2.5 3.5 0.00s 0.37s
1642440317.436549 Mon Jan 17 17:25:17 2022 22899280 17:28:04.482 8 9 0.5 2.6 3.6 1.93s 0.55s
1642440317.890854 Mon Jan 17 17:25:17 2022 22899281 17:28:06.569 6 9 0.6 3.2 4.5 0.00s 0.45s
1642440319.078601 Mon Jan 17 17:25:19 2022 22899282 17:28:08.652 3 5 0.5 2.6 3.8 0.84s 0.34s
1642440319.393484 Mon Jan 17 17:25:19 2022 22899283 17:28:10.186 2 2 0.6 2.8 4.0 0.00s 0.31s
1642440321.452705 Mon Jan 17 17:25:21 2022 22899284 17:28:12.107 5 6 0.7 3.3 4.6 1.61s 0.45s
1642440326.119526 Mon Jan 17 17:25:26 2022 22899285 17:28:13.933 7 10 0.6 3.1 4.1 4.16s 0.51s
1642440328.083696 Mon Jan 17 17:25:28 2022 22899286 17:28:15.829 3 3 0.5 2.0 2.6 1.63s 0.34s
1642440328.536960 Mon Jan 17 17:25:28 2022 22899287 17:28:17.923 6 8 0.6 2.6 3.4 0.00s 0.45s
1642440335.157313 Mon Jan 17 17:25:35 2022 22899288 17:28:20.263 6 6 0.4 2.2 2.7 6.15s 0.47s
1642440336.481846 Mon Jan 17 17:25:36 2022 22899289 17:28:22.255 9 14 0.4 2.4 3.1 0.76s 0.57s
1642440336.952895 Mon Jan 17 17:25:36 2022 22899290 17:28:24.582 5 7 0.5 2.9 3.8 0.00s 0.47s
1642440337.482851 Mon Jan 17 17:25:37 2022 22899291 17:28:26.433 8 12 0.6 3.7 5.0 0.00s 0.53s
1642440342.825363 Mon Jan 17 17:25:42 2022 22899292 17:28:28.461 5 7 0.5 3.3 4.6 4.90s 0.44s
1642440343.291389 Mon Jan 17 17:25:43 2022 22899293 17:28:30.319 6 10 0.6 3.9 5.6 0.00s 0.47s
1642440343.879489 Mon Jan 17 17:25:43 2022 22899294 17:28:32.268 9 11 0.7 4.8 6.7 0.00s 0.59s
1642440345.814776 Mon Jan 17 17:25:45 2022 22899295 17:28:34.528 3 7 0.7 4.5 6.8 1.60s 0.34s
1642440347.484518 Mon Jan 17 17:25:47 2022 22899296 17:28:36.553 9 12 0.5 3.2 4.7 1.08s 0.59s
1642440357.562288 Mon Jan 17 17:25:57 2022 22899297 17:28:38.512 8 16 0.1 0.8 1.6 9.53s 0.55s
1642440357.896675 Mon Jan 17 17:25:57 2022 22899298 17:28:40.463 3 3 0.2 1.1 1.9 0.00s 0.33s
1642440358.197594 Mon Jan 17 17:25:58 2022 22899299 17:28:42.348 2 3 0.3 1.3 2.2 0.00s 0.30s
1642440358.693921 Mon Jan 17 17:25:58 2022 22899300 17:28:44.233 7 9 0.4 2.0 3.1 0.00s 0.50s
1642440359.150926 Mon Jan 17 17:25:59 2022 22899301 17:28:46.019 6 10 0.5 2.6 4.1 0.00s 0.46s
1642440359.571802 Mon Jan 17 17:25:59 2022 22899302 17:28:48.413 5 6 0.6 3.1 4.7 0.00s 0.42s
1642440368.335763 Mon Jan 17 17:26:08 2022 22899303 17:28:50.047 7 8 0.4 2.5 3.3 8.26s 0.51s
1642440368.630217 Mon Jan 17 17:26:08 2022 22899304 17:28:51.953 2 2 0.5 2.7 3.5 0.00s 0.29s
1642440369.367197 Mon Jan 17 17:26:09 2022 22899305 17:28:56.028 13 15 0.4 2.7 3.1 0.00s 0.74s
1642440379.490061 Mon Jan 17 17:26:19 2022 22899306 17:28:57.895 6 9 0.1 0.6 0.9 9.67s 0.45s
1642440379.901577 Mon Jan 17 17:26:19 2022 22899307 17:28:59.851 5 10 0.2 1.1 1.9 0.00s 0.41s
1642440380.613298 Mon Jan 17 17:26:20 2022 22899308 17:29:03.755 12 15 0.3 2.3 3.4 0.00s 0.71s
1642440381.363266 Mon Jan 17 17:26:21 2022 22899309 17:29:07.893 13 19 0.4 3.6 5.3 0.00s 0.75s
1642440381.775371 Mon Jan 17 17:26:21 2022 22899310 17:29:09.634 5 11 0.5 4.1 6.4 0.00s 0.41s
1642440382.190584 Mon Jan 17 17:26:22 2022 22899311 17:29:11.431 5 5 0.6 4.6 6.9 0.00s 0.42s
1642440390.185615 Mon Jan 17 17:26:30 2022 22899312 17:29:13.583 6 8 0.5 4.1 5.8 7.49s 0.50s
1642440390.730550 Mon Jan 17 17:26:30 2022 22899313 17:29:15.410 8 11 0.5 3.7 5.4 0.00s 0.54s
1642440391.967553 Mon Jan 17 17:26:31 2022 22899314 17:29:17.226 5 7 0.4 2.4 3.1 0.80s 0.44s
1642440393.268375 Mon Jan 17 17:26:33 2022 22899315 17:29:19.408 5 7 0.4 2.4 3.3 0.89s 0.41s
1642440393.680700 Mon Jan 17 17:26:33 2022 22899316 17:29:21.337 5 9 0.5 2.9 4.2 0.00s 0.41s
1642440394.015001 Mon Jan 17 17:26:34 2022 22899317 17:29:23.618 3 5 0.6 3.2 4.7 0.00s 0.33s
1642440397.916308 Mon Jan 17 17:26:37 2022 22899318 17:29:25.737 7 7 0.7 3.9 5.4 3.37s 0.53s
1642440398.338627 Mon Jan 17 17:26:38 2022 22899319 17:29:27.678 5 8 0.8 4.4 6.2 0.00s 0.42s
1642440399.581262 Mon Jan 17 17:26:39 2022 22899320 17:29:29.688 7 8 0.9 5.1 7.0 0.75s 0.49s
1642440404.844136 Mon Jan 17 17:26:44 2022 22899321 17:29:31.471 5 5 0.4 2.4 2.8 4.85s 0.42s
1642440406.973205 Mon Jan 17 17:26:46 2022 22899322 17:29:33.298 5 7 0.5 2.9 3.5 1.69s 0.44s
1642440407.471689 Mon Jan 17 17:26:47 2022 22899323 17:29:35.217 7 9 0.6 3.6 4.4 0.00s 0.50s
1642440407.765624 Mon Jan 17 17:26:47 2022 22899324 17:29:37.358 2 2 0.7 3.8 4.6 0.00s 0.29s
1642440412.438333 Mon Jan 17 17:26:52 2022 22899325 17:29:39.192 9 10 0.5 2.8 3.3 4.06s 0.62s
1642440415.360583 Mon Jan 17 17:26:55 2022 22899326 17:29:41.399 7 9 0.5 3.0 3.7 2.39s 0.54s
1642440415.930286 Mon Jan 17 17:26:55 2022 22899327 17:29:43.299 9 10 0.6 3.9 4.7 0.00s 0.57s
1642440416.460931 Mon Jan 17 17:26:56 2022 22899328 17:29:44.972 8 10 0.7 4.7 5.7 0.00s 0.53s
1642440420.218490 Mon Jan 17 17:27:00 2022 22899329 17:29:47.027 7 12 0.5 4.0 5.1 3.25s 0.50s
1642440420.684959 Mon Jan 17 17:27:00 2022 22899330 17:29:48.895 6 7 0.6 4.6 5.8 0.00s 0.47s
1642440422.980187 Mon Jan 17 17:27:02 2022 22899331 17:29:51.119 6 6 0.6 4.3 5.4 1.84s 0.46s
1642440423.433271 Mon Jan 17 17:27:03 2022 22899332 17:29:53.138 5 6 0.7 4.8 6.0 0.00s 0.45s
1642440433.231959 Mon Jan 17 17:27:13 2022 22899333 17:29:55.070 6 9 0.2 1.1 1.5 9.35s 0.45s
1642440433.658559 Mon Jan 17 17:27:13 2022 22899334 17:29:56.957 5 5 0.2 1.1 1.4 0.00s 0.43s
1642440436.223238 Mon Jan 17 17:27:16 2022 22899335 17:30:01.260 15 18 0.3 2.6 3.2 1.76s 0.80s
1642440436.672641 Mon Jan 17 17:27:16 2022 22899336 17:30:03.479 6 7 0.4 3.2 3.9 0.00s 0.45s
1642440437.204477 Mon Jan 17 17:27:17 2022 22899337 17:30:05.243 8 13 0.5 4.0 5.2 0.00s 0.53s
1642440442.827284 Mon Jan 17 17:27:22 2022 22899338 17:30:07.080 5 5 0.6 4.5 5.7 5.20s 0.42s
1642440443.277037 Mon Jan 17 17:27:23 2022 22899339 17:30:08.993 6 9 0.6 4.5 5.7 0.00s 0.45s
1642440448.896213 Mon Jan 17 17:27:28 2022 22899340 17:30:13.109 19 25 0.3 3.0 3.9 4.65s 0.97s
1642440449.507380 Mon Jan 17 17:27:29 2022 22899341 17:30:15.294 10 15 0.4 4.0 5.4 0.00s 0.61s
1642440449.919549 Mon Jan 17 17:27:29 2022 22899342 17:30:17.127 5 11 0.5 4.5 6.5 0.00s 0.41s
1642440451.798900 Mon Jan 17 17:27:31 2022 22899343 17:30:19.051 2 4 0.6 4.7 6.9 1.58s 0.30s
1642440452.310819 Mon Jan 17 17:27:32 2022 22899344 17:30:21.030 7 7 0.7 5.4 7.6 0.00s 0.51s
1642440452.644954 Mon Jan 17 17:27:32 2022 22899345 17:30:22.830 3 3 0.8 5.7 7.9 0.00s 0.33s
1642440457.429608 Mon Jan 17 17:27:37 2022 22899346 17:30:25.079 6 8 0.7 5.2 7.3 4.29s 0.50s
1642440458.637194 Mon Jan 17 17:27:38 2022 22899347 17:30:27.239 6 7 0.8 5.8 8.0 0.75s 0.46s
1642440465.422521 Mon Jan 17 17:27:45 2022 22899348 17:30:29.456 6 8 0.3 1.8 2.3 6.34s 0.45s
1642440465.973263 Mon Jan 17 17:27:45 2022 22899349 17:30:31.557 8 10 0.4 2.6 3.3 0.00s 0.55s
1642440469.157704 Mon Jan 17 17:27:49 2022 22899350 17:30:33.524 8 12 0.3 2.2 3.0 2.66s 0.53s
1642440469.688647 Mon Jan 17 17:27:49 2022 22899351 17:30:35.825 8 11 0.4 3.0 4.1 0.00s 0.53s
1642440470.140685 Mon Jan 17 17:27:50 2022 22899352 17:30:37.729 6 9 0.5 3.6 5.0 0.00s 0.45s
1642440471.408308 Mon Jan 17 17:27:51 2022 22899353 17:30:39.739 4 4 0.6 4.0 5.4 0.87s 0.39s
1642440473.468826 Mon Jan 17 17:27:53 2022 22899354 17:30:41.663 6 8 0.7 4.6 6.2 1.61s 0.46s
1642440475.549437 Mon Jan 17 17:27:55 2022 22899355 17:30:43.484 5 6 0.7 4.5 6.0 1.67s 0.41s
1642440476.027513 Mon Jan 17 17:27:56 2022 22899356 17:30:45.344 6 7 0.7 4.3 5.7 0.00s 0.48s
1642440478.709571 Mon Jan 17 17:27:58 2022 22899357 17:30:47.576 2 3 0.8 4.5 6.0 2.39s 0.30s
1642440479.964694 Mon Jan 17 17:27:59 2022 22899358 17:30:49.604 5 7 0.7 3.4 4.4 0.84s 0.42s
1642440482.720683 Mon Jan 17 17:28:02 2022 22899359 17:30:51.498 4 5 0.6 2.8 3.6 2.37s 0.39s
1642440483.221152 Mon Jan 17 17:28:03 2022 22899360 17:30:53.474 7 8 0.7 3.5 4.4 0.00s 0.50s
1642440486.220425 Mon Jan 17 17:28:06 2022 22899361 17:30:55.423 5 7 0.5 2.3 3.0 2.58s 0.42s
1642440492.644010 Mon Jan 17 17:28:12 2022 22899362 17:30:57.352 7 9 0.4 2.3 2.9 5.89s 0.53s
1642440492.974328 Mon Jan 17 17:28:12 2022 22899363 17:30:59.259 3 3 0.4 2.2 2.7 0.00s 0.33s
1642440493.359531 Mon Jan 17 17:28:13 2022 22899364 17:31:01.158 4 7 0.4 1.9 2.6 0.00s 0.39s
1642440493.731598 Mon Jan 17 17:28:13 2022 22899365 17:31:02.989 4 5 0.5 2.3 3.1 0.00s 0.37s
1642440502.522161 Mon Jan 17 17:28:22 2022 22899366 17:31:05.029 7 8 0.5 2.5 3.2 8.28s 0.51s
1642440502.936134 Mon Jan 17 17:28:22 2022 22899367 17:31:06.907 5 5 0.5 2.3 2.8 0.00s 0.41s
1642440503.427085 Mon Jan 17 17:28:23 2022 22899368 17:31:08.868 7 9 0.4 2.3 2.7 0.00s 0.49s
1642440506.430213 Mon Jan 17 17:28:26 2022 22899369 17:31:10.703 7 8 0.4 2.6 3.0 2.50s 0.50s
1642440506.957445 Mon Jan 17 17:28:26 2022 22899370 17:31:12.596 8 12 0.5 3.4 4.2 0.00s 0.53s
1642440508.097785 Mon Jan 17 17:28:28 2022 22899371 17:31:14.440 3 5 0.6 3.7 4.7 0.79s 0.35s
1642440508.706494 Mon Jan 17 17:28:28 2022 22899372 17:31:16.439 10 17 0.7 4.7 6.4 0.00s 0.61s
1642440509.037596 Mon Jan 17 17:28:29 2022 22899373 17:31:18.695 3 7 0.8 5.0 7.1 0.00s 0.33s
1642440512.092784 Mon Jan 17 17:28:32 2022 22899374 17:31:20.681 5 6 0.9 5.5 7.7 2.64s 0.42s
1642440515.556215 Mon Jan 17 17:28:35 2022 22899375 17:31:22.600 5 6 0.7 4.1 6.1 3.05s 0.42s
1642440516.037125 Mon Jan 17 17:28:36 2022 22899376 17:31:24.614 6 6 0.8 4.7 6.7 0.00s 0.48s
1642440516.371405 Mon Jan 17 17:28:36 2022 22899377 17:31:26.428 3 4 0.9 5.0 7.1 0.00s 0.33s
1642440524.451177 Mon Jan 17 17:28:44 2022 22899378 17:31:28.349 7 8 0.4 2.1 2.4 7.59s 0.49s
1642440524.982178 Mon Jan 17 17:28:44 2022 22899379 17:31:30.619 8 10 0.5 2.9 3.4 0.00s 0.53s
1642440526.925734 Mon Jan 17 17:28:46 2022 22899380 17:31:32.537 4 5 0.3 1.9 2.3 1.57s 0.37s
1642440529.003883 Mon Jan 17 17:28:49 2022 22899381 17:31:34.708 5 7 0.4 2.4 3.0 1.66s 0.41s
1642440529.533887 Mon Jan 17 17:28:49 2022 22899382 17:31:36.862 8 11 0.5 3.2 4.1 0.00s 0.53s
1642440529.905898 Mon Jan 17 17:28:49 2022 22899383 17:31:38.486 4 5 0.6 3.6 4.6 0.00s 0.37s
1642440530.280167 Mon Jan 17 17:28:50 2022 22899384 17:31:40.440 4 5 0.7 4.0 5.1 0.00s 0.37s
1642440531.434966 Mon Jan 17 17:28:51 2022 22899385 17:31:42.237 4 6 0.8 4.4 5.7 0.75s 0.40s
1642440542.209475 Mon Jan 17 17:29:02 2022 22899386 17:31:44.365 7 10 0.1 0.7 1.0 10.27s 0.51s
1642440542.661821 Mon Jan 17 17:29:02 2022 22899387 17:31:46.260 6 10 0.2 1.3 2.0 0.00s 0.45s
1642440543.192322 Mon Jan 17 17:29:03 2022 22899388 17:31:48.260 8 9 0.3 2.1 2.9 0.00s 0.53s
1642440545.349469 Mon Jan 17 17:29:05 2022 22899389 17:31:50.248 7 11 0.4 2.8 4.0 1.67s 0.49s
1642440545.836510 Mon Jan 17 17:29:05 2022 22899390 17:31:52.407 7 7 0.5 3.5 4.7 0.00s 0.49s
Example ping & dig to the access node showing the fixed overhead of the network connection between flow cli and the access node:
$ ping access.mainnet.nodes.onflow.org
PING access.mainnet.nodes.onflow.org (34.67.208.11) 56(84) bytes of data.
64 bytes from 11.208.67.34.bc.googleusercontent.com (34.67.208.11): icmp_seq=1 ttl=58 time=39.7 ms
64 bytes from 11.208.67.34.bc.googleusercontent.com (34.67.208.11): icmp_seq=2 ttl=58 time=39.6 ms
64 bytes from 11.208.67.34.bc.googleusercontent.com (34.67.208.11): icmp_seq=3 ttl=58 time=39.3 ms
64 bytes from 11.208.67.34.bc.googleusercontent.com (34.67.208.11): icmp_seq=4 ttl=58 time=39.3 ms
64 bytes from 11.208.67.34.bc.googleusercontent.com (34.67.208.11): icmp_seq=5 ttl=58 time=39.6 ms
^C
--- access.mainnet.nodes.onflow.org ping statistics ---
5 packets transmitted, 5 received, 0% packet loss, time 10ms
rtt min/avg/max/mdev = 39.307/39.516/39.696/0.166 ms
$ dig access.mainnet.nodes.onflow.org
; <<>> DiG 9.11.5-P4-5.1+deb10u6-Debian <<>> access.mainnet.nodes.onflow.org
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 28501
;; flags: qr rd ra; QUERY: 1, ANSWER: 4, AUTHORITY: 0, ADDITIONAL: 1
;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 512
;; QUESTION SECTION:
;access.mainnet.nodes.onflow.org. IN A
;; ANSWER SECTION:
access.mainnet.nodes.onflow.org. 30 IN A 35.222.84.108
access.mainnet.nodes.onflow.org. 30 IN A 34.67.208.11
access.mainnet.nodes.onflow.org. 30 IN A 35.239.244.219
access.mainnet.nodes.onflow.org. 30 IN A 34.122.148.83
;; Query time: 14 msec
;; SERVER: 169.254.169.254#53(169.254.169.254)
;; WHEN: Mon Jan 17 17:39:54 UTC 2022
;; MSG SIZE rcvd: 124
From my knowledge better test would be fixing the test on single access node. (Skipping load balancer)
Also afaik cli has version check on each call. (So commenting it out when testing can be better)
Update: I've been using the above technique to examine the finalized block collections and transactions in real-time on localnet in order to provide account feedback info to the loader. This seems to work fine, except...
Just like with mainnet, localnet sometimes has longer delays before the contents (IDs of the collections and transactions) of the latest block are returned. Here's an example where polling with flow cli took 6.72 + 0.22 = 6.92 seconds to show the next block.
In the example below, the loader was injecting transactions at 220 TPS so a 6.92 second delay represents a delay in generating the loader feedback for ~ 1,522 transactions and their associated accounts, and it would be great to get this spike smaller and easier to deal with in the future.
Also, to note is that after the long delay, the next 8 blocks were each shown in < 0.18 seconds each... suggesting that the block manufacture itself was not delayed?
It would be great to have the -debug & -tail command line switches to help debug why flow cli sometimes dishes up the latest block after these longer delays.
poll time height proposed CX TX BPS CPS TPS delay cli
1643408651.611702 Fri Jan 28 22:24:11 2022 506 22:24:03.396 2 159 0.9 2.2 198.8 0.01s 0.16s
1643408658.554126 Fri Jan 28 22:24:18 2022 507 22:24:04.402 3 283 0.3 0.7 64.6 6.72s 0.22s <-
1643408658.718890 Fri Jan 28 22:24:18 2022 508 22:24:05.383 2 171 0.4 0.9 81.7 0.01s 0.16s
1643408658.893845 Fri Jan 28 22:24:18 2022 509 22:24:06.381 3 262 0.5 1.2 107.9 0.01s 0.17s
1643408659.045206 Fri Jan 28 22:24:19 2022 510 22:24:07.423 2 243 0.6 1.4 132.2 0.01s 0.14s
1643408659.227309 Fri Jan 28 22:24:19 2022 511 22:24:08.522 3 225 0.7 1.7 154.7 0.01s 0.18s
1643408659.514199 Fri Jan 28 22:24:19 2022 512 22:24:09.461 2 190 0.8 1.9 173.7 0.01s 0.28s
1643408659.692250 Fri Jan 28 22:24:19 2022 513 22:24:10.412 2 168 0.9 2.1 190.5 0.01s 0.17s
1643408659.853580 Fri Jan 28 22:24:19 2022 514 22:24:11.430 3 277 1.0 2.4 218.2 0.01s 0.15s
1643408660.019792 Fri Jan 28 22:24:20 2022 515 22:24:12.399 3 303 1.1 2.7 248.5 0.01s 0.16s