Delays for live trading

[cuberone]

Bug Report

After fixing the delays for live trading, I found a new random delay when reaching Exec Client. See the log (0.2 s)

{"timestamp":"2024-04-27T10:47:10.444593358Z","trader_id":"NODE-1","level":"INFO","color":"NORMAL","component":"GridSimple","message":"<--[EVT] OrderInitialized(instrument_id=BTCUSDT-PERP.BINANCE, client_order_id=O-20240427-1047-1-01-11, side=BUY, type=LIMIT, quantity=0.512, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'price': '62566.0', 'display_qty': None, 'expire_time_ns': 0}, emulation_trigger=NO_TRIGGER, trigger_instrument_id=None, contingency_type=NO_CONTINGENCY, order_list_id=None, linked_order_ids=None, parent_order_id=None, exec_algorithm_id=None, exec_algorithm_params=None, exec_spawn_id=None, tags=['78'])"}
{"timestamp":"2024-04-27T10:47:10.444722465Z","trader_id":"NODE-1","level":"INFO","color":"NORMAL","component":"GridSimple","message":"[CMD]--> SubmitOrder(order=LimitOrder(BUY 0.512 BTCUSDT-PERP.BINANCE LIMIT @ 62566.0 GTC, status=INITIALIZED, client_order_id=O-20240427-1047-1-01-11, venue_order_id=None, position_id=None, tags=['78']), position_id=None)"}
{"timestamp":"2024-04-27T10:47:10.444903651Z","trader_id":"NODE-1","level":"INFO","color":"NORMAL","component":"GridSimple","message":"<--[EVT] OrderInitialized(instrument_id=BTCUSDT-PERP.BINANCE, client_order_id=O-20240427-1047-1-01-12, side=SELL, type=LIMIT, quantity=0.512, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'price': '62880.0', 'display_qty': None, 'expire_time_ns': 0}, emulation_trigger=NO_TRIGGER, trigger_instrument_id=None, contingency_type=NO_CONTINGENCY, order_list_id=None, linked_order_ids=None, parent_order_id=None, exec_algorithm_id=None, exec_algorithm_params=None, exec_spawn_id=None, tags=['80'])"}
{"timestamp":"2024-04-27T10:47:10.444990472Z","trader_id":"NODE-1","level":"INFO","color":"NORMAL","component":"GridSimple","message":"[CMD]--> SubmitOrder(order=LimitOrder(SELL 0.512 BTCUSDT-PERP.BINANCE LIMIT @ 62880.0 GTC, status=INITIALIZED, client_order_id=O-20240427-1047-1-01-12, venue_order_id=None, position_id=None, tags=['80']), position_id=None)"}
{"timestamp":"2024-04-27T10:47:10.620145096Z","trader_id":"NODE-1","level":"INFO","color":"BLUE","component":"ExecClient-BINANCE","message":"Submit LimitOrder(BUY 0.512 BTCUSDT-PERP.BINANCE LIMIT @ 62566.0 GTC, status=INITIALIZED, client_order_id=O-20240427-1047-1-01-11, venue_order_id=None, position_id=None, tags=['78'])"}
{"timestamp":"2024-04-27T10:47:10.620297554Z","trader_id":"NODE-1","level":"INFO","color":"BLUE","component":"ExecClient-BINANCE","message":"Submit LimitOrder(SELL 0.512 BTCUSDT-PERP.BINANCE LIMIT @ 62880.0 GTC, status=INITIALIZED, client_order_id=O-20240427-1047-1-01-12, venue_order_id=None, position_id=None, tags=['80'])"}
{"timestamp":"2024-04-27T10:47:10.621388545Z","trader_id":"NODE-1","level":"INFO","color":"NORMAL","component":"GridSimple","message":"<--[EVT] OrderSubmitted(instrument_id=BTCUSDT-PERP.BINANCE, client_order_id=O-20240427-1047-1-01-11, account_id=BINANCE-spot-master, ts_event=1714214830620404417)"}
{"timestamp":"2024-04-27T10:47:10.621456529Z","trader_id":"NODE-1","level":"INFO","color":"NORMAL","component":"GridSimple","message":"<--[EVT] OrderSubmitted(instrument_id=BTCUSDT-PERP.BINANCE, client_order_id=O-20240427-1047-1-01-12, account_id=BINANCE-spot-master, ts_event=1714214830620927488)"}

There is still a direct call to _queue.put_nowait() in the code in nautilus_trader/common/executor.py, but I'm not sure if this is the cause of the delay since there were no delays in v1.180.

Specifications

• Python version: 3.12
• nautilus_trader version: v1.191.0

[cjdsellers]

Hi @cuberone

Thanks for sharing your observations.

I would say the ActorExecutor doesn't play a part in this unless you are actually using the Nautilus executor in your code? How consistent is this delay? I haven't done any detailed measurements for a while, are the Python GC events observable?

[cuberone]

Cannot reproduce

[cjdsellers]

Thanks for the update, I also couldn't see a consistent delay in that area from a light logs audit. My best guess is as above - some GC or even OS level event.

I know there are some users consistently tracking these metrics during live trading so I'll reach out and see if I can dig up any issues around this.