Invalid order of bar timestamps, when printed.

[misova]

I have simplistic strategy:

• it has 2 dataseries: 6E 1min (BIP 0) and 6E 5min (BIP 1)
• it just outputs BIP + Bar-Timestamp.

It is so simple. I just expect:

• that bar timestamps will be printed in correct time order.

Result is very strange:

• the bar-timestamps are correct for first hundreds of prints but later
• later they become chaotic like in the example below = I mean they do not goes by time, but jump from one time to another. It does not make any sense to me.

Example:

BIP: 0 | 2016-06-23 12:36:00
[COLOR="Red"]BIP: 0 | 2016-06-22 13:52:00[/COLOR]
BIP: 0 | 2016-06-22 13:53:00
[COLOR="red"]BIP: 0 | 2016-06-23 12:37:00[/COLOR]
BIP: 0 | 2016-06-22 13:54:00
BIP: 0 | 2016-06-23 12:38:00
BIP: 0 | 2016-06-22 13:55:00
BIP: 0 | 2016-06-23 12:39:00
BIP: 0 | 2016-06-23 12:40:00

It is easily reproducible every time.
I have attached minimalistic reproducible example. - DOWNLOAD HERE

Here are the settings, I ran it with:


I use:

• latest NT8 v8.0.2.0
• on Windows 10
• CQG datafeed (free demo)

Added later:

• I can confirm, that I have all data = no data missing, that would cause the chaotic timestamp.I verified that, by outputting just and only M1 timeframe (skipping M5), and all data were printed correctly = in correct time order = no chaotic jumps of timestamps.
• So one insight is, that this happens only, if multiple timeframes are added to the strategy. When only single timeframe is used, it works fine.

Last finding (2016-12-23 10:38):

• I found, that real order of the OnBarUpdate events is correct. What fails, is printing into the NinjaScript Output window. I found this, because when I collected all messages in to the List, and then save them into a file when strategy finished, all bar-timestamps are outputted in correct order. No problem. [B]Download extended strategy (with file logging)/B]
• So final problem is: Output windows causes some mess and outputs logs incorrectly = in some random way = instead of the correct order, how the log messages were printed.. This is, what needs to be fixed.

[NinjaTrader_JessicaP]

Hello misova,


You are correct as to the current asynchronous operation of NinjaTrader. NinjaTrader 8 is a multi-threaded application, and messages from multiple threads are not guaranteed to be sent to the output window in chronological order at this time.

With this in mind I have submitted a feature request to the product management team for the following feature :

This user would like a synchronization layer added to the Print method which forces messages to display chronologically, similarly to Log's functionality

I will follow up with more information as soon as it's available. If the feature requests already exists, a vote will be added to it.


Please let us know if there are any other ways we can help.

[misova]

You know, this is critical issue, breaking whole idea of logging.

If we have random order of printed messages - they are not useful, because we cannot find related events.

Basic principle of logging is to see chronological order of events, that help us understand what happened inside. This is absolutely neccessary for logging of any software.

I hope you understand how critical issue is, and that it is not just about something what one user wants Any logging in Output Window is useless, because we cannot reconstruct anything from logs, as they are not in chronological, but chaotic / random order.

I hope, this will be fixed soon

[sledge]

Are those different instances of the strategy? obj_ct will definitely tell us.

I suspect this is in Strategy Analyzer?

I see no issue in Playback-Market Replay. Everything is sequential.

Object #2 BIP: 1 | 2/3/2014 12:35:00 PM
Object #2 BIP: 0 | 2/3/2014 12:36:00 PM
Object #2 BIP: 0 | 2/3/2014 12:37:00 PM
Object #2 BIP: 0 | 2/3/2014 12:38:00 PM
Object #2 BIP: 0 | 2/3/2014 12:39:00 PM
Object #2 BIP: 0 | 2/3/2014 12:40:00 PM
Object #2 BIP: 1 | 2/3/2014 12:40:00 PM

[*]So final problem is: Output windows causes some mess and outputs logs incorrectly = in some random way = instead of the correct order, how the log messages were printed.. This is, what needs to be fixed.[/LIST]

	public class StrangeOrderOfPrintedBarTimestamps : Strategy
	{

		static int obj_ct = 0;
		
		protected override void OnStateChange()
		{
			if (State == State.SetDefaults)
			{
                IsUnmanaged = true;
                Calculate = Calculate.OnBarClose;
				
            }
			else if (State == State.Configure)
			{
                AddDataSeries(BarsPeriodType.Minute, 5);    // BarsArray[1]
				obj_ct ++;
            }
		}

		protected override void OnBarUpdate()
		{
            string s = "Object #"+ obj_ct + " BIP: " + BarsInProgress + " | " + Times[BarsInProgress][0];
            Print(s);
        }
	}

[misova]

Hi sledge,

I think, it depends on the context and speed = how frequently are messages printed to the output log.

I am suspicious, that when it works, then these are just positive circumstances,
that do not exploit this problem, because of not sufficient speed of logging.
You have to go to the full potential of threading framework, to get chaotic order.

• The slower is the speed (of strategy and hardware), the more probable it is, that the order will be correct.
• The faster is the speed (of strategy and hardware), the more probable is we get to the synchronization / threading issues, which results in the chaotic order.

You tested using Market Replay, what is different, than classic backstest.
Try to use demo strategy, that is attached in previous post with classic backtest.
Than, you should get chaotic order, especially, if you have powerful speedy machine.

I can reproduce it everytime.

[NinjaTrader_JessicaP]

This feature is being reviewed by the product management team and has been assigned the following unique tracking ID

SFT-1825

Please let us know if there is any other way we can help.