Profiling

So what do you do when your game starts to get slow? I have a particular command that’s very slow, and looking at the rules that run during the action, it seems like hardly anything is happening. Is there some way to get deeper than “rules” to see what’s really going on? Is there some way to turn on I6 debugging messages, for example?

Any tips would be helpful.

Thanks!

You could also use a special profiling interpreter, or use a web browser profiler with parchment/quixe.

I seem to recall there being a use-for-testing-only command (similar to “actions on” and “rules on”) that gave info about the I6 level, but try as I might I can’t seem to find it anywhere.

Where might I find a profiling interpreter?

Like most of the nitty-gritty programming requests, it hasn’t garnered many votes, but there’s a request for one or more profiling terps to be integrated with the IDE:

inform7.uservoice.com/forums/573 … f=comments

–Erik

I first use RULES ALL because even unexecuted rules take time to consider whether or not they apply, and if you have descriptions in the preamble like examining “someone suspicious” then there’s at least one hidden loop right there. While one or two of those don’t make much of a difference, they can add up. Every Turn rules, printing the name of rules, does the player mean rule, before & instead rules, all are considered frequently.

If you’ve narrowed it down to a single rule that’s being slow, then I suggest just inspecting the phrases within. Inform 7 is really good at hiding loops. Can you add a “let” variable to remember the result of a loop so it needn’t be looped again? That sort of thing. Is recursion occurring anywhere? Any “topic is listed in table” preamble loops? How many rules does a simple LOOK consider (not necessarily execute)? Etc.

RULES ALL didn’t turn up anything new. There is a loop in one of the phrases, but it’s a loop that also runs several times in an every turn rule, and other actions (such as waiting, ironically) aren’t slow at all.

I’m wondering if the hangup is actually happening during parsing. There’s a conditional understand line that might be slowing things down, but I don’t know how to be sure that’s the problem, and I don’t know how to speed it up:

[code]Specimen absence relates a multitude (called the set) to a thing (called the element) when the element is the specimen of the set and the element is not visible.

Understand “[something related by specimen absence]” as a multitude.[/code]

Yeah, that looks like it. I commented it out and everything went much faster. Maybe I need to write that scope-caching extension.

Turns out Scope Caching was quick to write, but didn’t result in any noticeable speed improvement. Dang!

I think Zoom lets you profile. The main one I was thinking of was Glulxe though, but you’d have to compile it yourself. Loading Parchment/Quixe with Firebug is very easy though!

I still haven’t tried out a profiler, but I managed to eliminate many of the slow-parsing cases by adding a redundant condition to the Understand rule:

Understand "[something related by specimen absence]" as a multitude when a visible multitude is abstract.

(I defined “abstract” to mean the specimen is not visible).

Someone mentioned it in another thread: TRACE!

I’d love it if testing commands were documented in the Actions index. I’m out of votes on uservoice, but if anyone wants to suggest it, I’d be grateful.

Oy vey. I now have a shell script that runs test commands using glulxe, but it takes about 40 minutes to run one of the more involved tests. Which is weird, because it only takes a few minutes in the IDE (less than 10, but I wasn’t watching).

So it looks like Zoom and glulxe don’t have high-level profiling tools, I need to write the commands into my source? I tried profiling Parchment Transcript with Firebug, but I don’t know how to read the output or send queries to the console.

As Dannii noted last time, you can compile Glulxe with profiling turned on. It’s not exactly high-level but it will track time spent in every function.

Start by reading the comments in github.com/erkyrath/glulxe/blob … analyze.py .

EDIT-ADD: Unless that’s what you were already doing?

Cool, thanks for the link!

Unfortunately, my test scripts make use of Autoundo for Object Response Tests, which probably mess with the call stack:

I was actually wondering if it was the autoundo that made the script run slow. But this will still be useful for profiling normal play.

Also, a question:

Which compiler does “inform” refer to? I notice all of the following in /Applications/Inform.app/Contents/Resources/Compilers:

Oh wait. I just looked at the “Progress” tab. It says:

/Applications/Inform.app/Contents/Resources/Compilers/inform-6.32-biplatform \ -kE2SDwG +include_path=/Applications/Inform.app/Contents/Resources/Library/Natural,.,../Source /Users/mike/i/headache.inform/Build/auto.inf /Users/mike/i/headache.inform/Build/output.ulx

So it looks like it is using the -k option - if so, why do I have so many <???>s in my profiling output?

…edit again… um, well, I hope this is useful for other people who want to try this. I forgot to specify gameinfo.dbg in my call to profile-analyze.py

Now I just have to figure out what @glk_$c0 is…

Yes, inform-6.32-biplatform is the one to use.

Is it all <???> in the output, or are you seeing some function names as well?

I was editing while you were posting…

If they’re all <???> except for a few <@glk_…> entries, then you’re probably using a gameinfo.dbg that doesn’t match the output.ulx.

No, it’s all good - I have real names now. And I figured out what @glk_$c0 must be - it’s the function to wait for input. I piped a list of commands to glulxe so I could skip that step and I got some more reasonable-looking results:

Yeah, that looks like an I7 game.

(Yes, @glk_$c0 is glk_select(), which is waiting for input.)

Those are all low-level library and veneer calls, of course. If you dig farther down the list, you may be able to find functions corresponding to I7 rules which are taking a lot of time, which are the parts of your code you’d want to focus on improving. These will have low “executing” times but high “including child calls”.

But, sadly, these will have names like “R_925” and you’ll have to look at the auto.inf file to figure out what they really are. Also, I never developed the profile-analyze.py much, so digging through the list requires you to use the “-i” option and then print out Python data structures.

It totally worked! Execution time when from 17 seconds to 2.3 seconds! Thanks Zarf!

Now there are no I7 functions at all in the top 10 total-time functions. Parser__parse is right up there… maybe I could do something with that if I need to.