VBA Performance Profiler : timing procedure execution

This is an update and replacement for the post on 9th March 2017 titled ‘Free add in to profile VBA speed and coverage’. Updated 8-Jul-2021 with an example profile report.

Download XLTEST_VBA_Profiler.xlam.

(Updated 22-Jul-2021: Tracing P_.O also sends to OutputDebugString )

I use it to find out which procedures are taking the most time, so that I can target performance improvements to the subs which need it.

INSTRUCTIONS

Open the file XLTEST_Vba_Profiler.xlam and enable macros, or install it as an add-in.

Open the workbook you want to profile. Save it under a different name to avoid overwriting the original.

On the Developer tab, in the VBA Profiler group, click the button “Profiling”.

This gives a form with two checkboxes and a Help button (which shows the same instructions as on this page). The options are:

1. Add a call to every line of code to trace its execution for coverage analysis.
   A tab-delimited text file is output of all the code after trace lines have been added
   so that the sub VBA_Profile_Reports can show what lines of code were executed.
   The text file is named from your workbook name suffixed with _VBA_COVERAGE.TXT
   
2. Export all the VBA to a text file before making the changes.
   This is just for your record, it is not used in this process.
   The tab-delimited text file is named from your workbook name suffixed with _VBA_BEFORE.TXT

When you click OK, it adds a line to every procedure in the project, unless its declaration line contains a comment ‘@notrace
The inserted line looks like this, where 12345 is the line number in the project:

Dim P_ As Object: Set P_ = VBA_Profiler.New_Profiler(): P_.Start 12345, "modulename", "procname"

It only adds one line of code to each of the procedures in the code, and that line calls subs in the addin to do the timing and calculations. That adds a few milliseconds of overhead to each procedure call. For very small, trivial, and frequently called procedures, consider adding a comment ‘@notrace to its Sub or Function declaration to suppress the insertion of a profiling line of code.

It adds a reference to VBA_Profiler to the VBProject so that those inserted lines can call the functions to do the timing calculations.

Finally, insert a procedure in any standard module like this:

Sub RunProfiler
   VBA_Profile_Initialize [delimiter]

   Call your_top_procedure_name

   VBA_Profile_Reports
End Sub

If the optional delimiter is specified after VBA_Profile_Initialize , such as vbTab or “,”
every P_.Start sends the values passed to the debug output, separated by that delimiter.
You can watch and capture that output using DebugView from SysInternals or TraceSpy from Simon Mourier. I use TraceSpy because it is faster than DbgView and did not miss any output in fast tests. To be sure that TraceSpy can keep up with the output, do not use Auto-Scroll.

VBA_Profile_Reports outputs a tab-delimited file named from the workbook name suffixed by _VBA_PROFILE.TXT;
and if you do the coverage analysis, a workbook is created with one sheet containing the contents of the _VBA_COVERAGE.TXT file with an extra column added to show the number of times a line of code was executed.
The workbook is unsaved, you can save it as a .xlsx file if you wish to keep it.

Finally, go into the VBE and click Compile to check that no syntax errors have been introduced

When a procedure exits and the P_ variable goes out of scope, the profiler counts up the number of calls and the length of time the procedure took. The resolution of the timer is about a microsecond.

The visible methods in this add-in are:

Function New_Profiler() returns an object that collects timing data for the reports.

Sub VBA_Profile_Initialize() Call to initialise the profiler data collection

Sub VBA_Profile_Reports(Optional sProfileTSV As String , Optional sCoverageTSV As String )
Produces reports. The default file names are
For the Profile output: workbook name plus “_VBA_PROFILE.TXT”
For the Coverage input: workbook name plus “_VBA_COVERAGE.TXT”

The report columns are:
Module.Proc: Module name and procedure name
Count: Number of times the procedure was called
Inclusive time: Execution time of this procedure and all those it calls
Exclusive time: Execution time within this procedure only
Average time: The average run time of the procedure, the exclusive time divided by the count of calls
Index: A sequence number

If you lose the original workbook, you can remove the profiling code by doing a Search with Wildcards and Replace All with nothing for these Find What strings:
Dim P_ *
P_O *&:

Feedback is welcome!

Limitations: It does not handle Unicode workbook and module names, so use the Windows-1252 Latin character set only.

Assurance: It only works locally, and does not ‘phone home’ with any telemetry. It is supplied free and with no guarantee, in the hope that it provides some utility.

EXAMPLE

Consider a module with three procedures. TopProc calls SubA once. SubA calls SubB four times. TopProc takes 1 second with its own code, SubA takes 3 seconds, and SubB takes 2 seconds. This is what the profile report will look like:

Module.Proc	Count	Inclusive time	Exclusive time	Average time	Index
TopProc	1	12.0000000	1.0000000	1.0000000	1
SubA	1	11.0000000	3.0000000	3.0000000	2
SubB	4	8.0000000	8.0000000	2.0000000	3

Example profile report

From this you see that:

TopProc is called once. The total execution time including its called subs is 12 seconds. The code in TopProc alone takes one second.

SubA is called once. The code in SubA takes three seconds. The total execution time including the eight seconds for its called subs is 11 seconds.

SubB is called four times. The total execution time is 8 seconds, so the average time per execution is 2 seconds.

Sort the table by Exclusive time descending to see which subs takes the most time overall. Sort by Average time to see which are slowest per execution.

To learn more about profiling, see these Microsoft articles:

https://docs.microsoft.com/en-us/visualstudio/profiling/instrumentation-method-data-views?view=vs-2017

https://docs.microsoft.com/en-us/visualstudio/profiling/caller-callee-view-instrumentation-data

Caller/Callee view – instrumentation data