Trading System Development and Investigation Memo (2)

Dec 9, 2018, 9:18 AM

about24mins to read

investment

Top
Hypothesis 2-2: The reason for closing in a few seconds is due to the deviation in price caused by the time lag
Detailed Data
Simple Investigation
Detailed Investigation
Conclusion 2-2
Hypothesis 3: BF WebSocket data is delayed by more than 500ms in over 75% of cases
Measurement Method
Measurement Results
Conclusion 3
Hypothesis 4: In IFD orders, there is always a delay of at least 1 second until execution, even during normal trading hours
Data Collection
Conclusion 4
Summary

Continuing from the previous article, I will investigate the behavior of the bot that caught my attention.

The previous article is here.

This time, the main focus is on measuring delays.

Hypothesis 2-2: The reason for closing in a few seconds is due to the deviation in price caused by the time lag

This is a continuation of the previous article.

Let's 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 received at 2018-12-02 01:39:27 UTC
The order was executed about 2 seconds later (2018-12-02 01:39:28.873 UTC)
The execution price at the time of opening was 482126.0
The closing price was executed about 3 seconds later (2018-12-02 01:39:31.763), at 482311 and 482283

Detailed Data

Here is the execution data for the opening order. 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"
}

And here is the closing order.

{
    "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"
},

Simple Investigation

Although it is necessary to investigate the execution price history in detail, let's first use 1-minute data to examine it simply. I looked at the candlestick chart on Trading View at that time.

Low: 480860, High: 482761

It is clear that the price was within the range of the low and high prices. There is no doubt that the price was deviated at that time.

Detailed Investigation

We need to confirm the bid/ask prices shown by BF at that time. This can be confirmed by fetching the execution history and storing it in a database. Using a Python tool, I obtained the following output.

The history is available, and it seems that the prices did not deviate significantly. Then, what about 2 seconds before the order was received (2018-12-02 01:39:27 UTC), 4 seconds before the bot sent the order, and 6 seconds before the WebSocket data was sent?

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)
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)
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 about 4,000 yen different from 477018-476834. In reality, the price that exceeded 477018 was at 01:31:42.950000, about 8 minutes before. It is unlikely that the WebSocket data was delayed for such a long time.

This suggests that the local price data was incorrect. Since I didn't have a log of the price data, I couldn't investigate further. I'll investigate again if it happens.

Conclusion 2-2

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

There was no deviation of over 5,000 yen as seen in the Motivating Example. If the execution history and WebSocket data are correct, it means that there is a bug in the bot. I'll verify it again when I reproduce it.

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

In Hypothesis 1, it was suggested that the WebSocket data from BitFlyer might be significantly delayed. This delay can cause the bot's behavior to slow down and affect the accuracy of triggers and SL/TP settings.

Although there is some overhead due to network delays, I'll investigate whether the delay is more than 500ms even when the server is in good condition.

Measurement Method

I ran the following program on GCP's asia-northeast1 for several hours. Since it is lightweight, I used an f1-micro instance.

I measured the delay every 10 messages and output it to an external file.

Measurement Results

I obtained 46,359 data points over about 20 hours. The unit is ms.

Oh, the outliers are too extreme, making the graph unclear. Even if I remove the outliers, the graph remains similar, so let's look at the numerical values.

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

Wait, what's with the negative values?! The possible causes are as follows, but the first one is quite plausible.

BF is sending data with future timestamps
There is a bug in the measurement program
The data is being sent at a speed faster than light

The maximum delay was 28.7 seconds, and the minimum delay was -80ms, resulting in an absurd outcome. However, looking at the 75% percentile, the delay was around 181ms, which is better than the initial hypothesis.

I also calculated the delay considering the measurement time, but it didn't affect the result.

Conclusion 3

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

The measurement result showed that the delay was around 181ms at the 75% percentile.

If there is no bug in the measurement tool, the reliability of the data being sent is questionable.

Hypothesis 4: In IFD orders, there is always a delay of at least 1 second until execution, even during normal trading hours

This is another issue discovered in the previous investigation. During the start of trading (IFD orders), there was a delay of 2-4 seconds until execution. Here, I'll investigate whether this always happens.

Data Collection

This can be easily investigated using the existing execution data. First, I obtained the parent order list using /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 the parent_order_id, I fetched the corresponding child orders from /v1/me/getchildorders. The result includes the execution results of TP/SL, so I only used 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, I obtained the execution time using /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"
}

For example, the delay can be calculated as follows.

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

Oh dear, it's delayed by 10 seconds... This is not a normal execution.

I wrote a simple program to calculate the delay for the latest 100 orders.

Looking at the data, I get a sense of excitement: " Oh, there's a delay... Ah, it's quite short... Wait, what's with the negative values?! " Negative values are strange, but they were also seen in Hypothesis 3. Maybe it's due to the distribution of the database or write delays. Anyway, I won't trust the sent data too much.

Let's plot the data as a box plot.

There are outliers with delays of around 20 seconds, but the median is around 1 second. Considering the continuity of the data, it seems that the exchange's condition has a significant impact. Although I couldn't record the exchange's condition, I'll investigate it further if it affects losses.

            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, there is always a delay of at least 1 second until execution, even during normal trading hours

In the latest 100 orders, about 50% of the orders were executed within 1 second, so it's not always the case that there is a delay of at least 1 second.

The relationship with losses is still unknown, but it might be good to shorten the expire time to cut off delayed orders.

Summary

Although I didn't reduce the essential losses in this investigation, it's good to consider these points when creating a bot.

Next time, I'll think about countermeasures for the delays discovered this time. For example, I'll consider the following hypotheses:

Is it possible to execute parent orders faster than child orders?
Can we reduce losses by stopping new orders when the WebSocket delay is large?