Profiling a BASIC program

[Vectrex32]

Let's say you want to profile your BASIC program, i.e. determine what lines of code it's spending most of its time on, perhaps to optimize it. Here's a technique I came up with.

From the terminal, I LOADed my program. I turned tracing on (TRON). Then, in the terminal program, I turned logging on (I use TeraTerm so I selected File -> Log. Note that by default, TeraTerm appends to the log file. You don't want that; you want it to create a new file. So uncheck the Append box.)

Then I ran my program. The line numbers were printed out as it executed and TeraTerm wrote them to the log file. The program also runs slower, but hopefully the results will still reflect the program's normal behavior. When I had run the program long enough, I hit Ctrl+C and turned off TeraTerm's logging.

Next, I opened the log file in Notepad++. It contains line numbers in square brackets. I did a Replace All, replacing "]" with "]\n", i.e. I added a line break after each number. For Notepad++ to recognize \n as a newline, you need to set the Search Mode to Extended in the Replace dialog.

Then I saved the file.

Next, I opened a bash window (I have Windows Subsystem for Linux on my PC). I ran the command:

Code Select Expand

sort teraterm.log | uniq -c | sort -r -n >profile.txt

This sorts the line numbers, then uniq counts how many times each line number occurs, then the second sort command sorts the file so the most-executed line number is at the top. profile.txt will contain a list of line numbers, with the number of times that line was executed, in order with the most-executed line on top. You can use that as a guide for optimizing your code.

Note that this tells you which line is executed the most, but it doesn't tell you which line consumes the most processor time. It's conceivable that a simple line of code is executed most often, but a more complex line of code consumes more time overall.

I apologize for the Windows-centric nature of my description, and the dependence on the Linux subsystem. There are certainly plenty of other ways to achieve the same results. If you profile your code with a different set of tools, please post a description here.

- Bob

[jaymzjulian]

Any chance of having the an option to TRON to output also the current value of the vectrex32 timer?  That way we should be able to turn that easily into "what line takes how many cycles" with a few lines of script, and then maybe beyond that turn that into function times etc (that one is not a simple script, obv, but I actually get a lot of value out of the former when I do it!)

[Vectrex32]

It might be do-able. But try this first: get the tick count after you return from WaitForFrame. Then, before you call WaitForFrame again, get the tick count and see how much time you've been running the BASIC code. Compare that to how much time you have for each frame. What do you see?

- Bob

[jaymzjulian]

So that strategy totally works in terms of "how much frame time have I consumed", which I've actually been using - i was thinking of it in terms of, though, it becomes tedious to wrap everything i want to instrument by hand like that - but it _does_ work

[Vectrex32]

And how much time are you using? No need to profile and optimize until you're pushing the envelope.

- Bob

[jaymzjulian]

And how much time are you using? No need to profile and optimize until you're pushing the envelope.

- Bob

Oh, the only reason I was profiling in the first place was the frame rate was dropping way back .  I'm a big fan of the old adage "premature optimization is the root of all evil".  I did end up just stopping trying to do the stupid thing I was doing, in any case.