Debugging game slowdowns

I’m doing my own playthrough of my big game. I’m carrying 29 objects and my game is getting slower between rooms, maybe .5 to 1.0 seconds of delay. Dropping all items shortens the delay.

I have numerous rules firing; I’m pretty sure it’s not a scope issue, as RULES doesn’t show any scope loop, and the same rules are firing when objects are carried as when objects are not.

Is there a way to print a real-time timestamp for each rule to figure out how long each rule is running? Or is there another effective way to determine which part of the code is slowing things down?

It may just be having a lot of small rules that cause the problem. Here’s a sample turn when carrying many items:

Summary
[Rule "After reading a command" applies.]
[Rule "After reading a command" applies.]
[Rule "declare everything initially unmentioned rule" applies.]
[Rule "standard set going variables rule" applies.]
[Rule "announce items from multiple object lists rule" applies.]
[Rule "set pronouns from items from multiple object lists rule" applies.]
[Rule "before stage rule" applies.]
[Rule "instead stage rule" applies.]
[Rule "Instead of going somewhere when the player encloses something ( called the stolen goods ) which is not owned by the player" applies.]
[Rule "investigate player's awareness before action rule" applies.]
[Rule "player aware of his own actions rule" applies.]
[Rule "check stage rule" applies.]
[Rule "can't travel in what's not a vehicle rule" applies.]
[Rule "can't go through undescribed doors rule" applies.]
[Rule "can't go through closed doors rule" applies.]
[Rule "determine map connection rule" applies.]
[Rule "can't go that way rule" applies.]
[Rule "can't go through closed rifts rule" applies.]
[Rule "can't go through closed ladders rule" applies.]
[Rule "carry out stage rule" applies.]
[Rule "move player and vehicle rule" applies.]
[Rule "move floating objects rule" applies.]
[Rule "check light in new location rule" applies.]
[Rule "after stage rule" applies.]
[Rule "investigate player's awareness after action rule" applies.]
[Rule "report stage rule" applies.]
[Rule "describe room gone into rule" applies.]

[Rule "determine visibility ceiling rule" applies.]
[Rule "investigate player's awareness before action rule" applies.]
[Rule "player aware of his own actions rule" applies.]
[Rule "check stage rule" applies.]
[Rule "carry out stage rule" applies.]
[Rule "declare everything unmentioned rule" applies.]
[Rule "room description heading rule" applies.]
Cabin
[Rule "room description body text rule" applies.]
The interior is modest, with a table and a couple of chairs, and little else in terms of decoration. There is a fireplace along one wall with a copper apparatus built over it. You can hear the rain falling on the cabin.

On the table is a cold press.

A red door leads back to the north, while a blue door leads to the south. Stairs lead up to another floor, but they look dangerously damaged.

[Rule "room description paragraphs about objects rule" applies.]
[Rule "initialise locale description rule" applies.]
[Rule "find notable locale objects rule" applies.]
[Rule "standard notable locale objects rule" applies.]
[Rule "interesting locale paragraphs rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "initial appearance on supporters rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "initial appearance on supporters rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "don't mention player's supporter in room descriptions rule" applies.]
[Rule "don't mention scenery in room descriptions rule" applies.]
[Rule "don't mention undescribed items in room descriptions rule" applies.]
[Rule "set pronouns from items in room descriptions rule" applies.]
[Rule "offer items to writing a paragraph about rule" applies.]
[Rule "use initial appearance in room descriptions rule" applies.]
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]
[Rule "you-can-also-see rule" applies.]
[Rule "check new arrival rule" applies.]
[Rule "after stage rule" applies.]
[Rule "investigate player's awareness after action rule" applies.]
[Rule "report stage rule" applies.]
[Rule "Report looking when the curious-tool is locator" applies.]
With the curious tool in locator mode, you see a faint aura around the rotten beam.

[Rule "other people looking rule" applies.]
[Rule "last specific action-processing rule" applies.]
[Rule "last specific action-processing rule" applies.]
[Rule "A first turn sequence rule" applies.]
[Rule "every turn stage rule" applies.]
[Rule "Every turn when clonesubmerged is true and the player is not in dark-pool" applies.]
[Rule "Every turn when the player is not in grand-room" applies.]
[Rule "Every turn when the player is not in castle-region" applies.]
[Rule "Every turn when silver-fight is not happening" applies.]
[Rule "Every turn when the player is in garden-region" applies.]
[Rule "Every turn when the player is in garden-region" applies.]
[Rule "A time allotment rule for going" applies.]
[Rule "Every turn when the player is in garden-region" applies.]
[Rule "Every turn when the player is in cabin-interior" applies.]
[Rule "Every turn when cable-ladder is secretive" applies.]
[Rule "rod falling rule" applies.]
[Rule "Every turn when the train-door is closed" applies.]
[Rule "Every turn" applies.]
[Rule "Every turn" applies.]
[Rule "Every turn" applies.]
[Rule "clear personlists rule" applies.]
[Rule "clone copying rule" applies.]
[Rule "clone adjustment rule" applies.]
[Rule "clone trying to take rule" applies.]
[Rule "music duet rule" applies.]
[Rule "laser deactivation rule" applies.]
[Rule "finding cover rule" applies.]
[Rule "blaster taking rule" applies.]
[Rule "scope adjustment rule" applies.]
[Rule "clone reacting rule" applies.]
[Rule "A last turn sequence rule" applies.]
[Rule "notify score changes rule" applies.]
3 Likes

Here’s a code block (for Glulx only) that will add HH:MM:SS.SSSSSS output after every applied rule.

6M62 version:

Rules Timestamping 6M62
Section - Rules Timestamping

Include (-

Array timestamp --> 4;
Array timestamp_converted --> 8;

[ SayCurrentTimestamp ;
	glk_current_time(timestamp);
	glk_time_to_date_local(timestamp, timestamp_converted);
	print timestamp_converted-->4, ":", timestamp_converted-->5, ":", timestamp_converted-->6, ".", timestamp_converted-->7;
];

-).

To say current system timestamp:
	(- SayCurrentTimestamp(); -).

Include (-

! ==== ==== ==== ==== ==== ==== ==== ==== ==== ====
! Rulebooks.i6t: Debugging
! ==== ==== ==== ==== ==== ==== ==== ==== ==== ====

[ DebugRulebooks subs parameter i;
	spaces(2*process_rulebook_count);
	print "[", (RulePrintingRule) subs;
	if (parameter) print " / on O", parameter;
	print "]^";
];

[ DB_Rule R N blocked;
	if (R==0) return;
	print "[Rule ~", (RulePrintingRule) R, "~ ";
	#ifdef NUMBERED_RULES; print "(", N, ") "; #endif;
	! BEGIN MODIFICATION
	if (blocked == false) {
		print "applies.]";
		print "  ("; SayCurrentTimestamp(); ")";
	}
	! END MODIFICATION
	print "does not apply (wrong ", (address) blocked, ").]^";
];


-) instead of "Debugging" in "Rulebooks.i6t".

10.1.2 version:

Rules Timestamping 10.1.2
Section - Rules Timestamping

Include (-

Array timestamp --> 4;
Array timestamp_converted --> 8;

[ SayCurrentTimestamp ;
	glk_current_time(timestamp);
	glk_time_to_date_local(timestamp, timestamp_converted);
	print timestamp_converted-->4, ":", timestamp_converted-->5, ":", timestamp_converted-->6, ".", timestamp_converted-->7;
];

-).

To say current system timestamp:
	(- SayCurrentTimestamp(); -).

Include (-

[ DB_Rule R N blocked;
	if (R==0) return;
	print "[Rule ~", (RulePrintingRule) R, "~ ";
	#ifdef NUMBERED_RULES; print "(", N, ") "; #endif;
	! BEGIN MODIFICATION
	if (blocked == false) {
		print "applies.]";
		print "  ("; SayCurrentTimestamp(); ")";
	}
	! END MODIFICATION
	print "does not apply (wrong ", (address) blocked, ").]^";
];


-) replacing "DB_Rule".
8 Likes

Have you checked your skein? Deleting a not-cleared-for-months skein recovered seconds for me. That was in 6M62, but I haven’t rechecked this behaviour it in 10.x.

The number of rules you quoted doesn’t look atypical or unusually large. So I’d say it’s particular mechanisms. If otis’s rule works it out for you, we might not have to guess for long.

Some ideas:

  • Definitions that are invoked that iterate through huge numbers of things every turn
  • A rule that iterates through all items every turn, or huge numbers of items (with tricky definitions?)
  • Any regex checks? They can slow things down. Using strategies to reduce their number or do things a simpler way can help.
  • Sometimes, using the helpful ‘now every BLAH is BLAHed’ parlance can be slower than writing a manual loop that does the same thing. Wouldn’t bother with this unless it’s happening all the time and you identify it as the culprit.
  • Do you use Eric Eve’s ‘old’ epistemology? Zarf replaced its core with way faster i6. That was a change that helped me a lot.

Btw, slowdown is more pronounced in Parchment/Quixe, so if you’re getting noticeable slowdown in an offline interpreter (other than Lectrote), I’d expect it to be worse in an online situation.

EDIT PS - In Lectrote, you can use its developer tools menu to turn on a display of how much time passes in ms between the user hitting return and the end of processing that turn. This is good for checking overall lag, or lag improvement. But because of the nature of Quixe, you have to perform some actions a few times to get the final results. There can be some processing overhead that only occurs the first time you do something, but if you do that thing again, you’ll get the time it takes to perform that action from then on, that basically won’t change.

-Wade

6 Likes

Thanks! Worked like a charm. Now I’ll go dig through this for a while:

Summary
[Rule "ignore beta-comments rule" applies.]  (23:0:31.206534)
[Rule "After reading a command" applies.]  (23:0:31.207941)
[Rule "After reading a command" applies.]  (23:0:31.208800)
[Rule "declare everything initially unmentioned rule" applies.]  (23:0:31.209481)
[Rule "standard set going variables rule" applies.]  (23:0:31.226601)
[Rule "announce items from multiple object lists rule" applies.]  (23:0:31.227050)
[Rule "set pronouns from items from multiple object lists rule" applies.]  (23:0:31.227080)
[Rule "before stage rule" applies.]  (23:0:31.227107)
[Rule "instead stage rule" applies.]  (23:0:32.706136)
[Rule "Instead of going somewhere when the player encloses something ( called the stolen goods ) which is not owned by the player" applies.]  (23:0:32.708981)
[Rule "investigate player's awareness before action rule" applies.]  (23:0:32.710374)
[Rule "player aware of his own actions rule" applies.]  (23:0:32.710394)
[Rule "check stage rule" applies.]  (23:0:32.710413)
[Rule "can't travel in what's not a vehicle rule" applies.]  (23:0:32.710436)
[Rule "can't go through undescribed doors rule" applies.]  (23:0:32.710457)
[Rule "can't go through closed doors rule" applies.]  (23:0:32.710494)
[Rule "determine map connection rule" applies.]  (23:0:32.710524)
[Rule "can't go that way rule" applies.]  (23:0:32.710559)
[Rule "can't go through closed rifts rule" applies.]  (23:0:32.710584)
[Rule "can't go through closed ladders rule" applies.]  (23:0:32.710612)
[Rule "carry out stage rule" applies.]  (23:0:32.710629)
[Rule "move player and vehicle rule" applies.]  (23:0:32.710654)
[Rule "move floating objects rule" applies.]  (23:0:32.710691)
[Rule "check light in new location rule" applies.]  (23:0:32.712896)
[Rule "after stage rule" applies.]  (23:0:32.712922)
[Rule "investigate player's awareness after action rule" applies.]  (23:0:33.901906)
[Rule "report stage rule" applies.]  (23:0:33.901936)
[Rule "describe room gone into rule" applies.]  (23:0:33.925717)

[Rule "determine visibility ceiling rule" applies.]  (23:0:33.925769)
[Rule "investigate player's awareness before action rule" applies.]  (23:0:33.925819)
[Rule "player aware of his own actions rule" applies.]  (23:0:33.925834)
[Rule "check stage rule" applies.]  (23:0:33.925853)
[Rule "carry out stage rule" applies.]  (23:0:33.925870)
[Rule "declare everything unmentioned rule" applies.]  (23:0:33.925891)
[Rule "room description heading rule" applies.]  (23:0:33.939883)
Cabin
[Rule "room description body text rule" applies.]  (23:0:33.940052)
The interior is modest, with a table and a couple of chairs, and little else in terms of decoration. There is a fireplace along one wall with a copper apparatus built over it. You can hear the rain falling on the cabin.

On the table is a cold press.

A red door leads back to the north, while a blue door leads to the south. Stairs lead up to another floor, but they look dangerously damaged.

[Rule "room description paragraphs about objects rule" applies.]  (23:0:33.940264)
[Rule "initialise locale description rule" applies.]  (23:0:33.940306)
[Rule "find notable locale objects rule" applies.]  (23:0:33.957686)
[Rule "standard notable locale objects rule" applies.]  (23:0:33.957727)
[Rule "interesting locale paragraphs rule" applies.]  (23:0:34.4307)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.14669)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.14698)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.14746)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.14769)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.21339)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.21481)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.21529)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.21570)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.21766)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.21801)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.21907)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.22027)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.22067)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.22101)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.22286)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.22436)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.22630)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.22680)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.22860)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.22916)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.22972)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.23019)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.23096)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.23159)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.23281)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.23328)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.23397)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.23425)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.23471)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.23593)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.23641)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.23683)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.23792)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.23835)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.23865)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.23973)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.24004)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.24034)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.24151)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.24187)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.24251)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.24275)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.24353)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.24383)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.24413)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.24519)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.24562)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.24599)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.24676)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.24700)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.24799)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.24831)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.24859)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.24905)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.25023)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.25064)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.25136)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.25160)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.25235)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.25262)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.25288)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.25427)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.25467)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.25501)
[Rule "initial appearance on supporters rule" applies.]  (23:0:34.25563)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.25587)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.25681)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.25770)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.25801)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.25829)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.25857)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.25923)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.25982)
[Rule "initial appearance on supporters rule" applies.]  (23:0:34.26069)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.26095)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.26130)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.26287)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.27011)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.27067)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.27100)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.27135)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.27184)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.27396)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.27426)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.27510)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.27537)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.27563)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.27589)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.27622)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.27667)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.27809)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.27839)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.27934)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.27962)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.27991)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.28019)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.28052)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.28158)
[Rule "don't mention player's supporter in room descriptions rule" applies.]  (23:0:34.28236)
[Rule "don't mention scenery in room descriptions rule" applies.]  (23:0:34.28261)
[Rule "don't mention undescribed items in room descriptions rule" applies.]  (23:0:34.28353)
[Rule "set pronouns from items in room descriptions rule" applies.]  (23:0:34.28382)
[Rule "offer items to writing a paragraph about rule" applies.]  (23:0:34.28409)
[Rule "use initial appearance in room descriptions rule" applies.]  (23:0:34.28436)
[Rule "describe what's on scenery supporters in room descriptions rule" applies.]  (23:0:34.28541)
[Rule "describe what's on mentioned supporters in room descriptions rule" applies.]  (23:0:34.28583)
[Rule "you-can-also-see rule" applies.]  (23:0:34.40009)
[Rule "check new arrival rule" applies.]  (23:0:34.67104)
[Rule "after stage rule" applies.]  (23:0:34.67137)
[Rule "investigate player's awareness after action rule" applies.]  (23:0:34.67549)
[Rule "report stage rule" applies.]  (23:0:34.67565)
[Rule "Report looking when the curious-tool is locator" applies.]  (23:0:34.67633)
With the curious tool in locator mode, you see a faint aura around the rotten beam.

[Rule "other people looking rule" applies.]  (23:0:34.98132)
[Rule "last specific action-processing rule" applies.]  (23:0:34.98167)
[Rule "last specific action-processing rule" applies.]  (23:0:34.98207)
[Rule "A first turn sequence rule" applies.]  (23:0:34.98545)
[Rule "every turn stage rule" applies.]  (23:0:34.98878)
[Rule "Every turn when clonesubmerged is true and the player is not in dark-pool" applies.]  (23:0:34.115602)
[Rule "Every turn when the player is not in grand-room" applies.]  (23:0:34.145796)
[Rule "Every turn when the player is not in castle-region" applies.]  (23:0:34.145901)
[Rule "Every turn when silver-fight is not happening" applies.]  (23:0:34.164964)
[Rule "Every turn when the player is in garden-region" applies.]  (23:0:34.165198)
[Rule "Every turn when the player is in garden-region" applies.]  (23:0:34.165273)
[Rule "A time allotment rule for going" applies.]  (23:0:34.165333)
[Rule "Every turn when the player is in garden-region" applies.]  (23:0:34.165399)
[Rule "Every turn when the player is in cabin-interior" applies.]  (23:0:34.165462)
[Rule "Every turn when cable-ladder is secretive" applies.]  (23:0:34.165542)
[Rule "rod falling rule" applies.]  (23:0:34.165647)
[Rule "Every turn when the train-door is closed" applies.]  (23:0:34.165766)
[Rule "Every turn" applies.]  (23:0:34.166121)
[Rule "Every turn" applies.]  (23:0:34.170301)
[Rule "Every turn" applies.]  (23:0:34.172394)
[Rule "clear personlists rule" applies.]  (23:0:34.174523)
[Rule "clone copying rule" applies.]  (23:0:34.192473)
[Rule "clone adjustment rule" applies.]  (23:0:34.192763)
[Rule "clone trying to take rule" applies.]  (23:0:34.192840)
[Rule "music duet rule" applies.]  (23:0:34.249584)
[Rule "laser deactivation rule" applies.]  (23:0:34.249635)
[Rule "finding cover rule" applies.]  (23:0:34.249717)
[Rule "blaster taking rule" applies.]  (23:0:34.249773)
[Rule "scope adjustment rule" applies.]  (23:0:34.249799)
[Rule "clone reacting rule" applies.]  (23:0:34.249831)
[Rule "A last turn sequence rule" applies.]  (23:0:34.250345)
[Rule "notify score changes rule" applies.]  (23:0:34.252513)

@severedhand thanks for the tips! I’ll check those things first! And this was in gargoyle with a release on desktop.

4 Likes

I was able to shave the time from 3 seconds to 2 just by changing two ‘before’ rules. I noticed the ‘before stage rule’ was taking a long time, and that checks all the conditions on before rules. I had two rules from the Otranto example that said:

‘Before going when the player has something that is stuck to something anchored:’

I only need to use this in one part of the game, so I changed it to:

Before going when the player is in finale2-region:
   if the player has something that is stuck to something anchored:
6 Likes

Yeah, well spotted there.

In the time listing I see

[Rule “investigate player’s awareness before action rule” applies.] (23:0:33.925819)

That’s more than a second, if I’m reading the list right, and I believe it is an Epistemology rule nope, Standard Rules.

4 Likes

I’ll look at that one next! Searching, it seems to check if things involved in the action are visible. I was investigating slowdown, so I had my character purloin the largest group of items in the game (all the money, which in all of its denominations is a couple dozen items). So that might be unavoidable, but I could advise players to drop unneeded items. But I’ll check it!

1 Like

Here’s a variant that does the elapsed time computation for you.

6M62:

'If only I had a computer to handle these details for me...` version
Section - Rules Timestamping

Include (-

Array prev_timestamp --> 3;
Array timestamp --> 3;
Array timestamp_diff --> 3;
Array timestamp_converted --> 8;

[ StoreLastTimestamp ;
	prev_timestamp-->0 = timestamp-->0;
	prev_timestamp-->1 = timestamp-->1;
	prev_timestamp-->2 = timestamp-->2;
];

[ ComputeTimestampDiff     n ;
	n = timestamp-->2 - prev_timestamp-->2;
	if (n < 0) {
		! negative microseconds
		(timestamp-->1)--; ! assume 21st century
		timestamp_diff-->2 = 1000000-n; 
	} else {
		! positive microseconds
		timestamp_diff-->2 = n; 
	}
	timestamp_diff-->1 = timestamp-->1 - prev_timestamp-->1; ! keep assuming 21st century
	timestamp_diff-->0 = 0;  ! keep assuming 21st century
];

[ PadToTens n ;
	if (n < 10) print "0";
	print n;
];

[ PadToHundredThousands n ;
	if (n < 100000) print "0";
	if (n < 10000) print "0";
	if (n < 1000) print "0";
	if (n < 100) print "0";
	if (n < 10) print "0";
	print n;
];

[ SayCurrentTimestamp  load_only_flag;
	glk_current_time(timestamp);
	if (load_only_flag) rtrue;
	glk_time_to_date_local(timestamp, timestamp_converted);
	print (PadToTens) timestamp_converted-->4, ":", (PadToTens) timestamp_converted-->5, ":", (PadToTens) timestamp_converted-->6, ".", (PadToHundredThousands) timestamp_converted-->7;
];

[ SayDiffFromLastTimestamp    i ;
	StoreLastTimeStamp();
	glk_current_time(timestamp);
	ComputeTimestampDiff();
	glk_time_to_date_local(timestamp_diff, timestamp_converted);
	print (PadToTens) timestamp_converted-->5, ":", (PadToTens) timestamp_converted-->6, ".", (PadToHundredThousands) timestamp_converted-->7;
];


-).

To say current system timestamp:
	(- SayCurrentTimestamp(); -).

To say elapsed system time:
	(- SayDiffFromLastTimestamp(); -).

To mark initial system time:
	(- SayCurrentTimestamp(true); StoreLastTimestamp(); -).

When play begins (this is the mark initial time rule):
	mark initial system time.

Include (-

! ==== ==== ==== ==== ==== ==== ==== ==== ==== ====
! Rulebooks.i6t: Debugging
! ==== ==== ==== ==== ==== ==== ==== ==== ==== ====

[ DebugRulebooks subs parameter i;
	spaces(2*process_rulebook_count);
	print "[", (RulePrintingRule) subs;
	if (parameter) print " / on O", parameter;
	print "]^";
];

[ DB_Rule R N blocked;
	if (R==0) return;
	print "[Rule ~", (RulePrintingRule) R, "~ ";
	#ifdef NUMBERED_RULES; print "(", N, ") "; #endif;
	! BEGIN MODIFICATION
	if (blocked == false) {
		print "applies.]";
		print "  ("; SayDiffFromLastTimestamp(); ")";
	}
	! END MODIFICATION
	print "does not apply (wrong ", (address) blocked, ").]^";
];

-) instead of "Debugging" in "Rulebooks.i6t".

For 10.1.2 (untested), you should only need to replace the second Include (- ... -). (at the end) with:

Include (-

[ DB_Rule R N blocked;
	if (R==0) return;
	print "[Rule ~", (RulePrintingRule) R, "~ ";
	#ifdef NUMBERED_RULES; print "(", N, ") "; #endif;
	! BEGIN MODIFICATION
	if (blocked == false) {
		print "applies.]";
		print "  ("; SayDiffFromLastTimestamp(); ")";
	}
	! END MODIFICATION
	print "does not apply (wrong ", (address) blocked, ").]^";
];

-) replacing "DB_Rule".

Note that the first elapsed time value reported doesn’t measure the time elapsed since the player entered the command, it measures the time elapsed since the last timestamp was noted (when processing the previous command, or when play began for first shown value).

3 Likes

This was great! This helped me identify some regex slowdown. It also made me decide to completely rewrite the rope code to use item properties instead of relations, which has almost totally eliminated rope-based slowdown. I’m still debugging a few trouble spots, but this has been some immense help!

3 Likes

code optimisation for speed in IF… color me perplexed, for obvious reasons.

Best regards from Italy,
dott. Piergiorgio.

2 Likes

It can get pretty bad if you write code in dumb ways (like I was doing). It was basically checking hundreds of items to see if they were related to hundreds of items, multiple times per turn. It was enough to slow it down a lot when playing, unfortunately :frowning:

4 Likes

I managed to slow down a tiny barely implemented toy game with one room and about 10 objects when I wrote a rule which effectively looped over every object in the game six nestings deep every turn. 10^6 = 1,000,000… it’s really easy to accidentally do that in Inform 7 if you’re not careful.

This is actually a general principle for speed optimization. Look out for nested loops; look out for loops over large numbers of things; and particularly look out for nested loops over large numbers of things. The “combinatorial explosion” is the most typical source of slow running times.

2 Likes

You’re sure that your rule actually loops over actual story objects, that is, not looping over also library/extensions defined objects ?

Best regards from Italy,
dott. Piergiorgio.

2 Likes

This looks really useful, as I have some performance issues in my game. I did manage to address some issues without it (I had some loops checking visibility and concealment of lots of objects that ran every turn), but this should help with any other issues that crop up.

I did make one small change to it:

[ SayDiffFromLastTimestamp    i ;
	StoreLastTimestamp();
	glk_current_time(timestamp);
	ComputeTimestampDiff();
	glk_time_to_date_local(timestamp_diff, timestamp_converted);
	! I added this line
	if(timestamp_converted-->7 >= 1000*WORRYING_RULE_TIME || timestamp_converted-->6 > 0 || timestamp_converted-->5 > 0) style bold;
	print (PadToTens) timestamp_converted-->5, ":", (PadToTens) timestamp_converted-->6, ".", (PadToHundredThousands) timestamp_converted-->7;
	! and this line
	style roman;
];

as well as a Constant WORRYING_RULE_TIME = 500; line above the array declarations.

That just makes times of more than 500ms be shown in bold. (The choice of 500 was somewhat random – I don’t really know what’s a good value for such a check.)

1 Like