{"id":1134,"date":"2007-09-23T15:44:44","date_gmt":"2007-09-23T15:44:44","guid":{"rendered":"http:\/\/www.amibroker.org\/userkb\/2007\/09\/23\/measuring-afl-execution-times\/"},"modified":"2007-10-07T10:40:55","modified_gmt":"2007-10-07T10:40:55","slug":"measuring-afl-execution-times","status":"publish","type":"post","link":"http:\/\/www.amibroker.org\/editable_userkb\/2007\/09\/23\/measuring-afl-execution-times\/","title":{"rendered":"Measuring AFL Execution Times (v3)"},"content":{"rendered":"

When your code increases in complexity, it will start to execute more slowly, and you will eventually reach a point where you will want to optimize your code for speed of execution. Even if you are willing to buy a faster computer, it will rarely give you a greater speed advantage than optimizing your code.<\/p>\n

Important note: The AmiBroker 5.01.1 beta released on 5\/10\/2007 offers a new profiling function that enables you to get accurate performance timing for all AmiBroker and custom functions called. It is available from the AFL Editor: Tools -> Code Check and Profile menu. To use this new tool effectively you should convert your code modules to function calls as much as possible. Try it!<\/strong><\/p>\n

The first requirement for analyzing your AFL execution speed is the ability to measure the execution times. This is best done using the GetPerformanceCounter(), which gives microsecond resolution. You can display the execution time in the chart Title, or log them to DebugView. To get an appreciation of how fast AFL executes you may want to time a few of your most frequently used AFL statements. As Tomasz pointed out in his comment to an earlier version of this post, this can be done using a simple loop:<\/p>\n

\r<\/span><<\/span>p<\/span>><\/span>On my 2GHz laptop<\/span>, <\/span>the Param<\/span>() <\/span>takes about 4 microseconds to execute<\/span>. <\/span>The <\/span>"Statement under test" <\/span>can be any AFL statement <\/span>or <\/span>section of code you want to analyze<\/span>. <\/span>This simple code will give you a fairly accurate idea of the true execution time<\/span>. <\/span>Please <\/span>do <\/span>not forget that all<\/span>&<\/span>nbsp<\/span>;<\/span>programs executing under Microsoft Operating Systems<\/span>&<\/span>nbsp<\/span>;<\/span>are subject to interruptions<\/span>. <\/span>This means that your readings may fluctuate <\/span>and <\/span>will generally be greater than their absolute true values<\/span>. <\/span>Your normal program executions are<\/span>&<\/span>nbsp<\/span>;<\/span>also subject to these interruptions <\/span>and, if <\/span>you perform<\/span>&<\/span>nbsp<\/span>;<\/span>precision timing tasks<\/span>, <\/span>your should consider their effect<\/span>.<\/<\/span>p<\/span>> \r\r<<\/span>p<\/span>>If, <\/span>in view of processing overhead<\/span>, <\/span>you prefer not to <\/span>use <\/span>DebugView<\/span>, <\/span>you can log execution times either to the Interpretation screen<\/span>, <\/span>which invokes an additional AFL execution<\/span>, or <\/span>to the chart Title <\/span>if <\/span>you output just a few measurements<\/span>. Use <\/span>of DebugView is outlined in several posts in the <\/span><<\/span>a href<\/span>=<\/span>"http:\/\/www.amibroker.org\/userkb\/category\/real-time-auto-trading\/debugging-afl\/"<\/span>><\/span>Debugging AFL<\/span><\/<\/span>a<\/span>> <\/span>category<\/span>. <\/span>When you are logging to DebugView<\/span>, <\/span>execution times will be inflated by the amount of time needed to call <\/span>and <\/span>execute the _Trace<\/span>() <\/span>functions<\/span>. <\/span>You can measure the timing overhead <\/span>for <\/span>a single<\/span>&<\/span>nbsp<\/span>;<\/span>_Trace<\/span>()&<\/span>nbsp<\/span>;function <\/span>using the same method we used above<\/span>:<\/<\/span>p<\/span>> \r\r\r<<\/span>p<\/span>><\/span>On my 2GHz laptop<\/span>, <\/span>the _Trace<\/span>() <\/span>takes about 35 microseconds to execute<\/span>. <\/span>Compared to the Param<\/span>(), <\/span>this would appear like a major error<\/span>, <\/span>but in practice it is not<\/span>. For <\/span>example<\/span>, <\/span>when calling the<\/span>&<\/span>nbsp<\/span>;<\/span>_Trace<\/span>() function <\/span>thirty times in your code<\/span>, <\/span>this would add only about 1 millisecond to the overall execution time of your program<\/span>. <\/<\/span>p<\/span>> \r\r<<\/span>p<\/span>><\/span>The example code below logs to DebugView <\/span>and <\/span>to the chart Title<\/span>. <\/span>It uses a small Trace<\/span>() function <\/span>that is called each time you want to log a timing measurement<\/span>. <\/span>You can customize this <\/span>function <\/span>to log additional information<\/span>. <\/span>Although you can call this <\/span>function <\/span>on each line<\/span>, <\/span>you <\/span>do <\/span>not have to<\/span>. <\/span>Calling Trace<\/span>() <\/span>introduces a small measurement error<\/span>. <\/span>This means that when you remove the measurement code<\/span>, <\/span>performance should be slightly better than your measurements predict<\/span>. If <\/span>you <\/span>do <\/span>not <\/span>use <\/span>DebugView<\/span>, <\/span>you can delete all DebugView related statements<\/span>. If <\/span>you <\/span>do <\/span>this<\/span>, <\/span>I suggest you comment them out until your modified code has been verified<\/span>.<\/<\/span>p<\/span>> \r\r<<\/span>p<\/span>><\/span>Be careful when calling the Trace<\/span>() <\/span>from inside a loop<\/span>. If <\/span>your loop steps through 50<\/span>,<\/span>000 bars of data<\/span>, <\/span>inserting one <\/span>or <\/span>more Trace<\/span>() <\/span>calls will slow down your code substantially <\/span>and <\/span>result in a significant measurement error<\/span>. <\/span>The key to reasonable accuracy is to <\/span>use <\/span>the minimum number of _Trace<\/span>() <\/span>statements <\/span>and <\/span>keep them out of loops <\/span>and <\/span>frequently called functions<\/span>.<\/<\/span>p<\/span>> \r\r<<\/span>p<\/span>><\/span>Inserting<\/span>\/<\/span>removing TRACE<\/span>() <\/span>statements in a test program is easily done using the Edit<\/span>- <\/span>Replace <\/span>function <\/span>in the formula editor<\/span>. <\/span>To add _Trace<\/span>() <\/span>statements<\/span>, <\/span>replace the <\/span>";" <\/span>at the end of the line with <\/span>"; TRACE(\"\");"<\/span>:<\/<\/span>p<\/span>> <<\/span>p align<\/span>=<\/span>"center"<\/span>><<\/span>img height<\/span>=<\/span>"178" <\/span>src<\/span>=<\/span>"http:\/\/www.amibroker.org\/userkb\/wp-content\/uploads\/2007\/09\/clip-image0023.jpg" <\/span>width<\/span>=<\/span>"351" <\/span>border<\/span>=<\/span>"0"<\/span>><\/<\/span>p<\/span>> \r\r<<\/span>p<\/span>><\/span>To remove the _Trace<\/span>() <\/span>statements substitute <\/span>"; TRACE(\"\");" <\/span>with <\/span>";"<\/span>:<\/<\/span>p<\/span>> <<\/span>p align<\/span>=<\/span>"center"<\/span>><<\/span>img height<\/span>=<\/span>"178" <\/span>src<\/span>=<\/span>"http:\/\/www.amibroker.org\/userkb\/wp-content\/uploads\/2007\/09\/clip-image0043.jpg" <\/span>width<\/span>=<\/span>"351" <\/span>border<\/span>=<\/span>"0"<\/span>><\/<\/span>p<\/span>> \r\r<<\/span>p<\/span>><\/span>Place your cursor just before the last <\/span>";" <\/span>that precedes the first line of code you want to time<\/span>. <\/span>Stop substitutions where you no longer want to time statements<\/span>. <\/span>You should initialize the LineNumber to the line number that contains your first Trace<\/span>() <\/span>statement<\/span>. <\/span>Line numbers <\/span>for <\/span>your cursor position are displayed at the right bottom of your editor screen<\/span>.<\/<\/span>p<\/span>> \r\r<<\/span>p<\/span>><\/span>Here is a <\/span>do-<\/span>nothing program where _Trace<\/span>() <\/span>statements were added using the above method<\/span>. <\/span>You can modify the <\/span>function <\/span>Trace<\/span>() <\/span>to output any information you like<\/span>: \r\r<<\/span>p<\/span>>function <\/span>Trace<\/span>( <\/span>Comment <\/span>)<\/<\/span>p<\/span>> <<\/span>p<\/span>>{<\/<\/span>p<\/span>> <<\/span>p<\/span>>global <\/span>LineNumber<\/span>, <\/span>TitleStr<\/span>;<\/<\/span>p<\/span>> <<\/span>p<\/span>><\/span>PC <\/span>= <\/span>GetPerformanceCounter<\/span>( <\/span>True <\/span>);<\/<\/span>p<\/span>> <<\/span>p<\/span>><\/span>Str <\/span>= <\/span>"# LN: "<\/span>+<\/span>NumToStr<\/span>(<\/span>LineNumber<\/span>++,<\/span>1.0<\/span>,<\/span>False<\/span>)+<\/span>", PC: "<\/span>+<\/span>NumToStr<\/span>(<\/span>PC<\/span>,<\/span>9.3<\/span>)+<\/span>" mSec., "<\/span>+<\/span>Comment<\/span>;<\/<\/span>p<\/span>> <<\/span>p<\/span>><\/span>TitleStr <\/span>= <\/span>TitleStr <\/span>+ <\/span>Str<\/span>+<\/span>"\\n"<\/span>;<\/<\/span>p<\/span>> <<\/span>p<\/span>><\/span>_TRACE<\/span>(<\/span>Str<\/span>);<\/<\/span>p<\/span>> <<\/span>p<\/span>>}<\/<\/span>p<\/span>> \r<<\/span>p<\/span>><\/span><\/pre>\n
The output produced in DebugView looks like this:<\/p>\n
\"dbvmeasurement.png\"<\/a><\/p>\n
The output in the Title looks like this:<\/p>\n
\"titlemeasurement.png\"<\/a><\/p>\n
The first reading in the Title should be ignored as it initializes the PerformanceCounter. This reading is suppressed by the DBViewClear command in the DebugView log. The above method can be used to determine execution times of all AFL functions. Note that in the above example SetBarsRequired() is used to process all available data. This would be the worst-case measurement. Commenting out SetBarsRequired() will make your code execute under Quick-AFL. This may be significantly faster than running over all data.<\/p>\n

\nMeasuring Execution Order and Timing for Window Panes<\/strong><\/p>\n
When you are executing AFL formulas in multiple panes or windows and experience a timing problem, the first step to take, before using the above method, is to determine which pane uses up too much time. You can turn on Tools -> Preferences ->Miscelaneous -> Display Chart Timing to read the execution time at the bottom of the charts. Alternatively, the simple code below lets you log the execution order and time for the formulas in each open pane to DebugView. Since the AmiBroker Performance Counter readout is unique for each pane, the code below does not use it. In this case you will have to turn on Options -> Show Milliseconds in DebugView. This will give you Millisecond resolution, not micro-second as with the performance Counter and is a very approximate measurement. It should only be used to identify the problem formula. The execution order of the panes is revealed by the order in which the lines appear in the DebugView.<\/p>\n
Filename <\/span>= <\/span>StrLeft<\/span>(<\/span>_DEFAULT_NAME<\/span>(),<\/span>StrLen<\/span>(<\/span>_DEFAULT_NAME<\/span>())-<\/span>2<\/span>);\rfunction <\/span>TraceChartID<\/span>() \r{ \r<\/span>Msg <\/span>= <\/span>"# ChartID, "<\/span>+<\/span>NumToStr<\/span>(<\/span>GetChartID<\/span>(),<\/span>1.0<\/span>,<\/span>False<\/span>)+<\/span>", "<\/span>+<\/span>Filename<\/span>;\r<\/span>_TRACE<\/span>( <\/span>Msg <\/span>); \rreturn <\/span>Msg<\/span>;\r} \r\r<\/span>TraceChartID<\/span>();\r\r<\/span>\/\/\r<\/span>for(<\/span>n<\/span>=<\/span>0<\/span>; <\/span>n<\/span><<\/span>BarCount<\/span>;<\/span>n<\/span>++) ; <\/span>\/\/ your code would be here\r\/\/\r\r<\/span>Title <\/span>= <\/span>TraceChartID<\/span>(); <\/span><\/pre>\n
\nThe Filename assignment and the TraceChartID() should be placed at the very top of your code, or you can add it to your default Include file. The single line used to call this function should be placed at both the beginning and the end of the code in each window\/pane. This is what it looks like in DebugView: <\/p>\n
Edited by Al Venosa.<\/p>\n","protected":false},"excerpt":{"rendered":"
When your code increases in complexity, it will start to execute more slowly, and you will eventually reach a point where you will want to optimize your code for speed of execution. Even if you are willing to buy a faster computer, it will rarely give you a greater speed advantage than optimizing your code. […]<\/p>\n","protected":false},"author":2,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":[],"categories":[64],"tags":[],"_links":{"self":[{"href":"http:\/\/www.amibroker.org\/editable_userkb\/wp-json\/wp\/v2\/posts\/1134"}],"collection":[{"href":"http:\/\/www.amibroker.org\/editable_userkb\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"http:\/\/www.amibroker.org\/editable_userkb\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"http:\/\/www.amibroker.org\/editable_userkb\/wp-json\/wp\/v2\/users\/2"}],"replies":[{"embeddable":true,"href":"http:\/\/www.amibroker.org\/editable_userkb\/wp-json\/wp\/v2\/comments?post=1134"}],"version-history":[{"count":0,"href":"http:\/\/www.amibroker.org\/editable_userkb\/wp-json\/wp\/v2\/posts\/1134\/revisions"}],"wp:attachment":[{"href":"http:\/\/www.amibroker.org\/editable_userkb\/wp-json\/wp\/v2\/media?parent=1134"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"http:\/\/www.amibroker.org\/editable_userkb\/wp-json\/wp\/v2\/categories?post=1134"},{"taxonomy":"post_tag","embeddable":true,"href":"http:\/\/www.amibroker.org\/editable_userkb\/wp-json\/wp\/v2\/tags?post=1134"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}
dbvtrace.png<\/a><\/p>\n