Trading System Development and Research Notes (2)

I continue to investigate the areas of concern in the bot's behavior.
Here's the previous article.

https://www.esplo.net/posts/2018/12/bf-bot-rd-1

This time, the main focus is on measuring delays.

Hypothesis 2-2: The reason for closing within a few seconds is due to execution at prices that have deviated due to time lag

This is homework from last time.

I'll organize the information from the Motivating Example in the previous article.

• Local price data is around 477018-476834 (spread of about 180 yen)
• The order was accepted at 2018-12-02 01:39:27 UTC
• Executed about 2 seconds later (2018-12-02 01:39:28.873 UTC)
• The opening execution price was 482126.0
• Closed 3 seconds later (2018-12-02 01:39:31.763), executed at 482311 and 482283

Detailed Data

This is the execution data for the opening. The execution price is 482126.0.

{
    "id": 613460271,
    "side": "BUY",
    "price": 482126,
    "size": 0.02,
    "exec_date": "2018-12-02T01:39:28.873",
    "child_order_id": "JFX20181202-013928-512467F",
    "commission": 0,
    "child_order_acceptance_id": "JRF20181202-013927-012822"
}

This is for closing.

{
    "id": 613460418,
    "side": "SELL",
    "price": 482311,
    "size": 0.01,
    "exec_date": "2018-12-02T01:39:31.763",
    "child_order_id": "JFX20181202-013931-517900F",
    "commission": 0,
    "child_order_acceptance_id": "JRF20181202-013927-012831"
},
{
    "id": 613460419,
    "side": "SELL",
    "price": 482283,
    "size": 0.01,
    "exec_date": "2018-12-02T01:39:31.763",
    "child_order_id": "JFX20181202-013931-517900F",
    "commission": 0,
    "child_order_acceptance_id": "JRF20181202-013927-012831"
},

Brief Investigation

For details, I need to search through the execution price history, but first, I'll use the easily accessible 1-minute candle data. I looked at the candles from that time on Trading View.

Low: 480860, High: 482761

Indeed, it falls between the low and high. There's no doubt that it was distributed at that price.

Detailed Investigation

I need the bid/ask shown by BF at that time. This needs to be confirmed from the execution history. Using a Python tool that continuously fetches execution history and dumps it into a DB, I obtained the following output.

There's indeed a history. Looking at nearby prices, there doesn't seem to be a significant deviation. So what about about 2 seconds before the order was accepted (2018-12-02 01:39:27 UTC), about 4 seconds before when the bot likely sent the order, and about 6 seconds before when the data was likely sent from WebSocket?

• About 2 seconds before (01:39:27.000)
  • bid: 481827 (2018-12-02 01:39:26.450000)
  • ask: 482211 (2018-12-02 01:39:26.997000)
• About 4 seconds before (01:39:25.000)
  • bid: 481796 (2018-12-02 01:39:24.950000)
  • ask: 481849 (2018-12-02 01:39:24.997000)
• About 6 seconds before (01:39:23.000)
  • bid: 481499 (2018-12-02 01:39:22.920000)
  • ask: 481630 (2018-12-02 01:39:22.873000)

Even going back 6 seconds, the price was nearly 4,000 different from 477018-476834.
In fact, the price that fell below 477018 was at 01:31:42.950000, almost 8 minutes earlier.
This is too long to consider that the price data from WebSocket was delayed.

From this, it seems that the locally held price data was incorrect. Since I didn't output logs of the price data, no further investigation is possible. I'd like to investigate again if it occurs again.

Conclusion 2-2

The reason for closing within a few seconds is not just due to time lag.

There was no deviation of over 5000 yen as seen in the Motivating Example. If the execution history and data distributed from WebSocket are correct, then there must be a bug in the bot. I'll verify again when it recurs.

Hypothesis 3: Data from BF WebSocket is delayed by more than 500ms in over 75% of cases

In hypothesis 1, the possibility emerged that the price data from BitFlyer's WebSocket was significantly delayed. When data is delayed, it leads to sluggish movement, causing phenomena such as decreased trigger accuracy and incorrect SL/TP settings.

Although there's a certain overhead due to network delay, assuming that over 500ms is considered a delay, I'll investigate whether this occurs even when the server is in good condition.

Measurement Method

I'll run the following program on GCP's asia-northeast1 for several hours. Since it's lightweight, I'm using an f1-micro instance.

https://gist.github.com/esplo/abbe146f543ea50e27613e093f25a106

It measures the delay once every 10 messages and outputs to an external file.
The definition of delay here is the difference between the time data included in the execution history message and the time when it was received.

After a while, I downloaded this data locally and plotted it in a box-and-whisker plot.

Measurement Results

After running for about 20 hours, 46359 data points were obtained. The unit is ms.

Oops, the outliers are so extreme that the graph became incomprehensible. Even after removing one outlying data point, the graph looked similar, so let's look at the numbers.

46359 rows
  2018-12-04 21:47:51 - 2018-12-05 17:13:29
count    46359.000000
mean       184.676228
std        398.884247
min        -80.261000
25%         76.384500
50%        105.105000
75%        181.621000
max      28782.979000

N-Negative!? The possible causes are as follows, but it's scary that #1 seems the most likely...

1. BF is distributing with future timestamps
2. There's a bug in the measurement program
3. Occasionally, distribution faster than the speed of light occurs

The maximum delay was 28.7 seconds, and the minimum delay was -80ms, which is an outrageous result, but looking at the 75th percentile, it's 181ms, which is better than the initial hypothesis. It seems to be a system that becomes thoroughly erratic when unstable.

I also calculated considering the measurement time just in case, but it didn't particularly affect the results.

Conclusion 3

Hypothesis 3: Data from BF WebSocket is delayed by more than 500ms in over 75% of cases

Upon measurement, it was about 181ms for 75% of the cases.

Assuming there's no bug in the measurement tool, there are times when the reliability of the distributed data is questionable.

Hypothesis 4: In IFD orders, even on a normal exchange, there's always a delay of more than 1 second until execution

This is another issue discovered in the previous investigation. At the start of trading (IFD order), there was a delay of about 2-4 seconds until actual execution. Here, I'll investigate whether this occurs every time.

Data Collection

This can be easily investigated using the execution data we've had so far. First, I'll retrieve a list of Parent Orders like this (/v1/me/getparentorders).

{
    "id": 141298782,
    "parent_order_id": "JCP20181204-033429-568254",
    "product_code": "FX_BTC_JPY",
    "side": "BUYSELL",
    "parent_order_type": "IFDOCO",
    "price": 0,
    "average_price": 428902,
    "size": 0.03,
    "parent_order_state": "COMPLETED",
    "expire_date": "2018-12-11T02:14:29.057",
    "parent_order_date": "2018-12-04T03:34:29.057",
    "parent_order_acceptance_id": "JRF20181204-033429-761002",
    "outstanding_size": 0,
    "cancel_size": 0,
    "executed_size": 0.02,
    "total_commission": 0
}

Using this parent_order_id, I'll pull the corresponding order from /v1/me/getchildorders. Since it returns execution results including TP/SL, I'll only use the last element.

[
    {
        "id": 740343317,
        "child_order_id": "JFX20181204-033457-094572F",
        "product_code": "FX_BTC_JPY",
        "side": "BUY",
        "child_order_type": "MARKET",
        "price": 0,
        "average_price": 429188,
        "size": 0.01,
        "child_order_state": "COMPLETED",
        "expire_date": "2018-12-11T02:14:29",
        "child_order_date": "2018-12-04T03:34:43",
        "child_order_acceptance_id": "JRF20181204-033429-568286",
        "outstanding_size": 0,
        "cancel_size": 0,
        "executed_size": 0.01,
        "total_commission": 0
    },
    {
        "id": 740342477,
        "child_order_id": "JFX20181204-033439-068825F",
        "product_code": "FX_BTC_JPY",
        "side": "SELL",
        "child_order_type": "MARKET",
        "price": 0,
        "average_price": 428616,
        "size": 0.01,
        "child_order_state": "COMPLETED",
        "expire_date": "2018-12-11T02:14:29",
        "child_order_date": "2018-12-04T03:34:29",
        "child_order_acceptance_id": "JRF20181204-033429-568263",
        "outstanding_size": 0,
        "cancel_size": 0,
        "executed_size": 0.01,
        "total_commission": 0
    }
]

Finally, using this child_order_id, I'll get the execution time from /v1/me/getexecutions.

{
    "id": 619456202,
    "side": "SELL",
    "price": 428616,
    "size": 0.01,
    "exec_date": "2018-12-04T03:34:39.583",
    "child_order_id": "JFX20181204-033439-068825F",
    "commission": 0,
    "child_order_acceptance_id": "JRF20181204-033429-568263"
}

In this example, the delay can be calculated as follows:

• Parent order acceptance: 2018-12-04T03:34:29.057 ("parent_order_date" from getparentorders)
• Child order placement: 2018-12-04T03:34:29 ("child_order_date" from getchildorders)
• Child order execution: 2018-12-04T03:34:39.583 ("exec_date" from getexecutions)

Oh no, there's a 10-second delay from placement to execution... It doesn't seem like a market order.

Now that I understand the calculation method, I'll write a simple program to output the delay for the most recent 100 orders.

10.000526
14.999824
22.000062
17.999986
5.999754
5.99966
21.999919
2.000142
2.000186
11.00037
8.000848
6.99988
0.000701
14.999447
13.999612
6.000358
5.000455
24.999334
24.000833
26.999897
21.000389
4.3e-05
...
0.00028
0.000204
0.000186
3.00005
2.00075
-8e-06
1.000091
0.00017
-0.000581
0.0002
-0.000178
0.00017
...
0.999356
2.000106
-0.000269
0.000326
1.000101
...
0.00024
7e-06
0.00029

Looking at the data from the top, you'll have a fun time thinking, "As expected, there's a delay... Oh, it's quite short... N-Negative!?" The negative values are strange, but we saw this in the WS of hypothesis 3 as well, so maybe that's just how it is. This time, it could still be explained if we consider that the DB is distributed or there's a write delay. In any case, we shouldn't overly trust the distributed data.

Now, if we plot this in a box-and-whisker diagram, it looks like this:

While there are outliers with delays of nearly 20 seconds, the median is almost 1 second. Considering the continuity of the data, it seems that the impact of the exchange's condition is very significant. The exchange's condition is not recorded, so we can't know for sure, but if it seems to affect losses, I'd like to investigate when the opportunity arises.

            delay
count  100.000000
mean     4.870090
std      7.284449
min     -0.000581
25%      0.000242
50%      1.000096
75%      7.000057
max     26.999897
median 1.000096

Conclusion 4

Hypothesis 4: In IFD orders, even on a normal exchange, there's always a delay of more than 1 second until execution

In the most recent 100 orders, nearly 50% of orders were executed within 1 second, so we can't say that there's always a delay of more than 1 second.

Although I haven't investigated the relationship with losses yet, it might be good to cut delayed orders by shortening the expire time.

Summary

Once again, this investigation didn't directly reduce essential losses, but it's worthwhile as it needs to be considered when creating bots.

Next time, I'll consider countermeasures for the delays we've discovered. For example, I plan to address hypotheses such as:

• Wouldn't child orders execute faster than parent orders?
• Wouldn't losses decrease if we stop new orders when there's a large delay from WS?