SCL Time Measureme

Lately I've been working on some models that are pretty involved, in terms of the scale of what's going on as well as making some calls that seem to run slow (creating new parts, packing parts, messing with allocating lists and structures into memory). I wasn't sure what was taking so long, and it's very hard to say with SCL the way it is.

I could have instrumented my code with some subroutine call to store the start time of every subroutine in a logic file, and then another call at the end of the subroutine (before the End line or any Return lines) that logs the time it took to run that subroutine.

Doing so manually would take quite a bit of effort, so I tried my hand at writing something in VB6 that would do the trick, and I think I've succeeded.

I created a standalone executable you can call from any command shell (on Windows) and pass in the full path to the SCL file to instrument, and optionally you can pass a second argument that is the name of the init logic in your model, and an optional 3rd argument specifying a string pattern for commenting out any existing instrumentation you've added to the logic.

Here's an example call I've used:

scltimeinstrument.exe "C:/Delmia/Questlib/LOGICS/CMSD/CMSD.scl" cmsd_model_init_logic *writer(*,*)*

So the first argument again is just the path to the SCL file to instrument. The second argument is cmsd_model_init_logic, so the instrumenter program will find the cmsd_model_init_logic subroutine as it's defined in the file, and the first line after Begin in that subroutine will be a call to a subroutine we include that will initialize the time log file (hardcoded as C:/Tmp/scl_times_log.txt"

The third argument "*writer(*,*)*" specifies to the program to find any line that contains the text "writer(" followed by anything, then a comma, then anything, and closed with a close paren, and finally allow anything outside the paren (to allow comments). This string pattern works well for me because I have one routine called writer where I pass some string message in as the first argument, and the second argument tells what the call means (i.e. error message, or standard debug, or starting/ending some subroutine). So this pattern matches my usage well, because my code is instrumented with this single call, and I can easily wipe out those calls now.

The output file is just a flat text file (saved to C:/Tmp/scl_times_log.txt) that shows the time (in milliseconds) every subroutine call took every time it was called (so long as that time was more than 1 millisecond). It's up to you to analyze the data (I use averageif, etc... in Excel to summarize the data)

Anyways, enough of my blabbing, here's a link to the tool.