Your interactive trading laboratory!
 • 
18 users online

Sequence of Calls to UserModelBase Model Executuon Functions During a Backtest

I wondered when and how the model execution functions of UserMofdelBase are called during a backtest.
To get a clear picture I wote the following C# Coded Model, which sports all model execution functions:

using System;
using System.IO;
using System.Text;
using Quantacula.Core;
using Quantacula.Backtest;
using System.Collections.Generic;

// show Sequence of Calls to UserModelBase Model Executuon Functions during a backtest
namespace Quantacula
{
	public class ShowSeq2 : UserModelBase
	{
		static int seq = 0;

		// Write log entries to C:\temp\qlog.txt
		void Log(string info, [System.Runtime.CompilerServices.CallerMemberName] string caller = "")
		{
			seq++;
			StringBuilder sb = new StringBuilder();
			sb.Append(caller);
			sb.Append('[');
			sb.Append(base.GetHashCode());
			sb.Append("] #");
			sb.Append(seq.ToString());
			sb.Append(": ");
			sb.Append(info);
			WriteToDebugLog(sb.ToString());
			using (StreamWriter sw = new StreamWriter(@"C:\temp\qlog.txt", true))
			{
				sw.WriteLine(sb.ToString());
			}
		}

		public override void BacktestBegin()
		{
			Log("");
		}

		public override void Initialize(BarHistory bars)
		{
			double curreq = this.Backtester.CurrentEquity;
			Log("bars.Symbol=" + bars.Symbol + ", Eq=" + curreq.ToString("C2"));
		}

		public override void PreExecute(DateTime dt, List<BarHistory> participants)
		{
			Log("dt=" + dt.ToString("yyyy-MM-dd"));
		}

		public override void Execute(BarHistory bars, int idx)
		{
			double curreq = this.Backtester.CurrentEquity;
			Log("bars.Symbol=" + bars.Symbol +
					    ", idx=" + idx.ToString() + ", dt=" + bars.DateTimes[idx].ToString("yyyy-MM-dd") +
 						", Eq=" + curreq.ToString("C2"));

			if(OpenPositions.Count > 0)
			{
				ClosePosition(OpenPositions[0], OrderType.Market, 0.0);
			}
			else
			{
				PlaceTrade(bars, TransactionType.Buy, OrderType.Market);
			}
		}

		public override void Cleanup(BarHistory bars)
		{
			Log("bars.Symbol=" + bars.Symbol);
		}

		public override void PostExecute(DateTime dt, List<BarHistory> participants)
		{
			double curreq = this.Backtester.CurrentEquity;
			Log("dt=" + dt.ToString("yyyy-MM-dd") + ", Eq=" + curreq.ToString("C2"));
		}

		public override void BacktestComplete()
		{
			Log("");
		}
	}
}

If you run this model on a test universe with three symbols (A, B, C) and for 5 trading days you get the following output in Debug Log:

--A--
BacktestBegin[51934113] #1: 
Initialize[51934113] #2: bars.Symbol=A, Eq=$100,000.00
PreExecute[51934113] #6: dt=2020-09-18
Execute[51934113] #7: bars.Symbol=A, idx=0, dt=2020-09-18, Eq=$100,000.00
PreExecute[51934113] #12: dt=2020-09-21
Execute[51934113] #13: bars.Symbol=A, idx=1, dt=2020-09-21, Eq=$99,916.64
PreExecute[51934113] #18: dt=2020-09-22
Execute[51934113] #19: bars.Symbol=A, idx=2, dt=2020-09-22, Eq=$99,925.17
PreExecute[51934113] #24: dt=2020-09-23
Execute[51934113] #25: bars.Symbol=A, idx=3, dt=2020-09-23, Eq=$99,345.33
PreExecute[51934113] #30: dt=2020-09-24
Execute[51934113] #31: bars.Symbol=A, idx=4, dt=2020-09-24, Eq=$99,336.66
Cleanup[51934113] #36: bars.Symbol=A
--B--
Initialize[36493504] #3: bars.Symbol=B, Eq=$100,000.00
Execute[36493504] #8: bars.Symbol=B, idx=0, dt=2020-09-18, Eq=$100,000.00
Execute[36493504] #14: bars.Symbol=B, idx=1, dt=2020-09-21, Eq=$99,916.64
Execute[36493504] #20: bars.Symbol=B, idx=2, dt=2020-09-22, Eq=$99,925.17
Execute[36493504] #26: bars.Symbol=B, idx=3, dt=2020-09-23, Eq=$99,345.33
Execute[36493504] #32: bars.Symbol=B, idx=4, dt=2020-09-24, Eq=$99,336.66
Cleanup[36493504] #37: bars.Symbol=B
--C--
Initialize[41881640] #4: bars.Symbol=C, Eq=$100,000.00
Execute[41881640] #9: bars.Symbol=C, idx=0, dt=2020-09-18, Eq=$100,000.00
Execute[41881640] #15: bars.Symbol=C, idx=1, dt=2020-09-21, Eq=$99,916.64
Execute[41881640] #21: bars.Symbol=C, idx=2, dt=2020-09-22, Eq=$99,925.17
Execute[41881640] #27: bars.Symbol=C, idx=3, dt=2020-09-23, Eq=$99,345.33
Execute[41881640] #33: bars.Symbol=C, idx=4, dt=2020-09-24, Eq=$99,336.66
Cleanup[41881640] #38: bars.Symbol=C
--D--
Initialize[1204833] #5: bars.Symbol=D, Eq=$100,000.00
Execute[1204833] #10: bars.Symbol=D, idx=0, dt=2020-09-18, Eq=$100,000.00
PostExecute[1204833] #11: dt=2020-09-18, Eq=$100,000.00
Execute[1204833] #16: bars.Symbol=D, idx=1, dt=2020-09-21, Eq=$99,916.64
PostExecute[1204833] #17: dt=2020-09-21, Eq=$99,916.64
Execute[1204833] #22: bars.Symbol=D, idx=2, dt=2020-09-22, Eq=$99,925.17
PostExecute[1204833] #23: dt=2020-09-22, Eq=$99,925.17
Execute[1204833] #28: bars.Symbol=D, idx=3, dt=2020-09-23, Eq=$99,345.33
PostExecute[1204833] #29: dt=2020-09-23, Eq=$99,345.33
Execute[1204833] #34: bars.Symbol=D, idx=4, dt=2020-09-24, Eq=$99,336.66
PostExecute[1204833] #35: dt=2020-09-24, Eq=$99,336.66
Cleanup[1204833] #39: bars.Symbol=D
BacktestComplete[1204833] #40: 

The sequence looks rather simple and roughly like expected.
Some things to note:

  • There is a new instance for each symbol
  • BacktestBegin() and PreExecute() are called in the instance of the first symbol
  • PostExecute() and BacktestComplete() are called in the instance of the last symbol
Attachment

Cancel

Responses

This means that all information which is used on a portfolio level e.g. used by BacktestBegin(), PreExecute() and BacktestComplete() should be declared static to work like expected.

On the other hand all information on a single symbol level e.g. used by Initialized() and Cleanup() should not be static in order to work as expected.

Furthermore inside Initialize() you should not acess data set by PreExecute().

and inside Cleanup() you should not access data set in PostExecute()

This means that all information which is used on a portfolio level e.g. used by <tt>BacktestBegin(), PreExecute()</tt> and <tt>BacktestComplete()</tt> should be declared <tt>static</tt> to work like expected. On the other hand all information on a single symbol level e.g. used by <tt>Initialized()</tt> and <tt>Cleanup()</tt> should **not** be <tt>static</tt> in order to work as expected. Furthermore inside <tt>Initialize()</tt> you should not acess data set by <tt>PreExecute()</tt>. and inside <tt>Cleanup()</tt> you should not access data set in </tt>PostExecute()</tt>

If you take a closer look at the Debug Log Output above you'll notice some strange things:

  1. the equity values are correct!
  2. the sequence numbers printed as #1, #2, #3 and so forth look rather convoluted.

The equity should be wrong given the call sequence printed in Debug Log. The call sequence suggests, that the first symbol is traded through its complete history, then the second symbol.

But after the call for the first trading day of the first symbol equity is correct and contains the trading result of all symbols! How can this be? TimeWarp?

If you take a closer look at the Debug Log Output above you'll notice some strange things: 1. the equity values are correct! 2. the sequence numbers printed as #1, #2, #3 and so forth look rather convoluted. The equity should be wrong given the call sequence printed in Debug Log. The call sequence suggests, that the first symbol is traded through its complete history, then the second symbol. But after the call for the first trading day of the first symbol equity is correct and contains the trading result of all symbols! How can this be? TimeWarp?

To find an answer to this questions I wrote a log file with the same information as shown in Debug Log:

BacktestBegin[53075407] #1: 
Initialize[53075407] #2: bars.Symbol=B, Eq=$100,000.00
Initialize[24832102] #3: bars.Symbol=A, Eq=$100,000.00
Initialize[54564110] #4: bars.Symbol=D, Eq=$100,000.00
Initialize[58837901] #5: bars.Symbol=C, Eq=$100,000.00
PreExecute[53075407] #6: dt=2020-09-16
Execute[53075407] #7: bars.Symbol=B, idx=0, dt=2020-09-16, Eq=$100,000.00
Execute[24832102] #8: bars.Symbol=A, idx=0, dt=2020-09-16, Eq=$100,000.00
Execute[54564110] #9: bars.Symbol=D, idx=0, dt=2020-09-16, Eq=$100,000.00
Execute[58837901] #10: bars.Symbol=C, idx=0, dt=2020-09-16, Eq=$100,000.00
PostExecute[58837901] #11: dt=2020-09-16, Eq=$100,000.00
PreExecute[53075407] #12: dt=2020-09-17
Execute[53075407] #13: bars.Symbol=B, idx=1, dt=2020-09-17, Eq=$100,317.71
Execute[24832102] #14: bars.Symbol=A, idx=1, dt=2020-09-17, Eq=$100,317.71
Execute[54564110] #15: bars.Symbol=D, idx=1, dt=2020-09-17, Eq=$100,317.71
Execute[58837901] #16: bars.Symbol=C, idx=1, dt=2020-09-17, Eq=$100,317.71
PostExecute[58837901] #17: dt=2020-09-17, Eq=$100,317.71
PreExecute[53075407] #18: dt=2020-09-18
Execute[53075407] #19: bars.Symbol=B, idx=2, dt=2020-09-18, Eq=$100,344.93
Execute[24832102] #20: bars.Symbol=A, idx=2, dt=2020-09-18, Eq=$100,344.93
Execute[54564110] #21: bars.Symbol=D, idx=2, dt=2020-09-18, Eq=$100,344.93
Execute[58837901] #22: bars.Symbol=C, idx=2, dt=2020-09-18, Eq=$100,344.93
PostExecute[58837901] #23: dt=2020-09-18, Eq=$100,344.93
PreExecute[53075407] #24: dt=2020-09-21
Execute[53075407] #25: bars.Symbol=B, idx=3, dt=2020-09-21, Eq=$100,260.91
Execute[24832102] #26: bars.Symbol=A, idx=3, dt=2020-09-21, Eq=$100,260.91
Execute[54564110] #27: bars.Symbol=D, idx=3, dt=2020-09-21, Eq=$100,260.91
Execute[58837901] #28: bars.Symbol=C, idx=3, dt=2020-09-21, Eq=$100,260.91
PostExecute[58837901] #29: dt=2020-09-21, Eq=$100,260.91
PreExecute[53075407] #30: dt=2020-09-22
Execute[53075407] #31: bars.Symbol=B, idx=4, dt=2020-09-22, Eq=$100,269.57
Execute[24832102] #32: bars.Symbol=A, idx=4, dt=2020-09-22, Eq=$100,269.57
Execute[54564110] #33: bars.Symbol=D, idx=4, dt=2020-09-22, Eq=$100,269.57
Execute[58837901] #34: bars.Symbol=C, idx=4, dt=2020-09-22, Eq=$100,269.57
PostExecute[58837901] #35: dt=2020-09-22, Eq=$100,269.57
PreExecute[53075407] #36: dt=2020-09-23
Execute[53075407] #37: bars.Symbol=B, idx=5, dt=2020-09-23, Eq=$99,685.21
Execute[24832102] #38: bars.Symbol=A, idx=5, dt=2020-09-23, Eq=$99,685.21
Execute[54564110] #39: bars.Symbol=D, idx=5, dt=2020-09-23, Eq=$99,685.21
Execute[58837901] #40: bars.Symbol=C, idx=5, dt=2020-09-23, Eq=$99,685.21
PostExecute[58837901] #41: dt=2020-09-23, Eq=$99,685.21
PreExecute[53075407] #42: dt=2020-09-24
Execute[53075407] #43: bars.Symbol=B, idx=6, dt=2020-09-24, Eq=$99,676.55
Execute[24832102] #44: bars.Symbol=A, idx=6, dt=2020-09-24, Eq=$99,676.55
Execute[54564110] #45: bars.Symbol=D, idx=6, dt=2020-09-24, Eq=$99,676.55
Execute[58837901] #46: bars.Symbol=C, idx=6, dt=2020-09-24, Eq=$99,676.55
PostExecute[58837901] #47: dt=2020-09-24, Eq=$99,676.55
Cleanup[53075407] #48: bars.Symbol=B
Cleanup[24832102] #49: bars.Symbol=A
Cleanup[54564110] #50: bars.Symbol=D
Cleanup[58837901] #51: bars.Symbol=C
BacktestComplete[58837901] #52: 

This log shows the true calling sequence.
The sequence numbers appear in the correct order as expected.

And it becomes clear, that the calling sequence is quite different from what is shown in Debug Log.

The overall effect is a correct equity curve and otherwise time dependent data.

Well done! But why is this delicate arrangement "hidden" in Debug Log?

To find an answer to this questions I wrote a log file with the same information as shown in Debug Log: [CODE] BacktestBegin[53075407] #1: Initialize[53075407] #2: bars.Symbol=B, Eq=$100,000.00 Initialize[24832102] #3: bars.Symbol=A, Eq=$100,000.00 Initialize[54564110] #4: bars.Symbol=D, Eq=$100,000.00 Initialize[58837901] #5: bars.Symbol=C, Eq=$100,000.00 PreExecute[53075407] #6: dt=2020-09-16 Execute[53075407] #7: bars.Symbol=B, idx=0, dt=2020-09-16, Eq=$100,000.00 Execute[24832102] #8: bars.Symbol=A, idx=0, dt=2020-09-16, Eq=$100,000.00 Execute[54564110] #9: bars.Symbol=D, idx=0, dt=2020-09-16, Eq=$100,000.00 Execute[58837901] #10: bars.Symbol=C, idx=0, dt=2020-09-16, Eq=$100,000.00 PostExecute[58837901] #11: dt=2020-09-16, Eq=$100,000.00 PreExecute[53075407] #12: dt=2020-09-17 Execute[53075407] #13: bars.Symbol=B, idx=1, dt=2020-09-17, Eq=$100,317.71 Execute[24832102] #14: bars.Symbol=A, idx=1, dt=2020-09-17, Eq=$100,317.71 Execute[54564110] #15: bars.Symbol=D, idx=1, dt=2020-09-17, Eq=$100,317.71 Execute[58837901] #16: bars.Symbol=C, idx=1, dt=2020-09-17, Eq=$100,317.71 PostExecute[58837901] #17: dt=2020-09-17, Eq=$100,317.71 PreExecute[53075407] #18: dt=2020-09-18 Execute[53075407] #19: bars.Symbol=B, idx=2, dt=2020-09-18, Eq=$100,344.93 Execute[24832102] #20: bars.Symbol=A, idx=2, dt=2020-09-18, Eq=$100,344.93 Execute[54564110] #21: bars.Symbol=D, idx=2, dt=2020-09-18, Eq=$100,344.93 Execute[58837901] #22: bars.Symbol=C, idx=2, dt=2020-09-18, Eq=$100,344.93 PostExecute[58837901] #23: dt=2020-09-18, Eq=$100,344.93 PreExecute[53075407] #24: dt=2020-09-21 Execute[53075407] #25: bars.Symbol=B, idx=3, dt=2020-09-21, Eq=$100,260.91 Execute[24832102] #26: bars.Symbol=A, idx=3, dt=2020-09-21, Eq=$100,260.91 Execute[54564110] #27: bars.Symbol=D, idx=3, dt=2020-09-21, Eq=$100,260.91 Execute[58837901] #28: bars.Symbol=C, idx=3, dt=2020-09-21, Eq=$100,260.91 PostExecute[58837901] #29: dt=2020-09-21, Eq=$100,260.91 PreExecute[53075407] #30: dt=2020-09-22 Execute[53075407] #31: bars.Symbol=B, idx=4, dt=2020-09-22, Eq=$100,269.57 Execute[24832102] #32: bars.Symbol=A, idx=4, dt=2020-09-22, Eq=$100,269.57 Execute[54564110] #33: bars.Symbol=D, idx=4, dt=2020-09-22, Eq=$100,269.57 Execute[58837901] #34: bars.Symbol=C, idx=4, dt=2020-09-22, Eq=$100,269.57 PostExecute[58837901] #35: dt=2020-09-22, Eq=$100,269.57 PreExecute[53075407] #36: dt=2020-09-23 Execute[53075407] #37: bars.Symbol=B, idx=5, dt=2020-09-23, Eq=$99,685.21 Execute[24832102] #38: bars.Symbol=A, idx=5, dt=2020-09-23, Eq=$99,685.21 Execute[54564110] #39: bars.Symbol=D, idx=5, dt=2020-09-23, Eq=$99,685.21 Execute[58837901] #40: bars.Symbol=C, idx=5, dt=2020-09-23, Eq=$99,685.21 PostExecute[58837901] #41: dt=2020-09-23, Eq=$99,685.21 PreExecute[53075407] #42: dt=2020-09-24 Execute[53075407] #43: bars.Symbol=B, idx=6, dt=2020-09-24, Eq=$99,676.55 Execute[24832102] #44: bars.Symbol=A, idx=6, dt=2020-09-24, Eq=$99,676.55 Execute[54564110] #45: bars.Symbol=D, idx=6, dt=2020-09-24, Eq=$99,676.55 Execute[58837901] #46: bars.Symbol=C, idx=6, dt=2020-09-24, Eq=$99,676.55 PostExecute[58837901] #47: dt=2020-09-24, Eq=$99,676.55 Cleanup[53075407] #48: bars.Symbol=B Cleanup[24832102] #49: bars.Symbol=A Cleanup[54564110] #50: bars.Symbol=D Cleanup[58837901] #51: bars.Symbol=C BacktestComplete[58837901] #52: [/CODE] This log shows the **true calling sequence.** The sequence numbers appear in the correct order as expected. And it becomes clear, that the calling sequence is quite different from what is shown in Debug Log. The overall effect is a correct equity curve and otherwise time dependent data. Well done! But why is this delicate arrangement "hidden" in Debug Log?

The debug log info is compiled on a symbol by symbol basis as the backtest proceeds, and is then merged together for output after the fact. We did this to be able to precede each little debug output snippet with the symbol that generated it. We can probably improve this mechanism with some thought!

The debug log info is compiled on a symbol by symbol basis as the backtest proceeds, and is then merged together for output after the fact. We did this to be able to precede each little debug output snippet with the symbol that generated it. We can probably improve this mechanism with some thought!
Forum Tips

Please sign in if you want to participate in our forum.

Our forum uses Markdown syntax to format posts.

To embed code snippets, enclose them in [CODE][/CODE] tags.