Delayed market order execution

[guidalpi]

Hello,

I´m testing my own developed strategy and during the historical processing the orders are not being processed as I expected.

For example, by analysing my strategy logs, the order was submitted on the bar closed at 14/06/2018 11:05:55, and reached the "working state" almost instantly. But it is filled only on the bar closed at 21/06/2018 22:16:58 (see below).

Is this the normal behaviour? Or am I missing something?

I´ve tested the same strategy on playback connection (historical and market replay data) and in the strategy analyser and the results are OK (as expected).

Regards.

T14/06/2018 11:05:55;O2786,75;H2792,75;L2786,25;C2792,75;V1694 07
orderId='NT-00000-32' account='Sim101' name='MultiHamaBuy' orderState=Submitted instrument='ES 09-18' orderAction=Buy orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=0 averageFillPrice=0 onBehalfOf='' id=-1 time='2018-06-22 00:12:01' gtd='2099-12-01' statementDate='2018-06-22'

orderId='NT-00000-32' account='Sim101' name='MultiHamaBuy' orderState=Accepted instrument='ES 09-18' orderAction=Buy orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=0 averageFillPrice=0 onBehalfOf='' id=-1 time='2018-06-22 00:12:01' gtd='2099-12-01' statementDate='2018-06-22'

orderId='NT-00000-32' account='Sim101' name='MultiHamaBuy' orderState=Working instrument='ES 09-18' orderAction=Buy orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=0 averageFillPrice=0 onBehalfOf='' id=-1 time='2018-06-22 00:12:01' gtd='2099-12-01' statementDate='2018-06-22'

T21/06/2018 22:16:58;O2750,5;H2756,5;L2750,5;C2756,5;V9800
orderId='NT-00000-32' account='Sim101' name='MultiHamaBuy' orderState=Filled instrument='ES 09-18' orderAction=Buy orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=10 averageFillPrice=2758.5 onBehalfOf='' id=-1 time='2018-06-22 00:12:01' gtd='2099-12-01' statementDate='2018-06-22'

[NinjaTrader_Jesse]

Hello guidalpi,

Welcome to the NinjaTrader support forums.

I wanted to further clarify what you are seeing here.

From what I can tell, all of your log statements here are on the same date/time: time='2018-06-22 00:12:01' so it seems the submission and progression of the order seem standard.

Where do you currently have your Print statements that you are comparing in your script? Also what bars type is currently being used for the strategy?

I look forward to being of further assistance.

[guidalpi]

Hello,

The logs are generated from two different points on my code:

protected override void OnBarUpdate()
{

(...)

Print(string.Format("T{0};O{1};H{2};L{3};C{4};V{5} ", Time[0], Open[0], High[0], Low[0], Close[0], Volume[0]));

(...)

}

protected override void OnOrderUpdate(Order order, double limitPrice, double stopPrice, int quantity, int filled, double averageFillPrice, OrderState orderState, DateTime time, ErrorCode error, string nativeError)
{
Print(order.ToString());
}

OnBarUpdate() is responsible for the strategy logic and on each bar close it also prints to a logfile the Time, Open, High, Low, Close and Volume of that bar.

I´ve added OnOrderUpdate just to print to the same logfile the order lifecycle.

The time you´ve mentioned "2018-06-22 00:12:01" was the clock time on my computer when the strategy was doing the historical processing, just before going real time.

So, from what I´ve read on the help guide, the historical processing of orders should respect the bar ordering, and between the two bars in my example (06/14/2018 11:05:55 - 06/21/2018 22:16:58), there are more than 100 other closed bars (I forgot to mention this on the first post).

The bar type is a custom renko bar (ninZaRenko), but the orders are submitted to a 1 Tick secondary data series.

As my english is not so good, I´ve uploaded a chart image that tries to show you what´s going on.

Regards,

Guilherme.

[NinjaTrader_Jesse]

Hello guidalpi,

Thank you for the reply.

I wanted to check, do you also see this when using the standard Renko bars type?

If so, It would be helpful if I could test the script in the same situation and see the same result to better understand what happened here. Based on only the print information, I couldn't really say what may be happening in more detail. Can you tell me, is this something that could be formed into a small sample and uploaded to the forum for review? If not, we could work together through email if you needed to send the overall script.

I look forward to being of further assistance.

[guidalpi]

Hello Jesse,

Thanks for your reply.

It also happens when using renko bars type.

I´ve made a short version of my strategy (replacing a paid indicator I´m using on it), and it keeps showing that strange behaviour.

The strategy is being attached on an ES 09-18 chart, using 24 Renko bars type and it is loaded with the last 200 bars.

Hope it helps you finding what I´m doing wrong!

Regards,

Guilherme.

[NinjaTrader_Jesse]

Hello guidalpi,

Thank you for providing the file.

I reviewed what you have but I was unable to see the same type of occurrence you had with your test.

As it is now the sample is fairly difficult to follow because there are quite a few logical paths it can follow and other extra code being run. The prints you provided in your original inquiry also don't seem to exactly match any of the prints in this sample so I am unsure if I am looking at the specific portion of the script that I need to.

I would likely suggest at this point to further reduce this sample to a single entry that can demonstrate what you are seeing in a more simple way. Removing the other logic and debugging you have added will make the specific syntax required to see what you are more clear.

I look forward to being of further assistance.

[guidalpi]

Hello,

I´ve made a new test code, as simple as possible.

On my execution (24 renko, 200 bars, ES 09-18) I got the following:

T27/06/2018 12:26:43;O2738,5;H2738,5;L2732,5;C2732,5;V302009
Vendendo
orderId='NT-00000-3064' account='Sim101' name='Ninza3HamaSell' orderState=Submitted instrument='ES 09-18' orderAction=SellShort orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=0 averageFillPrice=0 onBehalfOf='' id=-1 time='2018-06-29 17:58:59' gtd='2099-12-01' statementDate='2018-06-30'

orderId='NT-00000-3064' account='Sim101' name='Ninza3HamaSell' orderState=Accepted instrument='ES 09-18' orderAction=SellShort orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=0 averageFillPrice=0 onBehalfOf='' id=-1 time='2018-06-29 17:58:59' gtd='2099-12-01' statementDate='2018-06-30'

orderId='NT-00000-3064' account='Sim101' name='Ninza3HamaSell' orderState=Working instrument='ES 09-18' orderAction=SellShort orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=0 averageFillPrice=0 onBehalfOf='' id=-1 time='2018-06-29 17:58:59' gtd='2099-12-01' statementDate='2018-06-30'

(...)

T29/06/2018 16:24:21;O2738;H2738;L2732;C2732;V429926

T29/06/2018 16:50:00;O2732;H2732;L2726;C2726;V114154

orderId='NT-00000-3064' account='Sim101' name='Ninza3HamaSell' orderState=Filled instrument='ES 09-18' orderAction=SellShort orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=10 averageFillPrice=2721.5 onBehalfOf='' id=-1 time='2018-06-29 17:58:59' gtd='2099-12-01' statementDate='2018-06-30'

As you can see above, at least for me, the order is not getting the correct historical bar time.

I´m sending my code and the complete log file for the execution mentioned above.

Regards,

Guilherme.

[guidalpi]

Hello,

Any hint on what can be happening with these orders, or how can I further debug the orders.

Regards.

[NinjaTrader_Jesse]

Hello,

Thank you for the reply.

I reviewed the file further but I have been unable to see this print happen on my end. From my testing I am getting prints similar to the following reported back:

T5/11/2018 1:08:44 AM;O2722.75;H2722.75;L2722.25;C2722.25;V727
Vendendo
5/11/2018 1:08:44 AM Strategy 'Ninza3HamaDebug/142708669': Entered internal SubmitOrderManaged() method at 5/11/2018 1:08:44 AM: BarsInProgress=1 Action=SellShort OrderType=Market Quantity=10 LimitPrice=0 StopPrice=0 SignalName='Ninza3HamaSell' FromEntrySignal=''
orderId='NT-00000-136' account='Sim101' name='Ninza3HamaSell' orderState=Submitted instrument='ES 09-18' orderAction=SellShort orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=0 averageFillPrice=0 onBehalfOf='' id=-1 time='2018-05-11 01:08:44' gtd='2099-12-01' statementDate='2018-07-10'
orderId='NT-00000-136' account='Sim101' name='Ninza3HamaSell' orderState=Accepted instrument='ES 09-18' orderAction=SellShort orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=0 averageFillPrice=0 onBehalfOf='' id=-1 time='2018-05-11 01:08:44' gtd='2099-12-01' statementDate='2018-07-10'
orderId='NT-00000-136' account='Sim101' name='Ninza3HamaSell' orderState=Working instrument='ES 09-18' orderAction=SellShort orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=0 averageFillPrice=0 onBehalfOf='' id=-1 time='2018-05-11 01:08:44' gtd='2099-12-01' statementDate='2018-07-10'
orderId='NT-00000-136' account='Sim101' name='Ninza3HamaSell' orderState=Filled instrument='ES 09-18' orderAction=SellShort orderType='Market' limitPrice=0 stopPrice=0 quantity=10 tif=Gtc oco='' filled=10 averageFillPrice=2722.25 onBehalfOf='' id=-1 time='2018-05-11 01:08:44' gtd='2099-12-01' statementDate='2018-07-10'
T5/11/2018 1:10:53 AM;O2722.75;H2723.25;L2722.75;C2723.25;V645

I did note that you are not checking if there is enough data, so this could potentially be applying to this situation. Generally, if you use multiple series, you will also need a check like the following:

if (CurrentBars[0] < 1 || CurrentBars[1] < 1)
{
	return;
}

Potentially if you are using a different time in the data than I am, you may see different results depending on if both series has been fully loaded or not. If you add the above check-in and retest, do you still see the prints being delayed?

I look forward to being of further assistance.

[guidalpi]

Hello Jesse,

With your last post I found out what was happening.

As I am adding a secondary 1 tick data series, I can´t load my chart with the last 200 bars, as there won´t be enough bars for processing. Loading the chart with the days option solves the issue, as well as adding the check you suggested in the last post.

I didn´t realized that for the secondary data series the strategy would load only 200 bars. I was expecting that it would load the same period (in days) of the primary data series.

Thank you so much for your time and help!