I spent Friday afternoon coding a small profiler, may it be useful in reducing CPU usage for those that run time intensive backtests, e.g. with ML.

I've attached a backtest containing the file Profiler.cs with example of how to use it by using one of the QC University examples.

At the end of the backtest, it prints a log like this:

2017-08-26 00:00:00 Stopwatch at 145540 ms and 1455408662 ticks
2017-08-26 00:00:00 OnData: 100.00 % (87.78 %)
2017-08-26 00:00:00   ObjectiveScore: 0.11 % (0.11 %)
2017-08-26 00:00:00   SetPositions: 12.11 % (12.10 %)
2017-08-26 00:00:00     ObjectiveScore: 0.01 % (0.01 %)

In this case, it means that functions that wered profiled called by OnData took quite quite little time compared to other calls made by OnData itself (87.78% of time spent out of profiled sub-calls - probably it's the logging taking time).

In one of my real complicated projects, it can be useful to find out what's taking time, for instance from this log I can find out that warming up symbols after they're added by universe selection is the culprit:

2017-07-01 00:00:00 Stopwatch at 188665 ms and 1886654482 ticks
2017-07-01 00:00:00 OnData: 99.54 % (4.04 %)
2017-07-01 00:00:00   CheckTradables: 73.35 % (1.72 %)
2017-07-01 00:00:00     WarmUpFromHistory: 71.63 % (56.57 %)
2017-07-01 00:00:00       CheckSampleResolutionQueue: 0.79 % (0.73 %)
2017-07-01 00:00:00         ResolveSample: 0.06 % (0.06 %)
2017-07-01 00:00:00       Update: 14.01 % (14.01 %)
2017-07-01 00:00:00       CalcRank: 0.27 % (0.27 %)
2017-07-01 00:00:00   CheckSampleResolutionQueue: 3.05 % (1.10 %)
2017-07-01 00:00:00     ResolveSample: 1.95 % (1.95 %)
2017-07-01 00:00:00   EnterPositions: 0.61 % (0.59 %)
2017-07-01 00:00:00     Enter: 0.02 % (0.02 %)
2017-07-01 00:00:00   Update: 18.25 % (18.25 %)
2017-07-01 00:00:00   CalcRank: 0.20 % (0.20 %)
2017-07-01 00:00:00   Exit: 0.04 % (0.04 %)
2017-07-01 00:00:00     OnOrderEvent: 0.00 % (0.00 %)
2017-07-01 00:00:00 DisableAtEndOfDay: 0.46 % (0.06 %)
2017-07-01 00:00:00   CheckSampleResolutionQueue: 0.39 % (0.00 %)
2017-07-01 00:00:00     ResolveSample: 0.39 % (0.39 %)
2017-07-01 00:00:00   OnOrderEvent: 0.00 % (0.00 %)
2017-07-01 00:00:00 OnOrderEvent: 0.00 % (0.00 %)

Again, this is nothing fancy, but simple enough to copy paste into QC cloud environment. If you're running locally in Lean, it's probably better to use a real profiler.

 

Author