Feature Request : Reporting on Latency & Performance

[dlasher]

hey bud, updated to 5.5.1, love the changes, made me want more data. :)

["8/28/2020, 4:26:21 AM"] DEBUG: Pinging the Binance API ... ["8/28/2020, 4:26:21 AM"] INFO : Experiencing approximately 81 ms of latency

Can we get some sort of regular feedback in logs as to latency? maybe successful depth, either per "subscription" or per bundle? Maybe throw in ram usage and average CPU load in the performance.log? Utilization per thread? option to use more threads?

[bmino]

The latency check is currently done by hitting the /time endpoint of the Binance API server 5 times and averaging the response times. This shouldn't change much during execution. And if it did, what actions would be taken?

I see a good use case for logging ram/cpu usage every so often to ensure the host system isn't overloaded

[bmino]

At one point this bot was multi-threaded, however the overhead of passing data into/out of a thread was to net performance gains. I'm open to ideas here as to what exactly would be done in a thread.

I tried running a calculation cycle in a thread, and also tried running each calculation itself in a thread pool

[dlasher]

The latency check is currently done by hitting the /time endpoint of the Binance API server 5 times and averaging the response times. This shouldn't change much during execution. And if it did, what actions would be taken?

I'm not sure what actions we'd take, but it would be very interesting to see the results over time. As an example, I'm running the script on a VPS in toyko, with a 2ms ping to the IP addresses that show up in netstat for subs, but the program is reporting 350ms latency.

I see a good use case for logging ram/cpu usage every so often to ensure the host system isn't overloaded

True, Would help size the VM correctly, etc.

[dlasher]

At one point this bot was multi-threaded, however the overhead of passing data into/out of a thread was to net performance gains. I'm open to ideas here as to what exactly would be done in a thread.

I tried running a calculation cycle in a thread, and also tried running each calculation itself in a thread pool

I ask because from a TOP perspective, when it's running, I have one thread at 100-105%, and 2/3/4/5 other threads at 5-10%. Doesn't matter whether I run it on a 32 core machine, or a 4 core machine.

In theory when you open 150 web sockets, having that spread across threads would make handling the input easier?

[bmino]

It is correct that each update from all websockets have to be processed, but that information needs to be accumulated in one object (the local depth cache). I don't see how threading would save much here as this process is not computationally intense.

The most intense part (cpu wise) the bot does, is run a calculation cycle on every position being watched. This for me ends up being about ~174 positions and takes somewhere in the realm of 6-30 ms depending on my investment range.

To have a thread do any computations, information from the depth cache would need to be serialized and passed into a worker thread

[dlasher]

it would be interesting to see where CPU cycles within the program were going, like how investment range affects calc performance:

I suspect this: "INVESTMENT": { "BASE": "BTC", "MIN": 0.0001, "MAX": 0.1, "STEP": 0.0001

takes a lot more work than: "INVESTMENT": { "BASE": "BTC", "MIN": 0.01, "MAX": 0.1, "STEP": 0.01

Right?

[bmino]

That first example will DEFINITELY take more time for each cycle! You can see this with the debug logging in performance.log

DEBUG: Recent calculations completed in 17 ms

Currently this output happens after every 500 cycles. The next release will allow this to be configurable and based on time instead of cycles

[dlasher]

From a measurement standpoint, if it's longer than, what 250ms? we're over 100% CPU?

performance.log:["8/31/2020, 12:01:38 AM"] WARN : Completed 83/84 (98.8%) calculations in 306 ms performance.log:["8/31/2020, 12:01:39 AM"] WARN : Completed 83/84 (98.8%) calculations in 303 ms performance.log:["8/31/2020, 12:01:48 AM"] WARN : Completed 83/84 (98.8%) calculations in 312 ms performance.log:["8/31/2020, 12:01:49 AM"] WARN : Completed 83/84 (98.8%) calculations in 287 ms performance.log:["8/31/2020, 12:01:53 AM"] WARN : Completed 82/84 (97.6%) calculations in 312 ms performance.log:["8/31/2020, 12:01:54 AM"] WARN : Completed 82/84 (97.6%) calculations in 297 ms performance.log:["8/31/2020, 12:01:56 AM"] WARN : Completed 81/84 (96.4%) calculations in 313 ms performance.log:["8/31/2020, 12:02:00 AM"] WARN : Completed 45/84 (53.6%) calculations in 151 ms performance.log:["8/31/2020, 12:02:00 AM"] WARN : Completed 45/84 (53.6%) calculations in 185 ms performance.log:["8/31/2020, 12:02:02 AM"] WARN : Completed 82/84 (97.6%) calculations in 304 ms

[dlasher]

I reduced it to the second example (10 steps), and that drops the processing time a lot:

performance.log:["9/1/2020, 6:33:58 PM"] WARN : Completed 77/81 (95.1%) calculations in 50 ms performance.log:["9/1/2020, 6:34:19 PM"] WARN : Completed 77/81 (95.1%) calculations in 47 ms performance.log:["9/1/2020, 6:34:19 PM"] WARN : Completed 77/81 (95.1%) calculations in 40 ms performance.log:["9/1/2020, 6:34:30 PM"] WARN : Completed 76/81 (93.8%) calculations in 86 ms performance.log:["9/1/2020, 6:34:31 PM"] WARN : Completed 76/81 (93.8%) calculations in 40 ms performance.log:["9/1/2020, 6:34:38 PM"] WARN : Completed 1/81 (1.2%) calculations in 16 ms performance.log:["9/1/2020, 6:34:38 PM"] WARN : Completed 1/81 (1.2%) calculations in 14 ms performance.log:["9/1/2020, 6:34:44 PM"] WARN : Completed 76/81 (93.8%) calculations in 53 ms performance.log:["9/1/2020, 6:34:45 PM"] WARN : Completed 76/81 (93.8%) calculations in 74 ms performance.log:["9/1/2020, 6:34:46 PM"] WARN : Completed 76/81 (93.8%) calculations in 42 ms performance.log:["9/1/2020, 6:34:47 PM"] WARN : Completed 76/81 (93.8%) calculations in 43 ms performance.log:["9/1/2020, 6:34:47 PM"] WARN : Completed 76/81 (93.8%) calculations in 44 ms performance.log:["9/1/2020, 6:34:47 PM"] WARN : Completed 76/81 (93.8%) calculations in 79 ms

Doesn't seem to stop the timeouts (as you can see from the 1/81 example), but it seems better overall.

[dlasher]

Did just fire off a successful trade, but I'm not sure how to read this.. did I come out ahead or not? 👍

["9/1/2020, 6:53:22 PM"] INFO : Attempting to execute BTC-ANKR-BNB with an age of 36 ms and expected profit of 0.4811% ["9/1/2020, 6:53:22 PM"] INFO : Buying 7207 ANKRBTC @ market price ["9/1/2020, 6:53:22 PM"] INFO : Successfully bought 7207.00000000 ANKRBTC @ a quote of 0.00799977 in 42 ms ["9/1/2020, 6:53:22 PM"] INFO : Selling 7207 ANKRBNB @ market price ["9/1/2020, 6:53:22 PM"] INFO : Successfully sold 7207.00000000 ANKRBNB @ a quote of 4.00492990 in 20 ms ["9/1/2020, 6:53:22 PM"] INFO : Selling 4 BNBBTC @ market price ["9/1/2020, 6:53:22 PM"] INFO : Successfully sold 4.00000000 BNBBTC @ a quote of 0.00795680 in 19 ms ["9/1/2020, 6:53:22 PM"] INFO : Executed BTC-ANKR-BNB position in 86 ms ["9/1/2020, 6:53:22 PM"] INFO : ["9/1/2020, 6:53:22 PM"] INFO : BTC delta: -0.00004297 (-0.5371%) ["9/1/2020, 6:53:22 PM"] INFO : ANKR delta: 0.00000000 ( 0.0000%) ["9/1/2020, 6:53:22 PM"] INFO : BNB delta: 0.00492990 ( 0.1232%) ["9/1/2020, 6:53:22 PM"] INFO : BNB commission: -0.00904946

Might be nice to follow up with "expected XXX, got YYYY" info line.

[bmino]

I love it @dlasher we think so similar :D The bot will log EXACTLY what you are asking for, but you need to have debug logging turned on

To analyze what happened:

BTC delta: -0.00004297 (-0.5371%)     // BTC was overall lost... (0.5371%) of the investment quantity
ANKR delta: 0.00000000 ( 0.0000%     // ANKR value did not change
BNB delta: 0.00492990 ( 0.1232%)       // BNB was gained (0.1232%) of the invested quantity
BNB commission: -0.00904946            // 0.00904946 BNB was paid in fees

Overall it looks like a net loss because more % BTC was lost than BNB gained, but something went wrong. The BNB quantity should not have changed; just like the ANKR delta. Those debug logs would help determine what happened.

[dlasher]

Shoot, I thought I had debugging turned up, it was back to info. Fixed.

Wow, it's very spammy now, lots of data.. will have to wait till the next attempt at execution.

This line gives me pause:

Attempting to execute BTC-ANKR-BNB with an age of 36 ms and expected profit of 0.4811%

the net loss (-0.4139%) is not that far off from the "expected profit" so are we maybe looking at some sort of +/- math challenge? Or did the market actually make a 0.895% swing in the 86ms it took to execute the trade?

[bmino]

I've gone through the math manually (with snapshots of the depth snapshots) and the calculations are accurate. It's crazy how something can happen in suuuuch a short time interval. At some point I'd like to compare the depth snapshot used for calculation vs. the filled price/quantities to see EXACTLY what changed.

Logic stands to reason a profitable position arises when 1 of the 3 legs is inefficient compared to the market and the other 2 are within normal pricings. What likely is happening is that some other system (read bot) identified the inefficient ticker and made a trade before this bot did. Then our market order hits ms later and it's too late

[dlasher]

We need a switch to disable the "CPU 1 minute |calculation cycles averaging" output, at least at a high frequency. Maybe set how often it's written/checked? As it stands, It's hitting the performance.log multiple times a second, and it's already 3,684,764,172 in size after less than 24h.

[dlasher]

As an aside, I'm disappointed we didn't try to make some trades during today's dump. Higher periods of volatility are usually ripe for TriArb picking.. Nothing found. :(

Do you have a discord/slack/etc channel set up? Might be better to make some of this realtime, rather than a github conversation)

[bmino]

Yeah I've got a discord and honestly that'd be a great conversation. I see you're on the develop branch haha? There is a config option for how frequently the cpu load stats is displayed (based on time instead of cycles)

[dlasher]

pulled, updated the interval, Good data here:

["9/4/2020, 12:11:14 AM"] DEBUG: Latest 225 calculation cycles averaging 24.56 ms ["9/4/2020, 12:11:14 AM"] DEBUG: CPU 1 minute load averaging 0.2%

Can you throw the "5 server ping" latency check into that loop, and report on it as well? As "most recent experienced latency" ?

[bmino]

Yeah this could be done. I opted not because I didn't think latency would change over time. Are you experiencing issues and want to debug with this info?

[dlasher]

Absolutely, yes. I'm seeing the value reported at startup be anything from 40ms (which is odd, VPS is 2ms away) to 300-400ms, which I think is Binance API/servers feeling the load. I'd like to be able to see that over time, as a datapoint.

[dlasher]

Seems like "mostly" keeping up? I'm not convinced it's CPU..

["9/4/2020, 11:44:38 PM"] WARN : Completed 1/84 (1.2%) calculations in 16 ms ["9/5/2020, 12:01:55 AM"] WARN : Completed 80/84 (95.2%) calculations in 45 ms ["9/5/2020, 12:01:58 AM"] WARN : Completed 80/84 (95.2%) calculations in 79 ms ["9/5/2020, 12:02:02 AM"] WARN : Completed 1/84 (1.2%) calculations in 24 ms ["9/5/2020, 12:02:06 AM"] WARN : Completed 79/84 (94.0%) calculations in 43 ms ["9/5/2020, 12:02:07 AM"] WARN : Completed 81/84 (96.4%) calculations in 50 ms ["9/5/2020, 12:02:07 AM"] WARN : Completed 79/84 (94.0%) calculations in 75 ms ["9/5/2020, 12:02:09 AM"] WARN : Completed 81/84 (96.4%) calculations in 80 ms ["9/5/2020, 12:02:25 AM"] WARN : Completed 81/84 (96.4%) calculations in 76 ms ["9/5/2020, 12:02:29 AM"] WARN : Completed 76/84 (90.5%) calculations in 45 ms ["9/5/2020, 12:02:35 AM"] WARN : Completed 79/84 (94.0%) calculations in 76 ms ["9/5/2020, 12:02:53 AM"] WARN : Completed 81/84 (96.4%) calculations in 78 ms ["9/5/2020, 12:10:03 AM"] WARN : Completed 80/84 (95.2%) calculations in 78 ms ["9/5/2020, 12:10:05 AM"] WARN : Completed 80/84 (95.2%) calculations in 83 ms ["9/5/2020, 12:10:07 AM"] WARN : Completed 79/84 (94.0%) calculations in 77 ms ["9/5/2020, 12:10:21 AM"] WARN : Completed 79/84 (94.0%) calculations in 75 ms ["9/5/2020, 12:10:26 AM"] WARN : Completed 1/84 (1.2%) calculations in 34 ms ["9/5/2020, 12:10:30 AM"] WARN : Completed 81/84 (96.4%) calculations in 48 ms ["9/5/2020, 12:10:32 AM"] WARN : Completed 77/84 (91.7%) calculations in 42 ms ["9/5/2020, 12:10:37 AM"] WARN : Completed 77/84 (91.7%) calculations in 82 ms ["9/5/2020, 12:10:39 AM"] WARN : Completed 80/84 (95.2%) calculations in 78 ms ["9/5/2020, 12:10:40 AM"] WARN : Completed 80/84 (95.2%) calculations in 78 ms ["9/5/2020, 12:10:41 AM"] WARN : Completed 80/84 (95.2%) calculations in 49 ms ["9/5/2020, 12:10:43 AM"] WARN : Completed 79/84 (94.0%) calculations in 46 ms ["9/5/2020, 12:10:44 AM"] WARN : Completed 79/84 (94.0%) calculations in 49 ms ["9/5/2020, 12:10:53 AM"] WARN : Completed 81/84 (96.4%) calculations in 42 ms ["9/5/2020, 12:11:05 AM"] WARN : Completed 80/84 (95.2%) calculations in 79 ms ["9/5/2020, 12:11:24 AM"] WARN : Completed 79/84 (94.0%) calculations in 78 ms ["9/5/2020, 12:12:59 AM"] WARN : Completed 1/84 (1.2%) calculations in 16 ms ["9/5/2020, 12:13:23 AM"] WARN : Completed 80/84 (95.2%) calculations in 44 ms ["9/5/2020, 12:22:52 AM"] WARN : Completed 1/84 (1.2%) calculations in 15 ms ["9/5/2020, 12:22:53 AM"] WARN : Completed 1/84 (1.2%) calculations in 51 ms ["9/5/2020, 12:29:57 AM"] WARN : Completed 81/84 (96.4%) calculations in 84 ms ["9/5/2020, 12:30:02 AM"] WARN : Completed 1/84 (1.2%) calculations in 21 ms ["9/5/2020, 12:30:04 AM"] WARN : Completed 79/84 (94.0%) calculations in 94 ms ["9/5/2020, 12:30:05 AM"] WARN : Completed 81/84 (96.4%) calculations in 78 ms ["9/5/2020, 12:30:08 AM"] WARN : Completed 81/84 (96.4%) calculations in 46 ms ["9/5/2020, 12:30:09 AM"] WARN : Completed 80/84 (95.2%) calculations in 82 ms ["9/5/2020, 12:30:14 AM"] WARN : Completed 80/84 (95.2%) calculations in 76 ms ["9/5/2020, 12:30:15 AM"] WARN : Completed 80/84 (95.2%) calculations in 81 ms ["9/5/2020, 12:30:33 AM"] WARN : Completed 79/84 (94.0%) calculations in 48 ms ["9/5/2020, 12:31:33 AM"] WARN : Completed 80/84 (95.2%) calculations in 45 ms ["9/5/2020, 12:31:35 AM"] WARN : Completed 80/84 (95.2%) calculations in 76 ms ["9/5/2020, 12:31:52 AM"] WARN : Completed 81/84 (96.4%) calculations in 93 ms ["9/5/2020, 12:31:57 AM"] WARN : Completed 1/84 (1.2%) calculations in 19 ms ["9/5/2020, 12:32:01 AM"] WARN : Completed 81/84 (96.4%) calculations in 49 ms ["9/5/2020, 12:32:16 AM"] WARN : Completed 80/84 (95.2%) calculations in 43 ms ["9/5/2020, 12:42:02 AM"] WARN : Completed 1/84 (1.2%) calculations in 17 ms ["9/5/2020, 12:42:51 AM"] WARN : Completed 80/84 (95.2%) calculations in 83 ms ["9/5/2020, 12:42:53 AM"] WARN : Completed 81/84 (96.4%) calculations in 86 ms ["9/5/2020, 12:42:55 AM"] WARN : Completed 80/84 (95.2%) calculations in 99 ms ["9/5/2020, 12:42:59 AM"] WARN : Completed 81/84 (96.4%) calculations in 87 ms ["9/5/2020, 12:42:59 AM"] WARN : Completed 80/84 (95.2%) calculations in 79 ms ["9/5/2020, 12:43:02 AM"] WARN : Completed 79/84 (94.0%) calculations in 41 ms

[bmino]

Pinging a host is different than the latency to a host. In simple terms latency should be at least twice as long as ping since it includes the return trip. Latency in this bot also includes basic server processing time since it uses a basic api endpoint.

I put in some additional metric tracking in 5.6.1 which should address this specific issue