Backtesting Timestamp/Order Fill Bug

[DanielB]

This took me several hours to isolate.

First, look at the picture from 10:00 am to 11:30 am. According to this strategy, whenever entry0 is closed, entry1 is closed too. This functions perfectly on NT 6.5. Here, however, the ExitLong for entry1 doesn't go through on this backtest (after ExitLong is sent, entry1 is set to null) and everything after this point is corrupt because then when entry1's are attempted to be placed, they get the error that there is already an order with that name, which is true - it's still open.

Entry0 Sent:
	9/11/2009 10:00:00 AM Entered internal PlaceOrder() method at 9/11/2009 10:00:00 AM: Action=Buy OrderType=Market Quantity=0.1M LimitPrice=0 StopPrice=0 SignalName='Entry0' FromEntrySignal=''
Entry0 Filled:
	Execution='NT-00130' Instrument='$EURUSD' Account='Backtest' Name='Entry0' Exchange=Default Price=1.46082 Quantity=0.1M Market position=Long Commission=4.13 Order='NT-00140' Time='9/11/2009 10:30:00 AM' Multiplier=1E-05
		Order='NT-00140/Backtest' Name='Entry0' State=Filled Instrument='$EURUSD' Action=Buy Limit price=0 Stop price=0 Quantity=0.1M Strategy='BrezJeopardy003' Type=Market Tif=Gtc Oco='' Filled=100000 Fill price=1.46082 Token='2c01f12d1ce74244930ff6e07d3d3e55' Gtd='12/1/2099 12:00:00 AM'
Target0 Sent:
	9/11/2009 10:00:00 AM Entered internal PlaceOrder() method at 9/11/2009 10:00:00 AM: Action=Sell OrderType=Limit Quantity=0.1M LimitPrice=1.4618'2 StopPrice=0 SignalName='Entry0 - Target' FromEntrySignal='Entry0'

Entry1 Sent:
	9/11/2009 10:30:00 AM Entered internal PlaceOrder() method at 9/11/2009 10:30:00 AM: Action=Buy OrderType=Market Quantity=0.1M LimitPrice=0 StopPrice=0 SignalName='Entry1' FromEntrySignal=''
Entry1 Filled:
Time here is 11 AM!
	Execution='NT-00131' Instrument='$EURUSD' Account='Backtest' Name='Entry1' Exchange=Default Price=1.45882 Quantity=0.1M Market position=Long Commission=4.13 Order='NT-00142' Time='9/11/2009 11:00:00 AM' Multiplier=1E-05
		Order='NT-00142/Backtest' Name='Entry1' State=Filled Instrument='$EURUSD' Action=Buy Limit price=0 Stop price=0 Quantity=0.1M Strategy='BrezJeopardy003' Type=Market Tif=Gtc Oco='' Filled=100000 Fill price=1.45882 Token='17a7ab6f1ed1418db7c3b534ec3217a2' Gtd='12/1/2099 12:00:00 AM'

Target0 Filled:
	Execution='NT-00132' Instrument='$EURUSD' Account='Backtest' Name='Entry0 - Target' Exchange=Default Price=1.46182 Quantity=0.1M Market position=Short Commission=4.13 Order='NT-00141' Time='9/11/2009 11:00:00 AM' Multiplier=1E-05
		Order='NT-00141/Backtest' Name='Entry0 - Target' State=Filled Instrument='$EURUSD' Action=Sell Limit price=1.46182 Stop price=0 Quantity=0.1M Strategy='BrezJeopardy003' Type=Limit Tif=Gtc Oco='' Filled=100000 Fill price=1.46182 Token='ecc748a6a1f54b6a9deaeb8643a9336b' Gtd='12/1/2099 12:00:00 AM'

Entry1 Sent to Close: at 10:30...
	9/11/2009 10:30:00 AM Entered internal PlaceOrder() method at 9/11/2009 10:30:00 AM: Action=Sell OrderType=Market Quantity=0.1M LimitPrice=0 StopPrice=0 SignalName='Target Hit1' FromEntrySignal='Entry1'

(entry1 IOrder was set to null after an ExitOrder for it was sent, but the order never was filled. Later handling is all messed up. Notice the time stamp for it being filled was later than what was sent for it to be closed.)

I think the problem here has to do with the internal timing logic. Its cancel order was sent on the 11 am bar when it was filled, from getting an entry signal at 10:30. Again, on NT 6.5 this did not malfunction. Changing the bar sizes to 10 minutes spread things out and also avoided the problem, but I'd like the error fixed so I can use whichever bar time is best.

Also, I tried running this strategy with multicoreenabled to false and setting the IOrders to volatile. This didn't do anything to change the results.

- Daniel

[NinjaTrader_JoshP]

DanielB,

You said you set entry1 to null right as you place ExitLong() for it. Are you literally going in your code something like this?

ExitLong();
entry1 = null;

If you are doing it in this fashion I would strongly suggest otherwise. I would suggest only resetting to null when the order you place to close the position gets filled. Only when the trade is completely finished should it be reset to null. Please also add Print() statements into OnOrderUpdate() to specifically track the progress of that ExitLong() and see what it is doing through the process.

[DanielB]

You are essentially correct in your code example. Normally I do wait for an exit to be filled before the entry IOrder is set to null, but in this strategy, entry IOrders are generated dynamically and so I've have to scan compare dozens of possible IOrders to find their match that comes through OnExecution before setting them to null. This would only delay them being set to null. However, here the Order simply doesn't go through and never shows up in the log posted below. Even if I waited before setting the created entry IOrder to null, the strategy would be broken because the exit is never filled.

It's a lot of code, but just search Entry1 and notice it never gets its "PlaceOrder()" exit.

9/14/2009 10:30:00 AM Entered internal PlaceOrder() method at 9/14/2009 10:30:00 AM: Action=Buy OrderType=Limit Quantity=0.1M LimitPrice=1.4609 StopPrice=0 SignalName='Entry1' FromEntrySignal=''
OnOrderUpdate, IOrder: Order='NT-00312/Backtest' Name='Entry1' State=PendingSubmit Instrument='$EURUSD' Action=Buy Limit price=1.4609 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=0 Fill price=0 Token='744cf3fdad6349ed9f1718f52d528f4a' Gtd='12/1/2099 12:00:00 AM'
OnOrderUpdate, IOrder: Order='NT-00312/Backtest' Name='Entry1' State=Accepted Instrument='$EURUSD' Action=Buy Limit price=1.4609 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=0 Fill price=0 Token='744cf3fdad6349ed9f1718f52d528f4a' Gtd='12/1/2099 12:00:00 AM'
OnOrderUpdate, IOrder: Order='NT-00312/Backtest' Name='Entry1' State=Working Instrument='$EURUSD' Action=Buy Limit price=1.4609 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=0 Fill price=0 Token='744cf3fdad6349ed9f1718f52d528f4a' Gtd='12/1/2099 12:00:00 AM'
OnOrderUpdate, IOrder: Order='NT-00311/Backtest' Name='Entry0 - Target' State=Filled Instrument='$EURUSD' Action=Sell Limit price=1.46342 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=100000 Fill price=1.46342 Token='ba0ea13bda2c4e618a5ea1b025fcd91e' Gtd='12/1/2099 12:00:00 AM'
OnExecution, IExecution: Execution='NT-00281' Instrument='$EURUSD' Account='Backtest' Name='Entry0 - Target' Exchange=Default Price=1.46342 Quantity=0.1M Market position=Short Commission=4.13 Order='NT-00311' Time='9/14/2009 11:00:00 AM' Multiplier=1E-05
OnExecution, IOrder: Order='NT-00311/Backtest' Name='Entry0 - Target' State=Filled Instrument='$EURUSD' Action=Sell Limit price=1.46342 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=100000 Fill price=1.46342 Token='ba0ea13bda2c4e618a5ea1b025fcd91e' Gtd='12/1/2099 12:00:00 AM'
OnOrderUpdate, IOrder: Order='NT-00312/Backtest' Name='Entry1' State=Filled Instrument='$EURUSD' Action=Buy Limit price=1.4609 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=100000 Fill price=1.4609 Token='744cf3fdad6349ed9f1718f52d528f4a' Gtd='12/1/2099 12:00:00 AM'
OnExecution, IExecution: Execution='NT-00282' Instrument='$EURUSD' Account='Backtest' Name='Entry1' Exchange=Default Price=1.4609 Quantity=0.1M Market position=Long Commission=4.13 Order='NT-00312' Time='9/14/2009 11:00:00 AM' Multiplier=1E-05
OnExecution, IOrder: Order='NT-00312/Backtest' Name='Entry1' State=Filled Instrument='$EURUSD' Action=Buy Limit price=1.4609 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=100000 Fill price=1.4609 Token='744cf3fdad6349ed9f1718f52d528f4a' Gtd='12/1/2099 12:00:00 AM'
9/14/2009 11:00:00 AM Entered internal PlaceOrder() method at 9/14/2009 11:00:00 AM: Action=Buy OrderType=Market Quantity=0.1M LimitPrice=0 StopPrice=0 SignalName='Entry0' FromEntrySignal=''
OnOrderUpdate, IOrder: Order='NT-00313/Backtest' Name='Entry0' State=PendingSubmit Instrument='$EURUSD' Action=Buy Limit price=0 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Market Tif=Gtc Oco='' Filled=0 Fill price=0 Token='50b8f9105afa4ff1aa671412814f77cd' Gtd='12/1/2099 12:00:00 AM'
OnOrderUpdate, IOrder: Order='NT-00313/Backtest' Name='Entry0' State=Accepted Instrument='$EURUSD' Action=Buy Limit price=0 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Market Tif=Gtc Oco='' Filled=0 Fill price=0 Token='50b8f9105afa4ff1aa671412814f77cd' Gtd='12/1/2099 12:00:00 AM'
OnOrderUpdate, IOrder: Order='NT-00313/Backtest' Name='Entry0' State=Working Instrument='$EURUSD' Action=Buy Limit price=0 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Market Tif=Gtc Oco='' Filled=0 Fill price=0 Token='50b8f9105afa4ff1aa671412814f77cd' Gtd='12/1/2099 12:00:00 AM'
OnOrderUpdate, IOrder: Order='NT-00313/Backtest' Name='Entry0' State=Filled Instrument='$EURUSD' Action=Buy Limit price=0 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Market Tif=Gtc Oco='' Filled=100000 Fill price=1.46302 Token='50b8f9105afa4ff1aa671412814f77cd' Gtd='12/1/2099 12:00:00 AM'
OnExecution, IExecution: Execution='NT-00283' Instrument='$EURUSD' Account='Backtest' Name='Entry0' Exchange=Default Price=1.46302 Quantity=0.1M Market position=Long Commission=4.13 Order='NT-00313' Time='9/14/2009 11:30:00 AM' Multiplier=1E-05
OnExecution, IOrder: Order='NT-00313/Backtest' Name='Entry0' State=Filled Instrument='$EURUSD' Action=Buy Limit price=0 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Market Tif=Gtc Oco='' Filled=100000 Fill price=1.46302 Token='50b8f9105afa4ff1aa671412814f77cd' Gtd='12/1/2099 12:00:00 AM'
9/14/2009 11:00:00 AM Entered internal PlaceOrder() method at 9/14/2009 11:00:00 AM: Action=Sell OrderType=Limit Quantity=0.1M LimitPrice=1.4640'2 StopPrice=0 SignalName='Entry0 - Target' FromEntrySignal='Entry0'
OnOrderUpdate, IOrder: Order='NT-00314/Backtest' Name='Entry0 - Target' State=PendingSubmit Instrument='$EURUSD' Action=Sell Limit price=1.46402 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=0 Fill price=0 Token='ddbffd41218d4c29b2fb93762a856642' Gtd='12/1/2099 12:00:00 AM'
OnOrderUpdate, IOrder: Order='NT-00314/Backtest' Name='Entry0 - Target' State=Accepted Instrument='$EURUSD' Action=Sell Limit price=1.46402 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=0 Fill price=0 Token='ddbffd41218d4c29b2fb93762a856642' Gtd='12/1/2099 12:00:00 AM'
OnOrderUpdate, IOrder: Order='NT-00314/Backtest' Name='Entry0 - Target' State=Working Instrument='$EURUSD' Action=Sell Limit price=1.46402 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=0 Fill price=0 Token='ddbffd41218d4c29b2fb93762a856642' Gtd='12/1/2099 12:00:00 AM'
OnOrderUpdate, IOrder: Order='NT-00314/Backtest' Name='Entry0 - Target' State=Filled Instrument='$EURUSD' Action=Sell Limit price=1.46402 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=100000 Fill price=1.46402 Token='ddbffd41218d4c29b2fb93762a856642' Gtd='12/1/2099 12:00:00 AM'
OnExecution, IExecution: Execution='NT-00284' Instrument='$EURUSD' Account='Backtest' Name='Entry0 - Target' Exchange=Default Price=1.46402 Quantity=0.1M Market position=Short Commission=4.13 Order='NT-00314' Time='9/14/2009 11:30:00 AM' Multiplier=1E-05
OnExecution, IOrder: Order='NT-00314/Backtest' Name='Entry0 - Target' State=Filled Instrument='$EURUSD' Action=Sell Limit price=1.46402 Stop price=0 Quantity=0.1M Strategy='BrezWolfPack001' Type=Limit Tif=Gtc Oco='' Filled=100000 Fill price=1.46402 Token='ddbffd41218d4c29b2fb93762a856642' Gtd='12/1/2099 12:00:00 AM'

Then later, when another Entry1 is generated to send:
9/14/2009 1:30:00 PM Entered internal PlaceOrder() method at 9/14/2009 1:30:00 PM: Action=Buy OrderType=Limit Quantity=0.1M LimitPrice=1.4614 StopPrice=0 SignalName='Entry1' FromEntrySignal=''
9/14/2009 1:30:00 PM Ignored PlaceOrder() method at 9/14/2009 1:30:00 PM: Action=Buy OrderType=Limit Quantity=0.1M LimitPrice=1.4614 StopPrice=0 SignalName='Entry1' FromEntrySignal='' Reason='Exceeded entry signals limit based on EntryHandling and EntriesPerDirection properties'

[NinjaTrader_JoshP]

DanielB,

If you never get a PlaceOrder() it means your code never got to the section where it would submit an ExitLong(). Please add a Print() so you can actually see exactly when the line of code should have triggered the exit trade.

Also, your last issue is because of this "Exceeded entry signals limit based on EntryHandling and EntriesPerDirection properties". It means you have too many entries in the same direction. Default setting is 1 trade allowed in a single direction at a time.

[DanielB]

After trying what you said, you're right in that the ExitLong was never successfully submitted. After looking into it more, I have found that all orders are working except the orders placed that were called from within OnExecution(). The ExitLong for Entry1 was triggered from within OnExecution when Entry0 target was hit. The documentation for OnExecution does mention something about "the OnExecution() method to trigger actions such as the submission of a stop loss order" so I assumed that all orders would work, and in NT 6.5 it seemed to work fine, but this seems to be the root problem. In fact, further testing now has shown me that stop orders do work when placed on execution, but not exit/entry orders. Here I have written a sample strategy that demonstrates this issue, please take a look at it if you need demonstration.

As for the "Exceeded entry signals limit" issue - that's only a symptom.

[NinjaTrader_JoshP]

DanielB,

You need to use the signature method with liveUntilCancelled when submitting limit orders from OnExecution(). When you don't the limit order will automatically expire on the next OnBarUpdate() as it is not kept alive which is what you are seeing with your code. When that limit order is cancelled there is no chance of your ExitLong() in OnExecution() to ever trigger because targetOrder never triggers.

http://www.ninjatrader.com/support/helpGuides/nt7/exitlonglimit.htm

[DanielB]

Josh,

I understand you and I tried that. If what you say is correct, then this code:

        protected override void OnExecution(IExecution execution)
        {
            if (entryOrder1 != null && entryOrder1 == execution.Order)
            {
                targetOrder1 = ExitLongLimit(Close[0] + 0.0010, "Entry1");
                entryOrder2 = EnterLong("Entry2");
            }
         }

... would work. Try the sample strategy code I put on my last post. The target order is generated but the Entry2 never goes through. Wouldn't that be a NT error?

[NinjaTrader_JoshP]

Daniel,

You have two issues.

1. As stated earlier, you already exceeded your entry signals per direction so you can't enter again for your entryOrder2. If you want to be in long two times you need to increase your EntriesPerDirection in the UI properties.

2. For your market order exit after targetOrder1 gets filled to close entryOrder2, that won't work because targetOrder1 will never get filled by your code unless it gets filled within one bar of placement. Your order will expire and auto cancel otherwise. When submitting limit orders from OnExecution() you need to use the liveUntilCancelled signature.

Please see this reference sample: http://www.ninjatrader.com/support/f...ead.php?t=7499

[DanielB]

1. I set Order Handling to Unique Entries.

2. To demonstrate that certain order types aren't working when called with OnExecution that's why I did this sample code:

        protected override void OnExecution(IExecution execution)
        {
            if (entryOrder1 != null && entryOrder1 == execution.Order)
            {
                targetOrder1 = ExitLongLimit(0, true, DefaultQuantity, Close[0] + 0.0010, "Target1", "Entry1");
                entryOrder2 = EnterLong("Entry2");
				Print("Entry 2 Sent");
            }

            if (targetOrder1 != null && targetOrder1 == execution.Order)
            {
                entryOrder1 = null;
                entryOrder2 = ExitLong("Entry2");
            }

        }

With this code and orders set to Unique Entries, Entry2 never gets SENT through or shows up in the traces. Please take a moment to verify this bug.
I'm not even talking about exits for Entry2, even its entry.

[NinjaTrader_Bertrand]

Works for me, try ensure to have UniqueEntries on in the UI as you start up and then enter if (Historical) return; at your OnBarUpdate() start - otherwise the trade from the last leg up long is still open you could not see an entry as you've got no stop to take you out...try the above on for example a 10 sec ES chart, if the condition is true it places the 2 entries you've coded up.

[DanielB]

You're right, I tried that code again and the sample worked with Unique Entries mode, I'd forgotten to set it. Normally I have it already set that way from Initialize().

Going back to the original strategy, I determined that the reason it wasn't sending an exit order was because it checks that the IOrder.Filled > 0 and in the log, at that time the Entry filled is at 0. Then the strategy runs CancelOrder on the Entry and sets the IOrder to null. When I tried the strategy with the Filled > 0 check removed, the trace order showed the error that, "this was an exit order but no position exists to exit." Somehow, this event is getting processed at a time during the backtest on the same bar or something. With a smaller bar size, I don't get these errors.

For now, I coded a work-around.

[NinjaTrader_JoshP]

DanielB,

This is why you we highly recommend you not reset your IOrders till the trade is actually complete. You could be mismatching various states and doing operations when they simply would not be available.

The message you are seeing now means you have no position to exit for the exit order so it will be dropped out.

[DanielB]

Thank you for bearing it out with me.

I changed the routine to track the exit orders and when they're filled, the entry is then set to null (also nulling the exit tracking).