profile-run-one.txt

Profile run one: initial turn (through the first room description)
> YES / YES / ANDRA / / QUIT / YES

Main__:
  at $00003c (line 0); called 1 times
  0.000008 sec (1 ops) spent executing
  6.820018 sec (47815730 ops) including child calls
Main:
  at $00b94b (line 8589); called 1 times
  0.000004 sec (9 ops) spent executing
  6.820010 sec (47815729 ops) including child calls
ProcessRulebook:
  at $0bc9e4 (line 151997); called 171608 times
  0.823224 sec (9066042 ops) spent executing
  6.820002 sec (47815689 ops) including child calls
FollowRulebook:
  at $0bc87c (line 151939); called 386 times
  0.000721 sec (5398 ops) spent executing
  6.570315 sec (45259402 ops) including child calls
R_9: ["when play begins stage rule"]
  at $01874e (line 58793); called 1 times
  0.000000 sec (2 ops) spent executing
  5.729942 sec (43989369 ops) including child calls
Relation_TestVtoV:
  at $0ba375 (line 150895); called 524290 times
  1.827328 sec (16252561 ops) spent executing
  2.570643 sec (16252561 ops) including child calls
R_999: ["caching thread position information rule"]
  at $018b83 (line 59213); called 1 times
  0.000751 sec (4234 ops) spent executing
  2.400735 sec (15615520 ops) including child calls
R_3470: ["initialize hash codes rule"]
  at $018c3b (line 59285); called 1 times
  0.000003 sec (22 ops) spent executing
  2.138514 sec (20547035 ops) including child calls
R_SHELL_1: ["initialize hash codes rule"]
  at $018cc9 (line 59294); called 1 times
  0.008274 sec (70887 ops) spent executing
  2.138229 sec (20543623 ops) including child calls
INDEXED_TEXT_TY_Support:
  at $1b8c86 (line 284110); called 2714 times
  0.002251 sec (13450 ops) spent executing
  1.654880 sec (14980028 ops) including child calls
BlkValueCast:
  at $1b872b (line 283767); called 2268 times
  0.002581 sec (18144 ops) spent executing
  1.641408 sec (14805484 ops) including child calls
INDEXED_TEXT_TY_Cast:
  at $1b8d42 (line 284152); called 2316 times
  0.035961 sec (284148 ops) spent executing
  1.639754 sec (14802796 ops) including child calls
ProcessActivityRulebook:
  at $0b7ca1 (line 149580); called 7101 times
  0.006658 sec (47443 ops) spent executing
  1.428100 sec (12873863 ops) including child calls
PrintShortName:
  at $0b9812 (line 150627); called 2240 times
  0.001757 sec (11200 ops) spent executing
  1.300434 sec (11805848 ops) including child calls
PSN__:
  at $0b9350 (line 150470); called 2240 times
  0.002738 sec (17920 ops) spent executing
  1.298698 sec (11794758 ops) including child calls
CarryOutActivity:
  at $0b7cc7 (line 149589); called 2339 times
  0.002711 sec (9356 ops) spent executing
  1.296445 sec (11785278 ops) including child calls
text_routine_1327: [creating indexed-text form of an object name in "initialize hash codes rule"]
  at $126111 (line 191462); called 2118 times
  0.002149 sec (14826 ops) spent executing
  1.258477 sec (11374504 ops) including child calls
PARSE_COMMAND_R:
  at $00bb00 (line 8682); called 1 times
  0.000002 sec (5 ops) spent executing
  0.839691 sec (1263698 ops) including child calls
Parser__parse:
  at $0079f3 (line 5683); called 1 times
  0.000144 sec (1640 ops) spent executing
  0.839689 sec (1263688 ops) including child calls
R_992: ["indirect-following initializing rule"]
  at $018b47 (line 59194); called 1 times
  0.000286 sec (1830 ops) spent executing
  0.824348 sec (5338916 ops) including child calls

profile-run-two.txt

Profile run two: initial turn followed by three move commands and four look commands.
> YES / YES / ANDRA / / LOOK / NORTH / LOOK / E / LOOK / W / LOOK / QUIT / YES

Main__:
  at $00003c (line 0); called 1 times
  0.000008 sec (1 ops) spent executing
  15.843844 sec (101211818 ops) including child calls
Main:
  at $00b94b (line 8589); called 1 times
  0.000012 sec (72 ops) spent executing
  15.843836 sec (101211817 ops) including child calls
ProcessRulebook:
  at $0bc9e4 (line 151997); called 348915 times
  1.617080 sec (17741944 ops) spent executing
  15.843762 sec (101211256 ops) including child calls
FollowRulebook:
  at $0bc87c (line 151939); called 1672 times
  0.003119 sec (23524 ops) spent executing
  15.593167 sec (98655427 ops) including child calls
R_9: ["when play begins stage rule"]
  at $01874e (line 58793); called 1 times
  0.000000 sec (2 ops) spent executing
  5.743069 sec (43988941 ops) including child calls
BeginAction:
  at $0b7156 (line 149174); called 9 times
  0.000021 sec (180 ops) spent executing
  4.404934 sec (28049971 ops) including child calls
ActionPrimitive:
  at $0b71b4 (line 149188); called 9 times
  0.000065 sec (324 ops) spent executing
  4.404337 sec (28044601 ops) including child calls
GENERATE_ACTION_R:
  at $00bb6d (line 8701); called 8 times
  0.000027 sec (192 ops) spent executing
  4.399051 sec (27986270 ops) including child calls
PARSE_COMMAND_R:
  at $00bb00 (line 8682); called 8 times
  0.000012 sec (40 ops) spent executing
  4.007250 sec (14739940 ops) including child calls
Parser__parse:
  at $0079f3 (line 5683); called 8 times
  0.001074 sec (12235 ops) spent executing
  4.007234 sec (14739860 ops) including child calls
ProcessActivityRulebook:
  at $0b7ca1 (line 149580); called 93530 times
  0.085968 sec (652292 ops) spent executing
  3.760369 sec (33404765 ops) including child calls
CarryOutActivity:
  at $0b7cc7 (line 149589); called 26958 times
  0.031213 sec (107832 ops) spent executing
  2.687756 sec (24899895 ops) including child calls
Relation_TestVtoV:
  at $0ba375 (line 150895); called 524366 times
  1.828462 sec (16254917 ops) spent executing
  2.572408 sec (16254917 ops) including child calls
R_1701: ["sanity-check stage rule"]
  at $01e144 (line 62027); called 8 times
  0.000007 sec (24 ops) spent executing
  2.559630 sec (13802266 ops) including child calls
R_1803: ["Sanity-check going to a room"]
  at $07e9e3 (line 113834); called 3 times
  0.000008 sec (57 ops) spent executing
  2.540165 sec (13587048 ops) including child calls
R_1806: ["room-restriction rule for a southern room"]
  at $08c16c (line 120021); called 3 times
  0.000005 sec (18 ops) spent executing
  2.540050 sec (13586037 ops) including child calls
Adj_68_t1_v9: [meaning of "southern" (adjective: rooms)]
  at $0aea60 (line 140460); called 3 times
  0.000003 sec (12 ops) spent executing
  2.540044 sec (13586019 ops) including child calls
R_1805: [route-finding call for meaning of "southern"]
  at $0ad380 (line 138373); called 3 times
  0.000004 sec (24 ops) spent executing
  2.540040 sec (13586007 ops) including child calls
MapRouteTo:
  at $0bb0b6 (line 151212); called 3 times
  0.005842 sec (62637 ops) spent executing
  2.540036 sec (13585983 ops) including child calls
SlowRouteTo:
  at $0bb22b (line 151324); called 3 times
  1.475841 sec (13500340 ops) spent executing
  2.531099 sec (13522146 ops) including child calls
R_999: ["caching thread position information rule"]
  at $018b83 (line 59213); called 1 times
  0.000749 sec (4234 ops) spent executing
  2.398947 sec (15615520 ops) including child calls
Keyboard:
  at $007776 (line 5566); called 10 times
  0.000317 sec (3420 ops) spent executing
  2.292122 sec (10757 ops) including child calls
VM_Save_Undo:
  at $001e56 (line 2636); called 10 times
  2.290639 sec (90 ops) spent executing
  2.290639 sec (90 ops) including child calls
R_3470: ["initialize hash codes rule"]
  at $018c3b (line 59285); called 1 times
  0.000002 sec (22 ops) spent executing
  2.149576 sec (20547035 ops) including child calls
R_SHELL_1: ["initialize hash codes rule"]
  at $018cc9 (line 59294); called 1 times
  0.008266 sec (70887 ops) spent executing
  2.149297 sec (20543623 ops) including child calls
BeginActivity:
  at $0b7cee (line 149596); called 31180 times
  0.065097 sec (449120 ops) spent executing
  2.100986 sec (17488957 ops) including child calls
WhetherProvides:
  at $0bc3c4 (line 151801); called 205805 times
  0.796390 sec (6515214 ops) spent executing
  1.939396 sec (16464609 ops) including child calls
TestVisibility:
  at $0cf560 (line 157989); called 4179 times
  0.005491 sec (29166 ops) spent executing
  1.860520 sec (15756899 ops) including child calls
TestScope:
  at $00aa68 (line 7975); called 4187 times
  0.009252 sec (79553 ops) spent executing
  1.724468 sec (14895357 ops) including child calls
INDEXED_TEXT_TY_Support:
  at $1b8c86 (line 284110); called 3687 times
  0.002968 sec (17972 ops) spent executing
  1.722060 sec (15570406 ops) including child calls