Evaluating non-realtime block streaming in aiohivebot (part 1)

in HiveDevs • 3 months ago

In my last blogpost I wrote about rate limit support in the async python HIVE library aiohivebot.
I've spent some more time with stress testing the library, and while the end goal is to make things as robust as possible, but for now its fail hard if things go unexpectedly. This is something I'll be adressing later,
but right now I'm stress testing wth two different bot instantiation booleans that are important for its function. I wrote a little script that will process blocks in a do nothing way. The script starts at block 81520247, the first block of 2024 and runs for aproximately an hour.

This is the base script:

from asyncio import get_event_loop
from time import time
from datetime import timedelta
from aiohivebot import BaseBot

class MyBot(BaseBot):
    """Example of an aiohivebot python bot without real utility"""
    def __init__(self):
        jan2024=81520247
        super().__init__(start_block=jan2024, 
                         use_virtual=False,
                         maintain_order=False)
        self.count=0
        self.start_time = time()
        self.total_cought_up = timedelta(seconds=0)

    async def monitor_block_rate(self, rate, behind_head, behind_irreversable):
        self.count += 1
        behind = timedelta(seconds=behind_irreversable*3)
        if rate * 3 -1 < 0:
            negative_cought_up = timedelta(seconds=(1 - rate*3)*60)
            print("block rate =", rate, "blocks/second,"
                  "behind =", behind,
                  "fell behind =", negative_cought_up)
            self.total_cought_up -= negative_cought_up
        else:
            cought_up = timedelta(seconds=(rate*3-1)*60)
            print("block rate =", rate, "blocks/second,",
                  "behind =", behind,
                  "cought up =", cought_up)
            self.total_cought_up += cought_up
        if self.count == 60:
            print("Cought up", self.total_cought_up,
                  "in", timedelta(seconds=time() - self.start_time))
            self.abort()

pncset = MyBot()
loop = get_event_loop()
loop.run_until_complete(pncset.run())
print("Done")

Lets go through the script bit by bit before we look at the results.

from asyncio import get_event_loop
from time import time
from datetime import timedelta

We start with importing a few dependencies. Any aiohivebot script will need the main async event loop and thus the get_event_loop function from asyncio. This particular script will need the current time and will work with time deltas too.

from aiohivebot import BaseBot

class MyBot(BaseBot):
    """Example of an aiohivebot python bot without real utility"""

To make the script we import BaseBot from the aiohivebot lib and subclass it.

    def __init__(self):
        jan2024=81520247
        super().__init__(start_block=jan2024, 
                         use_virtual=False,
                         maintain_order=False)

The constructor starts off by invoking the constructor of the base class. In this script we explicitly set three constructor arguments:

  • start_block: If specified, the HIVE main chain block to start streaming at. If unspecified, we start streaming one block before head.
  • use_virtual: If this is set to false or if left unspecified, virtual operations will not get streamed. By setting it to true, virtual operations will be available in the API too, but at a relatively huge price in terms of performance.
  • maintain_order: By default, aiohivebot will start processing the next block in a different aio task in case another actively being processed block is bussy in async operations. While this should give some better latency specs, this can lead to operations being processed out of order. By specifying this argument as True, no paralel processing of blocks will be done.
       self.count=0
       self.start_time = time()
       self.total_cought_up = timedelta(seconds=0)

In the rest of the constructor some members get initialized.

    async def monitor_block_rate(self, rate, behind_head, behind_irreversable):
        self.count += 1
        behind = timedelta(seconds=behind_irreversable*3)
        if rate * 3 -1 < 0:
            negative_cought_up = timedelta(seconds=(1 - rate*3)*60)
            print("block rate =", rate, "blocks/second,"
                  "behind =", behind,
                  "fell behind =", negative_cought_up)
            self.total_cought_up -= negative_cought_up
        else:
            cought_up = timedelta(seconds=(rate*3-1)*60)
            print("block rate =", rate, "blocks/second,",
                  "behind =", behind,
                  "cought up =", cought_up)
            self.total_cought_up += cought_up

One of the methods our bot can implement is the monitor_block_rate method. This method will get invoked roughly oncew per minute, baring high latency circumstances in all nodes. It gets three arguments:

  • rate: The number of blocks per second in the last minute or so
  • behind_head : How far behind head we still are
  • behind_irreversable: How far behind the last irreversable block we currently are.

This code assumes one block every 3 seconds and calculates how much the bot has cought up since the last time. The script prints some info on processing and continues.


        if self.count == 60:
            print("Cought up", self.total_cought_up,
                  "in", timedelta(seconds=time() - self.start_time))
            self.abort()

When the method has been invoked 60 times, in somewhat more than an hour, it prints some additional data about the entire hour and than calls self.abort()
It will take some time for the bot to halt, but abort will tell all of the tasks that they should abbort operations. Once all tasks are aborted, the script will end.

pncset = MyBot()
loop = get_event_loop()
loop.run_until_complete(pncset.run())

This last bit of code instantiates the bot and starts it.

So now for the results. We ran this script with just the use_virtual and maintain_order arguments set differently/

use_virtual True, maintain_order True

We start off with what should be the slowest. We add support for virtual operations and we disable paralelism in the processing of blocks.

block rate = 26.35 blocks/second, behind = 166 days, 3:40:24 cought up = 1:18:03
block rate = 20.51 blocks/second, behind = 166 days, 2:39:48 cought up = 1:00:31.800000
block rate = 23.57 blocks/second, behind = 166 days, 1:30:06 cought up = 1:09:42.600000
block rate = 20.46 blocks/second, behind = 166 days, 0:27:00 cought up = 1:00:22.800000
block rate = 28.97 blocks/second, behind = 165 days, 23:00:21 cought up = 1:25:54.600000
block rate = 23.34 blocks/second, behind = 165 days, 21:51:15 cought up = 1:09:01.200000
block rate = 19.65 blocks/second, behind = 165 days, 20:51:21 cought up = 0:57:57
block rate = 24.54 blocks/second, behind = 165 days, 19:38:51 cought up = 1:12:37.200000
block rate = 11.0 blocks/second, behind = 165 days, 19:06:30 cought up = 0:32:00
block rate = 23.14 blocks/second, behind = 165 days, 17:58:15 cought up = 1:08:25.200000
block rate = 28.74 blocks/second, behind = 165 days, 16:33:00 cought up = 1:25:13.200000
block rate = 25.39 blocks/second, behind = 165 days, 15:17:51 cought up = 1:15:10.200000
block rate = 26.53 blocks/second, behind = 165 days, 13:59:15 cought up = 1:18:35.400000
block rate = 27.54 blocks/second, behind = 165 days, 12:37:12 cought up = 1:21:37.200000
block rate = 25.85 blocks/second, behind = 165 days, 11:19:00 cought up = 1:16:33
block rate = 25.84 blocks/second, behind = 165 days, 10:02:18 cought up = 1:16:31.200000
block rate = 19.25 blocks/second, behind = 165 days, 9:05:39 cought up = 0:56:45
block rate = 25.79 blocks/second, behind = 165 days, 7:49:06 cought up = 1:16:22.200000
block rate = 28.98 blocks/second, behind = 165 days, 6:23:00 cought up = 1:25:56.400000
block rate = 23.75 blocks/second, behind = 165 days, 5:12:45 cought up = 1:10:15
block rate = 28.28 blocks/second, behind = 165 days, 3:48:54 cought up = 1:23:50.400000
block rate = 23.91 blocks/second, behind = 165 days, 2:38:12 cought up = 1:10:43.800000
block rate = 25.98 blocks/second, behind = 165 days, 1:21:18 cought up = 1:16:56.400000
block rate = 27.63 blocks/second, behind = 164 days, 23:59:21 cought up = 1:21:53.400000
block rate = 26.7 blocks/second, behind = 164 days, 22:40:09 cought up = 1:19:06
block rate = 29.3 blocks/second, behind = 164 days, 21:13:09 cought up = 1:26:54
block rate = 24.52 blocks/second, behind = 164 days, 20:00:27 cought up = 1:12:33.600000
block rate = 20.35 blocks/second, behind = 164 days, 18:59:27 cought up = 1:00:03
block rate = 19.69 blocks/second, behind = 164 days, 18:01:12 cought up = 0:58:04.200000
block rate = 24.15 blocks/second, behind = 164 days, 16:49:48 cought up = 1:11:27
block rate = 20.04 blocks/second, behind = 164 days, 15:50:33 cought up = 0:59:07.200000
block rate = 25.73 blocks/second, behind = 164 days, 14:34:21 cought up = 1:16:11.400000
block rate = 29.68 blocks/second, behind = 164 days, 13:06:15 cought up = 1:28:02.400000
block rate = 20.94 blocks/second, behind = 164 days, 12:03:33 cought up = 1:01:49.200000
block rate = 23.37 blocks/second, behind = 164 days, 10:54:39 cought up = 1:09:06.600000
block rate = 23.58 blocks/second, behind = 164 days, 9:44:45 cought up = 1:09:44.400000
block rate = 26.24 blocks/second, behind = 164 days, 8:26:57 cought up = 1:17:43.200000
block rate = 24.25 blocks/second, behind = 164 days, 7:15:03 cought up = 1:11:45
block rate = 22.6 blocks/second, behind = 164 days, 6:06:57 cought up = 1:06:48
block rate = 26.67 blocks/second, behind = 164 days, 4:46:57 cought up = 1:19:00.600000
block rate = 24.3 blocks/second, behind = 164 days, 3:34:54 cought up = 1:11:54
block rate = 27.23 blocks/second, behind = 164 days, 2:14:06 cought up = 1:20:41.400000
block rate = 21.14 blocks/second, behind = 164 days, 1:11:36 cought up = 1:02:25.200000
block rate = 26.3 blocks/second, behind = 163 days, 23:53:39 cought up = 1:17:54
block rate = 22.86 blocks/second, behind = 163 days, 22:46:00 cought up = 1:07:34.800000
block rate = 24.04 blocks/second, behind = 163 days, 21:34:42 cought up = 1:11:07.200000
block rate = 17.03 blocks/second, behind = 163 days, 20:44:45 cought up = 0:50:05.400000
block rate = 29.79 blocks/second, behind = 163 days, 19:16:21 cought up = 1:28:22.200000
block rate = 31.4 blocks/second, behind = 163 days, 17:42:57 cought up = 1:33:12
block rate = 19.13 blocks/second, behind = 163 days, 16:46:33 cought up = 0:56:23.400000
block rate = 26.11 blocks/second, behind = 163 days, 15:27:45 cought up = 1:17:19.800000
block rate = 29.09 blocks/second, behind = 163 days, 14:01:27 cought up = 1:26:16.200000
block rate = 24.28 blocks/second, behind = 163 days, 12:49:33 cought up = 1:11:50.400000
block rate = 30.68 blocks/second, behind = 163 days, 11:18:24 cought up = 1:31:02.400000
block rate = 21.31 blocks/second, behind = 163 days, 10:15:30 cought up = 1:02:55.800000
block rate = 24.24 blocks/second, behind = 163 days, 9:03:42 cought up = 1:11:43.200000
block rate = 24.95 blocks/second, behind = 163 days, 7:49:48 cought up = 1:13:51
block rate = 22.77 blocks/second, behind = 163 days, 6:42:30 cought up = 1:07:18.600000
block rate = 25.56 blocks/second, behind = 163 days, 5:26:45 cought up = 1:15:40.800000
block rate = 27.02 blocks/second, behind = 163 days, 4:06:00 cought up = 1:20:03.600000
Cought up 3 days, 0:36:05.400000 in 1:00:13.128328

There is some fluctuation, but overall processing is very stable over the entire hour. We managed to process just over 3 days of blocks in one hour. Not fast, but processing a whole month
would be feasible.

use_virtual True, maintain_order False

We keep support for virtual operations and now we enable paralelism in the processing of blocks.

block rate = 38.74 blocks/second, behind = 166 days, 4:03:12 cought up = 1:55:13.200000
block rate = 41.89 blocks/second, behind = 166 days, 1:58:18 cought up = 2:04:40.200000
block rate = 21.76 blocks/second, behind = 166 days, 0:53:03 cought up = 1:04:16.800000
block rate = 40.08 blocks/second, behind = 165 days, 22:53:33 cought up = 1:59:14.400000
block rate = 20.99 blocks/second, behind = 165 days, 21:51:39 cought up = 1:01:58.200000
RETRY HEADER: 10 api.deathwing.me
RETRY HEADER: 10 api.deathwing.me
block rate = 29.12 blocks/second, behind = 165 days, 20:23:45 cought up = 1:26:21.600000
block rate = 7.86 blocks/second, behind = 165 days, 20:00:54 cought up = 0:22:34.800000
block rate = 7.48 blocks/second, behind = 165 days, 19:39:15 cought up = 0:21:26.400000
block rate = 2.92 blocks/second, behind = 165 days, 19:23:24 cought up = 0:07:45.600000
block rate = 11.25 blocks/second, behind = 165 days, 18:51:24 cought up = 0:32:45
block rate = 5.94 blocks/second, behind = 165 days, 18:34:33 cought up = 0:16:49.200000
block rate = 8.73 blocks/second, behind = 165 days, 18:08:54 cought up = 0:25:11.400000
block rate = 7.35 blocks/second, behind = 165 days, 17:47:24 cought up = 0:21:03
block rate = 7.75 blocks/second, behind = 165 days, 17:24:57 cought up = 0:22:15
block rate = 6.56 blocks/second, behind = 165 days, 17:04:03 cought up = 0:18:40.800000
block rate = 4.44 blocks/second, behind = 165 days, 16:51:15 cought up = 0:12:19.200000
block rate = 1.82 blocks/second, behind = 165 days, 16:46:21 cought up = 0:04:27.600000
block rate = 0.03 blocks/second, behind = 165 days, 16:46:12 fell behind = 0:00:54.600000
block rate = 6.96 blocks/second, behind = 165 days, 16:28:54 cought up = 0:19:52.800000
block rate = 8.77 blocks/second, behind = 165 days, 16:03:27 cought up = 0:25:18.600000
block rate = 4.48 blocks/second, behind = 165 days, 15:50:51 cought up = 0:12:26.400000
block rate = 10.55 blocks/second, behind = 165 days, 15:20:09 cought up = 0:30:39
block rate = 7.33 blocks/second, behind = 165 days, 14:59:03 cought up = 0:20:59.400000
block rate = 7.5 blocks/second, behind = 165 days, 14:37:24 cought up = 0:21:30
block rate = 7.43 blocks/second, behind = 165 days, 14:15:57 cought up = 0:21:17.400000
block rate = 2.66 blocks/second, behind = 165 days, 14:07:39 cought up = 0:06:58.800000
block rate = 0.01 blocks/second, behind = 165 days, 14:08:45 fell behind = 0:00:58.200000
block rate = 8.38 blocks/second, behind = 165 days, 13:46:21 cought up = 0:24:08.400000
block rate = 7.63 blocks/second, behind = 165 days, 13:24:06 cought up = 0:21:53.400000
block rate = 7.23 blocks/second, behind = 165 days, 13:03:18 cought up = 0:20:41.400000
block rate = 7.37 blocks/second, behind = 165 days, 12:42:03 cought up = 0:21:06.600000
block rate = 7.27 blocks/second, behind = 165 days, 12:21:06 cought up = 0:20:48.600000
block rate = 7.41 blocks/second, behind = 165 days, 11:59:45 cought up = 0:21:13.800000
block rate = 7.44 blocks/second, behind = 165 days, 11:38:18 cought up = 0:21:19.200000
block rate = 2.84 blocks/second, behind = 165 days, 11:29:54 cought up = 0:07:31.200000
block rate = 0.01 blocks/second, behind = 165 days, 11:30:39 fell behind = 0:00:58.200000
block rate = 7.64 blocks/second, behind = 165 days, 11:10:21 cought up = 0:21:55.200000
block rate = 7.11 blocks/second, behind = 165 days, 10:49:27 cought up = 0:20:19.800000
block rate = 7.33 blocks/second, behind = 165 days, 10:28:15 cought up = 0:20:59.400000
block rate = 7.28 blocks/second, behind = 165 days, 10:07:36 cought up = 0:20:50.400000
block rate = 7.66 blocks/second, behind = 165 days, 9:44:57 cought up = 0:21:58.800000
block rate = 7.14 blocks/second, behind = 165 days, 9:24:51 cought up = 0:20:25.200000
block rate = 7.38 blocks/second, behind = 165 days, 9:03:30 cought up = 0:21:08.400000
block rate = 1.4 blocks/second, behind = 165 days, 8:54:39 cought up = 0:03:12
block rate = 0.01 blocks/second, behind = 165 days, 8:54:39 fell behind = 0:00:58.200000
block rate = 0.0 blocks/second, behind = 165 days, 8:54:36 fell behind = 0:01:00
block rate = 6.67 blocks/second, behind = 165 days, 8:47:30 cought up = 0:19:00.600000
block rate = 7.18 blocks/second, behind = 165 days, 8:26:51 cought up = 0:20:32.400000
block rate = 7.5 blocks/second, behind = 165 days, 8:04:54 cought up = 0:21:30
block rate = 7.48 blocks/second, behind = 165 days, 7:43:27 cought up = 0:21:26.400000
block rate = 7.55 blocks/second, behind = 165 days, 7:21:39 cought up = 0:21:39
block rate = 7.36 blocks/second, behind = 165 days, 7:00:24 cought up = 0:21:04.800000
block rate = 7.43 blocks/second, behind = 165 days, 6:39:00 cought up = 0:21:17.400000
block rate = 1.65 blocks/second, behind = 165 days, 6:25:00 cought up = 0:03:57
block rate = 7.01 blocks/second, behind = 165 days, 6:06:18 cought up = 0:20:01.800000
block rate = 7.21 blocks/second, behind = 165 days, 5:45:54 cought up = 0:20:37.800000
block rate = 7.39 blocks/second, behind = 165 days, 5:24:15 cought up = 0:21:10.200000
block rate = 7.35 blocks/second, behind = 165 days, 5:03:21 cought up = 0:21:03
block rate = 7.55 blocks/second, behind = 165 days, 4:41:21 cought up = 0:21:39
block rate = 7.36 blocks/second, behind = 165 days, 4:20:15 cought up = 0:21:04.800000
Cought up 1 day, 1:16:51.600000 in 1:16:11.494475

We only cought up a little bit over one day compared to the three days in the previous run.
We even see more than a few fell behind lines, what is pretty bad because it means that in those minutes we fetched and processed less blocks (plus virtual opps) than were produced newly in that minute.
Well that is interesting. Instead of things going faster, things go slower. I have some old debug messages showing through the data and we see that we are getting rate limmiting headers just before the slowdown, but still, we will need more data than what we got from this script to figure out what is going on. For now it seems that maintain_order doesn't come at the price we assumed it did. I will spent more time looking into this. There are hooks for per node stats, but their triggering isn't in sync with the triggering of monitor_block_rate. I'll need to make some changes to the code so I can use the combined info in a synced manner. I'll be doing that for my next blog post to get to the bottom of what is causing this unexpected result. It is quite possible that the client side rate limiting is doing something unintended. Something I need to figure out.

use_virtual False, maintain_order False

Next we go back to maintaining order, but now we abandon the virtual operation support.

block rate = 171.91 blocks/second, behind = 165 days, 22:28:21 cought up = 8:34:43.800000
block rate = 212.31 blocks/second, behind = 165 days, 11:52:27 cought up = 10:35:55.800000
block rate = 216.27 blocks/second, behind = 165 days, 1:00:12 cought up = 10:47:48.600000
block rate = 209.23 blocks/second, behind = 164 days, 14:32:03 cought up = 10:26:41.400000
block rate = 209.88 blocks/second, behind = 164 days, 4:03:27 cought up = 10:28:38.400000
block rate = 199.43 blocks/second, behind = 163 days, 17:48:30 cought up = 9:57:17.400000
block rate = 193.65 blocks/second, behind = 163 days, 7:59:03 cought up = 9:39:57
block rate = 196.31 blocks/second, behind = 162 days, 22:09:54 cought up = 9:47:55.800000
block rate = 198.75 blocks/second, behind = 162 days, 12:14:00 cought up = 9:55:15
block rate = 196.78 blocks/second, behind = 162 days, 2:24:24 cought up = 9:49:20.400000
block rate = 204.05 blocks/second, behind = 161 days, 16:09:36 cought up = 10:11:09
block rate = 196.01 blocks/second, behind = 161 days, 6:20:06 cought up = 9:47:01.800000
block rate = 214.21 blocks/second, behind = 160 days, 19:33:12 cought up = 10:41:37.800000
block rate = 195.01 blocks/second, behind = 160 days, 9:43:54 cought up = 9:44:01.800000
block rate = 197.96 blocks/second, behind = 159 days, 23:47:45 cought up = 9:52:52.800000
block rate = 170.45 blocks/second, behind = 159 days, 15:14:00 cought up = 8:30:21
block rate = 203.11 blocks/second, behind = 159 days, 5:05:18 cought up = 10:08:19.800000
block rate = 204.86 blocks/second, behind = 158 days, 18:49:54 cought up = 10:13:34.800000
block rate = 204.2 blocks/second, behind = 158 days, 8:34:39 cought up = 10:11:36
block rate = 204.18 blocks/second, behind = 157 days, 22:19:48 cought up = 10:11:32.400000
block rate = 203.49 blocks/second, behind = 157 days, 12:04:06 cought up = 10:09:28.200000
block rate = 206.12 blocks/second, behind = 157 days, 1:42:09 cought up = 10:17:21.600000
block rate = 209.38 blocks/second, behind = 156 days, 15:14:18 cought up = 10:27:08.400000
block rate = 212.89 blocks/second, behind = 156 days, 4:33:21 cought up = 10:37:40.200000
block rate = 220.16 blocks/second, behind = 155 days, 17:33:18 cought up = 10:59:28.800000
block rate = 216.56 blocks/second, behind = 155 days, 6:39:33 cought up = 10:48:40.800000
block rate = 221.88 blocks/second, behind = 154 days, 19:26:54 cought up = 11:04:38.400000
block rate = 207.19 blocks/second, behind = 154 days, 9:04:54 cought up = 10:20:34.200000
block rate = 210.71 blocks/second, behind = 153 days, 22:30:27 cought up = 10:31:07.800000
block rate = 196.28 blocks/second, behind = 153 days, 12:40:24 cought up = 9:47:50.400000
block rate = 176.65 blocks/second, behind = 153 days, 3:47:39 cought up = 8:48:57
block rate = 211.39 blocks/second, behind = 152 days, 17:13:09 cought up = 10:33:10.200000
block rate = 206.8 blocks/second, behind = 152 days, 6:51:39 cought up = 10:19:24
block rate = 213.19 blocks/second, behind = 151 days, 20:13:03 cought up = 10:38:34.200000
block rate = 195.1 blocks/second, behind = 151 days, 10:21:42 cought up = 9:44:18
block rate = 206.51 blocks/second, behind = 151 days, 0:00:15 cought up = 10:18:31.800000
block rate = 218.04 blocks/second, behind = 150 days, 13:00:15 cought up = 10:53:07.200000
block rate = 214.18 blocks/second, behind = 150 days, 2:13:18 cought up = 10:41:32.400000
block rate = 215.44 blocks/second, behind = 149 days, 15:20:00 cought up = 10:45:19.200000
block rate = 212.96 blocks/second, behind = 149 days, 4:39:06 cought up = 10:37:52.800000
block rate = 202.44 blocks/second, behind = 148 days, 18:30:51 cought up = 10:06:19.200000
block rate = 202.87 blocks/second, behind = 148 days, 8:21:12 cought up = 10:07:36.600000
block rate = 219.74 blocks/second, behind = 147 days, 21:21:12 cought up = 10:58:13.200000
block rate = 208.95 blocks/second, behind = 147 days, 10:53:12 cought up = 10:25:51
block rate = 192.16 blocks/second, behind = 147 days, 1:15:39 cought up = 9:35:28.800000
block rate = 179.51 blocks/second, behind = 146 days, 16:16:30 cought up = 8:57:31.800000
block rate = 211.23 blocks/second, behind = 146 days, 5:42:12 cought up = 10:32:41.400000
block rate = 218.58 blocks/second, behind = 145 days, 18:47:30 cought up = 10:54:44.400000
block rate = 208.69 blocks/second, behind = 145 days, 8:21:21 cought up = 10:25:04.200000
block rate = 208.76 blocks/second, behind = 144 days, 21:53:48 cought up = 10:25:16.800000
block rate = 204.56 blocks/second, behind = 144 days, 11:38:48 cought up = 10:12:40.800000
block rate = 211.72 blocks/second, behind = 144 days, 1:04:33 cought up = 10:34:09.600000
block rate = 196.82 blocks/second, behind = 143 days, 15:09:03 cought up = 9:49:27.600000
block rate = 203.16 blocks/second, behind = 143 days, 5:00:12 cought up = 10:08:28.800000
block rate = 211.73 blocks/second, behind = 142 days, 18:25:27 cought up = 10:34:11.400000
block rate = 206.55 blocks/second, behind = 142 days, 8:03:27 cought up = 10:18:39
block rate = 212.33 blocks/second, behind = 141 days, 21:16:30 cought up = 10:35:59.400000
block rate = 205.03 blocks/second, behind = 141 days, 11:01:36 cought up = 10:14:05.400000
block rate = 211.14 blocks/second, behind = 141 days, 0:27:15 cought up = 10:32:25.200000
block rate = 198.63 blocks/second, behind = 140 days, 14:31:12 cought up = 9:54:53.400000
Cought up 25 days, 13:24:14.400000 in 1:00:19.683127

That's a whole lot laster than the previous two one hour runs. We cought up not one day, not three days, but 25 and a half days in one hour. This is a clear demonstration of the price we pay for wanting to process virtual operations. While aiohivebot isn't designed with a focus on historic data streaming, the performance for block streaming withhout virtual operations is actually quite decent.

use_virtual False, maintain_order True

block rate = 171.75 blocks/second, behind = 166 days, 0:12:30 cought up = 8:34:15
block rate = 209.61 blocks/second, behind = 165 days, 13:43:42 cought up = 10:27:49.800000
block rate = 207.2 blocks/second, behind = 165 days, 3:02:57 cought up = 10:20:36
block rate = 206.46 blocks/second, behind = 164 days, 16:41:12 cought up = 10:18:22.800000
block rate = 209.65 blocks/second, behind = 164 days, 6:06:45 cought up = 10:27:57
block rate = 207.6 blocks/second, behind = 163 days, 19:38:48 cought up = 10:21:48
block rate = 186.16 blocks/second, behind = 163 days, 10:14:33 cought up = 9:17:28.800000
block rate = 198.96 blocks/second, behind = 163 days, 0:18:33 cought up = 9:55:52.800000
block rate = 196.44 blocks/second, behind = 162 days, 14:28:48 cought up = 9:48:19.200000
block rate = 204.3 blocks/second, behind = 162 days, 4:13:33 cought up = 10:11:54
block rate = 207.37 blocks/second, behind = 161 days, 17:51:33 cought up = 10:21:06.600000
block rate = 198.51 blocks/second, behind = 161 days, 7:55:36 cought up = 9:54:31.800000
block rate = 187.18 blocks/second, behind = 160 days, 22:35:00 cought up = 9:20:32.400000
block rate = 202.49 blocks/second, behind = 160 days, 12:21:33 cought up = 10:06:28.200000
block rate = 196.94 blocks/second, behind = 160 days, 2:31:30 cought up = 9:49:49.200000
block rate = 171.52 blocks/second, behind = 159 days, 17:57:27 cought up = 8:33:33.600000
block rate = 203.3 blocks/second, behind = 159 days, 7:47:54 cought up = 10:08:54
block rate = 202.97 blocks/second, behind = 158 days, 21:38:51 cought up = 10:07:54.600000
block rate = 189.53 blocks/second, behind = 158 days, 12:11:15 cought up = 9:27:35.400000
block rate = 203.93 blocks/second, behind = 158 days, 1:59:45 cought up = 10:10:47.400000
block rate = 193.53 blocks/second, behind = 157 days, 16:16:30 cought up = 9:39:35.400000
block rate = 196.52 blocks/second, behind = 157 days, 6:20:09 cought up = 9:48:33.600000
block rate = 209.23 blocks/second, behind = 156 days, 19:52:03 cought up = 10:26:41.400000
block rate = 208.9 blocks/second, behind = 156 days, 9:24:15 cought up = 10:25:42
block rate = 206.33 blocks/second, behind = 155 days, 22:56:21 cought up = 10:17:59.400000
block rate = 203.39 blocks/second, behind = 155 days, 12:46:57 cought up = 10:09:10.200000
block rate = 208.2 blocks/second, behind = 155 days, 2:19:03 cought up = 10:23:36
block rate = 207.19 blocks/second, behind = 154 days, 15:57:15 cought up = 10:20:34.200000
block rate = 183.66 blocks/second, behind = 154 days, 6:44:48 cought up = 9:09:58.800000
block rate = 193.73 blocks/second, behind = 153 days, 20:59:51 cought up = 9:40:11.400000
block rate = 169.73 blocks/second, behind = 153 days, 12:25:45 cought up = 8:28:11.400000
block rate = 200.57 blocks/second, behind = 153 days, 2:23:36 cought up = 10:00:42.600000
block rate = 189.54 blocks/second, behind = 152 days, 16:46:51 cought up = 9:27:37.200000
block rate = 190.39 blocks/second, behind = 152 days, 7:16:27 cought up = 9:30:10.200000
block rate = 208.89 blocks/second, behind = 151 days, 20:48:51 cought up = 10:25:40.200000
block rate = 178.93 blocks/second, behind = 151 days, 11:37:27 cought up = 8:55:47.400000
block rate = 199.97 blocks/second, behind = 151 days, 1:29:03 cought up = 9:58:54.600000
block rate = 198.61 blocks/second, behind = 150 days, 15:32:45 cought up = 9:54:49.800000
block rate = 185.82 blocks/second, behind = 150 days, 6:15:15 cought up = 9:16:27.600000
block rate = 197.7 blocks/second, behind = 149 days, 20:13:06 cought up = 9:52:06
block rate = 200.39 blocks/second, behind = 149 days, 10:10:33 cought up = 10:00:10.200000
block rate = 197.92 blocks/second, behind = 149 days, 0:14:30 cought up = 9:52:45.600000
block rate = 183.26 blocks/second, behind = 148 days, 15:03:18 cought up = 9:08:46.800000
block rate = 200.72 blocks/second, behind = 148 days, 5:00:51 cought up = 10:01:09.600000
block rate = 190.43 blocks/second, behind = 147 days, 19:30:15 cought up = 9:30:17.400000
block rate = 162.86 blocks/second, behind = 147 days, 11:21:27 cought up = 8:07:34.800000
block rate = 207.09 blocks/second, behind = 147 days, 0:59:57 cought up = 10:20:16.200000
block rate = 202.77 blocks/second, behind = 146 days, 14:51:03 cought up = 10:07:18.600000
block rate = 195.08 blocks/second, behind = 146 days, 4:54:30 cought up = 9:44:14.400000
block rate = 204.82 blocks/second, behind = 145 days, 18:32:42 cought up = 10:13:27.600000
block rate = 192.18 blocks/second, behind = 145 days, 8:55:33 cought up = 9:35:32.400000
block rate = 214.2 blocks/second, behind = 144 days, 21:49:00 cought up = 10:41:36
block rate = 207.41 blocks/second, behind = 144 days, 11:27:45 cought up = 10:21:13.800000
block rate = 201.98 blocks/second, behind = 144 days, 1:22:48 cought up = 10:04:56.400000
block rate = 205.91 blocks/second, behind = 143 days, 15:03:51 cought up = 10:16:43.800000
block rate = 192.4 blocks/second, behind = 143 days, 5:27:03 cought up = 9:36:12
block rate = 208.77 blocks/second, behind = 142 days, 18:52:33 cought up = 10:25:18.600000
block rate = 215.87 blocks/second, behind = 142 days, 8:05:24 cought up = 10:46:36.600000
block rate = 215.32 blocks/second, behind = 141 days, 21:11:33 cought up = 10:44:57.600000
block rate = 188.2 blocks/second, behind = 141 days, 11:46:45 cought up = 9:23:36
Cought up 24 days, 17:00:50.400000 in 1:00:25.357840

So now we have basicly the same speed as we had in the previous run.

In short

virtualordercought-up
yesyes3 days, 0:36:05
yesno1 day, 1:16:51
noyes25 days, 13:24:14
nono24 days, 17:00:50

Lets run our first and second run once more

Because the first versus the second run were surprising, lets run that one once more:
We start off with parallel block processing enabled.

block rate = 34.38 blocks/second, behind = 166 days, 9:22:54 cought up = 1:42:08.400000
block rate = 30.3 blocks/second, behind = 166 days, 7:51:54 cought up = 1:29:54
block rate = 39.93 blocks/second, behind = 166 days, 5:48:24 cought up = 1:58:47.400000
block rate = 15.94 blocks/second, behind = 166 days, 5:00:51 cought up = 0:46:49.200000
block rate = 34.67 blocks/second, behind = 166 days, 3:17:18 cought up = 1:43:00.600000
block rate = 30.66 blocks/second, behind = 166 days, 1:45:33 cought up = 1:30:58.800000
block rate = 31.1 blocks/second, behind = 166 days, 0:08:48 cought up = 1:32:18
block rate = 35.03 blocks/second, behind = 165 days, 22:23:57 cought up = 1:44:05.400000
block rate = 18.2 blocks/second, behind = 165 days, 20:42:21 cought up = 0:53:36
block rate = 39.74 blocks/second, behind = 165 days, 18:44:45 cought up = 1:58:13.200000
block rate = 13.89 blocks/second, behind = 165 days, 18:03:42 cought up = 0:40:40.200000
block rate = 39.78 blocks/second, behind = 165 days, 16:05:12 cought up = 1:58:20.400000
block rate = 13.92 blocks/second, behind = 165 days, 15:22:45 cought up = 0:40:45.600000
block rate = 39.71 blocks/second, behind = 165 days, 13:24:15 cought up = 1:58:07.800000
block rate = 23.92 blocks/second, behind = 165 days, 12:12:18 cought up = 1:10:45.600000
block rate = 34.99 blocks/second, behind = 165 days, 10:27:48 cought up = 1:43:58.200000
block rate = 34.11 blocks/second, behind = 165 days, 8:45:39 cought up = 1:41:19.800000
block rate = 39.95 blocks/second, behind = 165 days, 6:46:12 cought up = 1:58:51
block rate = 24.58 blocks/second, behind = 165 days, 5:33:24 cought up = 1:12:44.400000
RETRY HEADER: 10 api.deathwing.me
RETRY HEADER: 10 api.deathwing.me
block rate = 32.44 blocks/second, behind = 165 days, 3:55:03 cought up = 1:36:19.200000
block rate = 7.9 blocks/second, behind = 165 days, 3:32:21 cought up = 0:22:42
block rate = 7.49 blocks/second, behind = 165 days, 3:10:03 cought up = 0:21:28.200000
block rate = 7.49 blocks/second, behind = 165 days, 2:48:24 cought up = 0:21:28.200000
block rate = 6.76 blocks/second, behind = 165 days, 2:27:09 cought up = 0:19:16.800000
block rate = 7.6 blocks/second, behind = 165 days, 2:05:09 cought up = 0:21:48
block rate = 7.06 blocks/second, behind = 165 days, 1:43:12 cought up = 0:20:10.800000
block rate = 1.05 blocks/second, behind = 165 days, 1:35:15 cought up = 0:02:09
block rate = 7.4 blocks/second, behind = 165 days, 1:16:03 cought up = 0:21:12
block rate = 7.55 blocks/second, behind = 165 days, 0:54:09 cought up = 0:21:39
block rate = 7.32 blocks/second, behind = 165 days, 0:32:57 cought up = 0:20:57.600000
block rate = 7.39 blocks/second, behind = 165 days, 0:11:33 cought up = 0:21:10.200000
block rate = 7.33 blocks/second, behind = 164 days, 23:50:24 cought up = 0:20:59.400000
block rate = 7.5 blocks/second, behind = 164 days, 23:29:03 cought up = 0:21:30
block rate = 7.64 blocks/second, behind = 164 days, 23:06:54 cought up = 0:21:55.200000
block rate = 2.88 blocks/second, behind = 164 days, 22:58:33 cought up = 0:07:38.400000
block rate = 0.01 blocks/second, behind = 164 days, 22:58:30 fell behind = 0:00:58.200000
block rate = 8.05 blocks/second, behind = 164 days, 22:36:57 cought up = 0:23:09
block rate = 7.46 blocks/second, behind = 164 days, 22:16:06 cought up = 0:21:22.800000
block rate = 7.3 blocks/second, behind = 164 days, 21:54:57 cought up = 0:20:54
block rate = 7.69 blocks/second, behind = 164 days, 21:32:57 cought up = 0:22:04.200000
block rate = 6.96 blocks/second, behind = 164 days, 21:12:48 cought up = 0:19:52.800000
block rate = 7.64 blocks/second, behind = 164 days, 20:51:00 cought up = 0:21:55.200000
block rate = 6.91 blocks/second, behind = 164 days, 20:30:48 cought up = 0:19:43.800000
block rate = 3.71 blocks/second, behind = 164 days, 20:19:45 cought up = 0:10:07.800000
block rate = 0.16 blocks/second, behind = 164 days, 20:19:18 fell behind = 0:00:31.200000
block rate = 0.36 blocks/second, behind = 164 days, 20:10:33 cought up = 0:00:04.800000
block rate = 4.87 blocks/second, behind = 164 days, 20:05:57 cought up = 0:13:36.600000
block rate = 7.04 blocks/second, behind = 164 days, 19:46:30 cought up = 0:20:07.200000
block rate = 7.37 blocks/second, behind = 164 days, 19:25:09 cought up = 0:21:06.600000
block rate = 7.3 blocks/second, behind = 164 days, 19:03:42 cought up = 0:20:54
block rate = 7.58 blocks/second, behind = 164 days, 18:41:48 cought up = 0:21:44.400000
block rate = 7.47 blocks/second, behind = 164 days, 18:20:09 cought up = 0:21:24.600000
block rate = 7.58 blocks/second, behind = 164 days, 17:58:27 cought up = 0:21:44.400000
block rate = 6.3 blocks/second, behind = 164 days, 17:36:54 cought up = 0:17:54
block rate = 0.11 blocks/second, behind = 164 days, 17:36:30 fell behind = 0:00:40.200000
block rate = 7.6 blocks/second, behind = 164 days, 17:16:12 cought up = 0:21:48
block rate = 6.23 blocks/second, behind = 164 days, 16:58:36 cought up = 0:17:41.400000
block rate = 7.82 blocks/second, behind = 164 days, 16:35:54 cought up = 0:22:27.600000
block rate = 7.49 blocks/second, behind = 164 days, 16:14:00 cought up = 0:21:28.200000
block rate = 6.94 blocks/second, behind = 164 days, 15:54:27 cought up = 0:19:49.200000
Cought up 1 day, 17:46:39 in 1:15:08.508353

While the average performance over an hour is a little better, but now thanks to our left-in debug log we do notice something of a pattern. After we get rate limiting headers from one of the nodes, the speed pretty much collapses including dramatic minutes where we actually drop down to a level were we fall behind further than we started.

But this isn't just about any node. This is the only node that after my last blog post I increased the parameters for for the client side rate limiting. So it would not be surprising if rate limiting for that one specific node kicking in would have a major impact on the performance as a whole.

Lets do something brutal

Each of the test runs so far took about an hour, so we are already five hours in for this blog post. But let's do one last test run, lets run the test that we just repeated one last time, but this time we set the client side rate limits that we had for api.deathwing.me for each one of the public API nodes and we'll see what happens.

{
  "api.hive.blog": {
    "policies": [
            {"w": 2, "v": 100},
            {"w": 60, "v": 2400},
            {"w": 600, "v": 18000},
            {"w": 3600, "v": 90000},
            {"w": 10800, "v": 216000}
    ]
  },
  "api.deathwing.me": {
    "note": "@deathwing reported using a 50 calls/second policy and using 429/Retry-After",
    "policies": [
            {"w": 2, "v": 100},
            {"w": 60, "v": 2400},
            {"w": 600, "v": 18000},
            {"w": 3600, "v": 90000},
            {"w": 10800, "v": 216000}
    ]
  },
  ...
}

This rate limiting policy defines five paralel policies for what four ar relevant for our one hour run:

  • 100 requests per 2 seconds (50 requests per second)
  • 2400 requests per minute (40 requests per second)
  • 18000 requests per 10 minutes (30 requests per second)
  • 90000 requests per hour (25 requests per second)

Let's do a run with ALL node clients set to these policies and see what happens now.

block rate = 35.16 blocks/second, behind = 166 days, 10:37:39 cought up = 1:44:28.800000
RETRY HEADER: 10 api.deathwing.me
RETRY HEADER: 10 api.deathwing.me
block rate = 15.25 blocks/second, behind = 166 days, 9:51:45 cought up = 0:44:45
block rate = 10.22 blocks/second, behind = 166 days, 9:21:45 cought up = 0:29:39.600000
block rate = 6.15 blocks/second, behind = 166 days, 9:04:15 cought up = 0:17:27
block rate = 10.05 blocks/second, behind = 166 days, 8:34:51 cought up = 0:29:09
block rate = 8.96 blocks/second, behind = 166 days, 8:08:36 cought up = 0:25:52.800000
block rate = 7.59 blocks/second, behind = 166 days, 7:46:36 cought up = 0:21:46.200000
block rate = 5.69 blocks/second, behind = 166 days, 7:30:24 cought up = 0:16:04.200000
block rate = 2.83 blocks/second, behind = 166 days, 7:19:51 cought up = 0:07:29.400000
block rate = 5.71 blocks/second, behind = 166 days, 7:04:36 cought up = 0:16:07.800000
block rate = 6.52 blocks/second, behind = 166 days, 6:46:09 cought up = 0:18:33.600000
block rate = 7.48 blocks/second, behind = 166 days, 6:24:42 cought up = 0:21:26.400000
block rate = 6.85 blocks/second, behind = 166 days, 6:04:48 cought up = 0:19:33
block rate = 7.78 blocks/second, behind = 166 days, 5:42:24 cought up = 0:22:20.400000
block rate = 6.43 blocks/second, behind = 166 days, 5:24:12 cought up = 0:18:17.400000
block rate = 7.63 blocks/second, behind = 166 days, 5:02:15 cought up = 0:21:53.400000
block rate = 4.87 blocks/second, behind = 166 days, 4:47:57 cought up = 0:13:36.600000
block rate = 1.07 blocks/second, behind = 166 days, 4:42:42 cought up = 0:02:12.600000
block rate = 3.39 blocks/second, behind = 166 days, 4:35:21 cought up = 0:09:10.200000
block rate = 10.09 blocks/second, behind = 166 days, 4:05:51 cought up = 0:29:16.200000
block rate = 5.58 blocks/second, behind = 166 days, 3:49:45 cought up = 0:15:44.400000
block rate = 6.33 blocks/second, behind = 166 days, 3:31:48 cought up = 0:17:59.400000
block rate = 10.74 blocks/second, behind = 166 days, 3:00:33 cought up = 0:31:13.200000
block rate = 5.11 blocks/second, behind = 166 days, 2:46:09 cought up = 0:14:19.800000
block rate = 6.49 blocks/second, behind = 166 days, 2:27:21 cought up = 0:18:28.200000
block rate = 5.76 blocks/second, behind = 166 days, 2:10:48 cought up = 0:16:16.800000
block rate = 0.51 blocks/second, behind = 166 days, 2:06:33 cought up = 0:00:31.800000
block rate = 8.4 blocks/second, behind = 166 days, 1:45:03 cought up = 0:24:12
block rate = 7.79 blocks/second, behind = 166 days, 1:22:48 cought up = 0:22:22.200000
block rate = 7.38 blocks/second, behind = 166 days, 1:01:09 cought up = 0:21:08.400000
block rate = 7.48 blocks/second, behind = 166 days, 0:39:18 cought up = 0:21:26.400000
block rate = 7.6 blocks/second, behind = 166 days, 0:17:18 cought up = 0:21:48
block rate = 7.64 blocks/second, behind = 165 days, 23:55:21 cought up = 0:21:55.200000
block rate = 7.62 blocks/second, behind = 165 days, 23:33:27 cought up = 0:21:51.600000
block rate = 2.63 blocks/second, behind = 165 days, 23:26:15 cought up = 0:06:53.400000
block rate = 0.06 blocks/second, behind = 165 days, 23:25:54 fell behind = 0:00:49.200000
block rate = 3.03 blocks/second, behind = 165 days, 23:19:42 cought up = 0:08:05.400000
block rate = 5.59 blocks/second, behind = 165 days, 23:02:57 cought up = 0:15:46.200000
block rate = 8.85 blocks/second, behind = 165 days, 22:37:09 cought up = 0:25:33
block rate = 6.04 blocks/second, behind = 165 days, 22:19:57 cought up = 0:17:07.200000
block rate = 7.29 blocks/second, behind = 165 days, 21:58:45 cought up = 0:20:52.200000
block rate = 7.15 blocks/second, behind = 165 days, 21:38:24 cought up = 0:20:27
block rate = 8.79 blocks/second, behind = 165 days, 21:13:03 cought up = 0:25:22.200000
block rate = 6.57 blocks/second, behind = 165 days, 20:54:24 cought up = 0:18:42.600000
block rate = 0.11 blocks/second, behind = 165 days, 20:49:24 fell behind = 0:00:40.200000
block rate = 7.03 blocks/second, behind = 165 days, 20:42:18 cought up = 0:20:05.400000
block rate = 7.17 blocks/second, behind = 165 days, 20:21:15 cought up = 0:20:30.600000
block rate = 7.6 blocks/second, behind = 165 days, 19:59:09 cought up = 0:21:48
block rate = 7.49 blocks/second, behind = 165 days, 19:37:33 cought up = 0:21:28.200000
block rate = 7.21 blocks/second, behind = 165 days, 19:16:54 cought up = 0:20:37.800000
block rate = 7.48 blocks/second, behind = 165 days, 18:55:21 cought up = 0:21:26.400000
block rate = 7.25 blocks/second, behind = 165 days, 18:34:15 cought up = 0:20:45
block rate = 3.04 blocks/second, behind = 165 days, 18:20:45 cought up = 0:08:07.200000
block rate = 0.15 blocks/second, behind = 165 days, 18:20:09 fell behind = 0:00:33
block rate = 6.09 blocks/second, behind = 165 days, 18:04:06 cought up = 0:17:16.200000
block rate = 7.54 blocks/second, behind = 165 days, 17:42:15 cought up = 0:21:37.200000
block rate = 7.31 blocks/second, behind = 165 days, 17:20:36 cought up = 0:20:55.800000
block rate = 7.52 blocks/second, behind = 165 days, 16:59:45 cought up = 0:21:33.600000
block rate = 7.23 blocks/second, behind = 165 days, 16:38:18 cought up = 0:20:41.400000
block rate = 7.28 blocks/second, behind = 165 days, 16:17:12 cought up = 0:20:50.400000
Cought up 19:52:57 in 1:16:02.825036

This is the worst run so far, lets give it one mor run but now we give every node just one policy for a one minut window.

{
  "api.hive.blog": {
    "policies": [
            {"w": 60, "v": 240}
    ]
  },
  "api.deathwing.me": {
    "policies": [
            {"w": 60, "v": 240}
    ]
  },
  "hive-api.arcange.eu": {
    "policies": [
            {"w": 60, "v": 240}
    ]
  },
  ...
}

Lets do our last 1 hour run of the day:

block rate = 26.64 blocks/second, behind = 166 days, 12:56:18 cought up = 1:18:55.200000
block rate = 39.79 blocks/second, behind = 166 days, 10:57:39 cought up = 1:58:22.200000
block rate = 17.23 blocks/second, behind = 166 days, 10:06:00 cought up = 0:50:41.400000
block rate = 39.66 blocks/second, behind = 166 days, 8:07:33 cought up = 1:57:58.800000
block rate = 22.54 blocks/second, behind = 166 days, 7:00:51 cought up = 1:06:37.200000
block rate = 33.2 blocks/second, behind = 166 days, 5:21:03 cought up = 1:38:36
block rate = 36.51 blocks/second, behind = 166 days, 3:32:18 cought up = 1:48:31.800000
block rate = 40.12 blocks/second, behind = 166 days, 1:32:24 cought up = 1:59:21.600000
block rate = 22.56 blocks/second, behind = 166 days, 0:24:54 cought up = 1:06:40.800000
RETRY HEADER: 10 api.deathwing.me
RETRY HEADER: 10 api.deathwing.me
RETRY HEADER: 10 api.deathwing.me
RETRY HEADER: 10 api.deathwing.me
block rate = 29.48 blocks/second, behind = 165 days, 22:57:15 cought up = 1:27:26.400000
block rate = 10.36 blocks/second, behind = 165 days, 22:26:57 cought up = 0:30:04.800000
block rate = 10.17 blocks/second, behind = 165 days, 21:54:54 cought up = 0:29:30.600000
block rate = 13.56 blocks/second, behind = 165 days, 21:15:18 cought up = 0:39:40.800000
block rate = 7.49 blocks/second, behind = 165 days, 20:53:36 cought up = 0:21:28.200000
block rate = 12.12 blocks/second, behind = 165 days, 20:18:27 cought up = 0:35:21.600000
block rate = 9.89 blocks/second, behind = 165 days, 19:49:51 cought up = 0:28:40.200000
block rate = 7.44 blocks/second, behind = 165 days, 19:27:42 cought up = 0:21:19.200000
block rate = 2.35 blocks/second, behind = 165 days, 19:20:15 cought up = 0:06:03
block rate = 0.02 blocks/second, behind = 165 days, 19:21:03 fell behind = 0:00:56.400000
block rate = 7.11 blocks/second, behind = 165 days, 19:02:51 cought up = 0:20:19.800000
block rate = 5.42 blocks/second, behind = 165 days, 18:47:33 cought up = 0:15:15.600000
block rate = 7.65 blocks/second, behind = 165 days, 18:25:18 cought up = 0:21:57
block rate = 7.53 blocks/second, behind = 165 days, 18:03:09 cought up = 0:21:35.400000
block rate = 7.42 blocks/second, behind = 165 days, 17:41:51 cought up = 0:21:15.600000
block rate = 7.43 blocks/second, behind = 165 days, 17:20:51 cought up = 0:21:17.400000
block rate = 5.6 blocks/second, behind = 165 days, 17:04:09 cought up = 0:15:48
block rate = 1.47 blocks/second, behind = 165 days, 16:59:30 cought up = 0:03:24.600000
block rate = 0.0 blocks/second, behind = 165 days, 16:59:51 fell behind = 0:01:00
block rate = 5.62 blocks/second, behind = 165 days, 16:46:30 cought up = 0:15:51.600000
block rate = 3.84 blocks/second, behind = 165 days, 16:35:18 cought up = 0:10:31.200000
block rate = 3.87 blocks/second, behind = 165 days, 16:24:39 cought up = 0:10:36.600000
block rate = 3.83 blocks/second, behind = 165 days, 16:14:15 cought up = 0:10:29.400000
block rate = 3.82 blocks/second, behind = 165 days, 16:03:42 cought up = 0:10:27.600000
block rate = 3.85 blocks/second, behind = 165 days, 15:52:45 cought up = 0:10:33
block rate = 3.85 blocks/second, behind = 165 days, 15:42:03 cought up = 0:10:33
block rate = 1.27 blocks/second, behind = 165 days, 15:38:27 cought up = 0:02:48.600000
block rate = 0.02 blocks/second, behind = 165 days, 15:38:51 fell behind = 0:00:56.400000
block rate = 16.21 blocks/second, behind = 165 days, 14:53:21 cought up = 0:47:37.800000
block rate = 3.89 blocks/second, behind = 165 days, 14:42:36 cought up = 0:10:40.200000
block rate = 3.86 blocks/second, behind = 165 days, 14:31:51 cought up = 0:10:34.800000
block rate = 3.8 blocks/second, behind = 165 days, 14:21:36 cought up = 0:10:24
block rate = 3.85 blocks/second, behind = 165 days, 14:10:42 cought up = 0:10:33
block rate = 3.79 blocks/second, behind = 165 days, 14:00:15 cought up = 0:10:22.200000
block rate = 3.8 blocks/second, behind = 165 days, 13:49:45 cought up = 0:10:24
block rate = 0.08 blocks/second, behind = 165 days, 13:46:30 fell behind = 0:00:45.600000
block rate = 27.33 blocks/second, behind = 165 days, 12:38:15 cought up = 1:20:59.400000
block rate = 3.81 blocks/second, behind = 165 days, 12:27:48 cought up = 0:10:25.800000
block rate = 3.82 blocks/second, behind = 165 days, 12:17:21 cought up = 0:10:27.600000
block rate = 3.98 blocks/second, behind = 165 days, 12:05:33 cought up = 0:10:56.400000
block rate = 3.85 blocks/second, behind = 165 days, 11:55:12 cought up = 0:10:33
block rate = 3.9 blocks/second, behind = 165 days, 11:44:09 cought up = 0:10:42
block rate = 3.89 blocks/second, behind = 165 days, 11:33:36 cought up = 0:10:40.200000
block rate = 1.26 blocks/second, behind = 165 days, 11:29:18 cought up = 0:02:46.800000
block rate = 0.0 blocks/second, behind = 165 days, 11:29:18 fell behind = 0:01:00
block rate = 19.88 blocks/second, behind = 165 days, 10:33:33 cought up = 0:58:38.400000
block rate = 3.84 blocks/second, behind = 165 days, 10:22:33 cought up = 0:10:31.200000
block rate = 3.9 blocks/second, behind = 165 days, 10:11:33 cought up = 0:10:42
block rate = 3.85 blocks/second, behind = 165 days, 10:01:09 cought up = 0:10:33
block rate = 3.85 blocks/second, behind = 165 days, 9:50:30 cought up = 0:10:33
block rate = 4.01 blocks/second, behind = 165 days, 9:39:18 cought up = 0:11:01.800000
Cought up 1 day, 4:33:32.400000 in 1:16:03.315173

A bit better again, but still much worse than our guaranteed order run.

Conclusions

Historic block streaming without virtual operations seems to perform quite decently regardless of the setting for strict ordering, though we need to keep in mind that this is a dry run without any actual bot functionality doing aditional JSON-RPC API calls.

The same can't be said for streaming with virtual operations. Somehow the policy to allow paralel block processing has a major impact on server side rate limits being triggered, and from there on something happens that we need to investigate more closely. Changing the client side rate limiting for all nodes in a brutal way for one one hour test resulted in very little difference.

The tests run so far have basicly been unloaded. The bot did noo aditional API calls of any kind like a real bot would. First I'm going to look into the strong and lasting impact of rate limiting headers, see if there is anything wrong with the code and if it is fix it, before moving on to testing with a loaded version of the tests I ran today.

The mistery for now is a bit frustrating, especialy because historic data streaming isn't supposed to be the main concern for this library. But it is a problem that might show up in life scenarios too, and the historic data is easy to replay and thus a better place to reproduce and fix any problem we may have. So I'm dedicating myself to spending at least a few more days looking into what the problem is and if we need to fix it.

image.png

#programming #development #python #aiohivebot #hivedev #opensource #innuendo
3 months ago in HiveDevs by
$6.82
  • Past Payouts $6.82
  • - Author $3.42
  • - Curators & beneficiaries $3.40
  • > peakd: $0.17
232 votes
Reply 1
Sort:  
  • Trending
    • [-]
     3 months ago  

    Thanks for your contribution to the STEMsocial community. Feel free to join us on discord to get to know the rest of us!

    Please consider delegating to the @stemsocial account (85% of the curation rewards are returned).

    You may also include @stemsocial as a beneficiary of the rewards of this post to get a stronger support. 
     

    $0.00
      Reply