execution.Time & Time[0] differing significantly

[ChainsawDR]

Hi,
My live strategy did something very odd today and hoping to ask a few questions to help me debug and protect against this happening again. My strategy calculates OnBarClose using a 10sec dataseries, and a 1 tick dataseries. I set off my strategy around 9.20am and it had been running for approximately 40mins before it entered a Buy trade at 9:59:20 AM. It then immediately sent an exit order for the same time. In my backtest this doesn't happen. I print to output at various points in my strategy and its showing an odd scenario outlined below that I'm trying to debug please...

What happened:
Within my strategy only the 10sec bars can trigger a trade (1 tick series can trigger an exit). When a Buy Order is submitted it's set to print like this:
Print Code:

"Buying at Time: " +Time[0] + " and Bar: " +CurrentBar + ", Ticker: " + Instrument.FullName;

Today's Output: Buying at Time: 8/25/2022 9:59:20 AM and Bar: 8955, Ticker: DRUG

Within OnExecutionUpdate I'm trying to monitor the fills using the following code (not doing anything with it yet, just trying to log fills properly):

Code inc Print code

protected override void OnExecutionUpdate(Execution execution, string executionId, double price, int quantity, MarketPosition marketPosition, string orderId, DateTime time)
{

if (entryOrder != null && entryOrder == execution.Order)
{
if (execution.Order.OrderState == OrderState.Filled || execution.Order.OrderState == OrderState.PartFilled || (execution.Order.OrderState == OrderState.Cancelled && execution.Order.Filled > 0))
{
// We sum the quantities of each execution making up the entry order
sumFilled += execution.Quantity;
Print(execution.Time + ", Time: " + Time[0] + ", We sum the quantities of each execution making up the entry order, " + Instrument.FullName + ", " + execution.Order.OrderState + ", " + execution.Order.Filled + ", SUMFILLED: " + sumFilled + ", " + entryOrder);
...

Todays Output: 8/25/2022 9:59:20 AM, Time: 8/25/2022 9:53:41 AM, We sum the quantities of each execution making up the entry order, DRUG, Filled, 3600, SUMFILLED: 500, orderId='XXXXXX' account='XXXXXXX' name='BuyLong' orderState=Filled instrument='DRUG' orderAction=Buy orderType='Market' limitPrice=0 stopPrice=0 quantity=3,600 tif=Gtc oco='' filled=3600 averageFillPrice=2.749385 onBehalfOf='' id=XXX time='2022-08-25 09:59:20' gtd='2099-12-01' statementDate='2022-08-25'


I've highlighted in underline and bold the odd thing. execution.Time = 9:59:20 AM while Time[0] =9:53:41 AM. Earlier at 9.53.41AM the price was much higher, and so my strategy sent a take-profit exit order because it believed the Close was much higher (~$2.90 vs $2.75). I ran a backtest afterwards and this order-and-immediately-exit issue never happened, so I'm trying to figure out what may have happened so I can code to avoid this in future. Here are my best guesses, but please let me know if you have any other ideas:
1. NT8 was up to speed processing 10sec bars but was delayed by almost 6mins processing ticks, and Time[0] was showing the time on the 1 tick series - (highly unlikely but listing it anyway)
2. A delayed tick was received at 9:59:20 AM for 9.53.41AM - as my code isn't checking the timestamp of each tick it processed its Close price as current and submitted a takeprofit exit.

Questions:
A) Can you think of any other reason why execution.Time & Time[0] would differ by 6mins?
B) If it is likely scenario #2, any advice to guard against this? E.g. should I always keep a record of the latest time, and if a tick arrives from the past ignore it?
C) Is the processing of onexecutionupdate tied into a dataseries or are updates here event tracked outside of dataseries timebounds? e.g. does OnExecutionUpdate only process if a tick is received, or a 10sec bar completes, or will it update on its on timeline?

Thanks in advance for any help you can provide with this

ChainsawDR

EDIT: In case it is helpful, the strategy was processing 3 days data (but had been running for 40mins and showed as green in the strategy tab as synced, so I presume it was all up to date).

[NinjaTrader_Emily]

Hello ChainsawDR,

Thank you for your post.

I would like to start by answering your third question first:
"C) Is the processing of onexecutionupdate tied into a dataseries or are updates here event tracked outside of dataseries timebounds? e.g. does OnExecutionUpdate only process if a tick is received, or a 10sec bar completes, or will it update on its on timeline?"

OnExecutionUpdate() is an event-driven method. It is not tied to a data series; it relies on updates regarding order fills received through the data connection with your broker. For additional details, please see the following page:

https://ninjatrader.com/support/helpGuides/nt8/onexecutionupdate.htm

As for your other two questions, I am curious about your logic and print statements with regard to the use of multiple time frames. Since you are using a 10-second data series and a 1-tick data series, please refer to the following page for more details about Multi-Time Frame & Instruments:

https://ninjatrader.com/support/helpGuides/nt8/multi-time_frame__instruments.htm

It is important that you are submitting orders using the proper BarsInProgress index, as well as using the desired indexes for the time (time of the primary data series or the secondary data series) as needed in your print statements. Since your entries are only supposed to be submitted on the 30-second data series that is processing On Bar Close, I would expect the times from the prints to be in 30-second increments. 9:59:20 AM does not seem accurate here.

Additionally, what is the time shown in the Executions tab of the control center (or in the Trade Performance report) for the entry and exit? You could also compare this to the Orders tab (or Orders report in the Trade Performance) and see the time reported for when the order was in a Submitted state vs. Filled. This may differ from the backtest results because of how historical orders are filled based on the OHLC values. You mentioned your strategy is set to process On Bar Close, and historical orders are also only processed at the close of each bar. Since you are seeing a discrepancy, I recommend reviewing your strategy's logic in regard to the multiple time frames to make sure that entries truly are only being submitted on the 30-second series. We have more information regarding real-time vs. backtest discrepancies here:

https://ninjatrader.com/support/helpGuides/nt8/discrepancies_real-time_vs_bac.htm

Please let me know if I may be of further assistance.

[ChainsawDR]

Hi Emily, just a brief response - the series is running on 10secs not 30secs, does that make a difference to your reply? (Apologies if I’ve said 30secs somewhere)

[NinjaTrader_Emily]

Hello ChainsawDR,

Thank you for pointing that out.

For some reason I had it in my head that you were using 30 seconds, although going back and reading your post I don't know where I got that value from. I would still like to focus on this part of my reply:

"Additionally, what is the time shown in the Executions tab of the control center (or in the Trade Performance report) for the entry and exit? You could also compare this to the Orders tab (or Orders report in the Trade Performance) and see the time reported for when the order was in a Submitted state vs. Filled. This may differ from the backtest results because of how historical orders are filled based on the OHLC values."

It is also important to keep in mind the Multi-Time Frame & Instruments information and be sure to reference the proper BarsInProgress or BarsArray for your conditions, actions, and print statements.

Thank you for your patience.

[ChainsawDR]

Hi Emily,
Thanks for your response. There is no difference between the entry times in both live & backtest, only the exit (as the live system exited immediately, presumably because of a 6 minute old tick being processed as current). I did go back through my code and ensured that both the EnterLong & ExitLong are using the BarsInProgress:0 for my primary 10sec dataseries.

EnterLong(barsInProgressIndex:0, quantity:myOrderQty, signalName:"BuyLong");

I've attached an output from the NinjaTrader today. I've highlighted that OnExecutionUpdate is sometimes firing on BarsInProgress:1. Note: the EnterLong code copied above is the only line of code in the strategy that can place an order.

Am I correct in thinking that when OnExecutionUpdate is called (by an event from the broker), that it uses whichever was the last bar or dataseries that was processed last, irrespective of which dataseries it was (e.g. the strategy has just processed a 1-tick bar that is BarsInProgress:1 - therefore OnExecutionUpdate will show the time and bar for index 1?). Otherwise, why else would onexecutionupdate return barsinprogress:1 please?

If so, then the reason why my code previously showed a 6min old tick must have been because either A) it was 6mins delayed in processing tick data, or B) my datafeed sent an 'out of time' old tick for 6mins ago that was just received and processed as current (hence exiting a position because the system thought the price was at a high point that was really 6mins earlier).

[NinjaTrader_Emily]

Hello ChainsawDR,

Thank you for your patience.


BarsInProgress is updated based on whichever bars object called OnBarUpdate() most recently. When OnExecutionUpdate() is called it will not matter which data is being processed in OnBarUpdate() so it would be possible for you to get BarsInProgress 0 or BarsInProgress 1.

I would like to review your diagnostic files to better understand what occurred and provide an accurate analysis of what happened. Please send me your log and trace files so that I may look into what occurred.

You can do this by going to the Control Center-> Help-> Email Support

Ensuring 'Log and Trace Files' is checked will include these files. This is checked by default.

Please include a link to this forum thread and reference the following information in the subject line: ATTN Emily 03171429

Additionally, in the body of the message, please include the Order ID number for the Exit order in question.

Thanks in advance; I look forward to resolving this item with you.

[ChainsawDR]

Hi Emily,

Thanks for this. "BarsInProgress is updated based on whichever bars object called OnBarUpdate() most recently" - this is super helpful, thank you. I prefer not to share the full log and trace files but now I know that the reason for the time difference is because of either a delay in processing, or a delayed/old tick coming through as current, I'll soon write a reduced/simpler script to monitor and alert for this (and if I see it here, I'll share the log and trace files for it).

Thanks again for your help with this.

Dean