Benchmark code execution

[Sam.]

I would like a way to benchmark code execution time with WeiDU.  I don't particularly care if it uses math with high-resolution time stamps, tick counts, or processor cycles, as long as it is accurate enough to be meaningful.  There are often a great number of ways to accomplish the same task using different commands or procedures (reading/editing 2DA files is one example of this), and I think it would be useful to have a standard, reproducible way to document which perform significantly faster (or slower) than others.

Presumably a version of this is already implemented internally:

Code: [Select]

WeiDU Timings
OUTER_INNER_PATCH_SAVE           0.000
EXTEND_TOP                       0.000
<<<<<<<<                         0.000
OUTER_WHILE                      0.000
ACTION_FOR_EACH                  0.000
parsing .ids files               0.000
adding translation strings       0.000
ACTION_BASH_FOR                  0.000
DEFINE_PATCH_FUNCTION            0.000
resolve labels                   0.000
VERBOSE                          0.000
ACTION_DEFINE_ARRAY              0.000
emit D                           0.000
DEFINE_ACTION_FUNCTION           0.000
MKDIR                            0.000
ACTION_TRY                       0.000
find local string                0.000
LOAD_TRA                         0.000
strings to add                   0.000
parsing .log files               0.000
ACTION_TO_LOWER                  0.000
OUTER_FOR                        0.000
DEFINE_ACTION_MACRO              0.000
ACTION_TO_UPPER                  0.000
OUTER_INNER_PATCH                0.000
SILENT                           0.000
marshal DLG                      0.000
resolve strings                  0.000
DEFINE_PATCH_MACRO               0.000
unmarshal DLG                    0.000
RANDOM_SEED                      0.000
parsing .d files                 0.000
unmarshal BIFF                   0.016
ACTION_MATCH                     0.016
INCLUDE                          0.016
APPEND                           0.016
PRINT                            0.016
ACTION_CLEAR_ARRAY               0.031
LAUNCH_ACTION_FUNCTION           0.031
COMPILE                          0.047
AT_NOW                           0.047
Parsing TPP files                0.047
BUT_ONLY                         0.063
ACTION_DEFINE_ASSOCIATIVE_ARRAY   0.063
ACTION_PHP_EACH                  0.063
add strings to TLK               0.063
OUTER_SPRINT                     0.078
parsing .tra files               0.094
marshal KEY                      0.094
DISABLE_FROM_KEY                 0.125
LAUNCH_ACTION_MACRO              0.141
marshal and save TLK             0.156
ACTION_IF                        0.156
parsing .bcs files               0.172
Parsing TPA files                0.172
REINCLUDE                        0.203
Parsing TP2 files                0.219
unmarshal KEY                    0.281
stuff not covered elsewhere      0.875
unmarshal TLK                    1.141
OUTER_SET                        1.797
parsing .baf files               2.578
COPY                             3.109
marshal BCS                      5.219
saving files                     5.406
loading files                    6.828
READ_*                          16.156
eval_pe                         52.734
process_patch2                 1097.313
TOTAL                          1195.578What I'm asking for is to give the modder direct access to the underlying functionality:  being able to manually start a timer before a block of code and stop it after the code is executed.  The time from start to stop would then either be stored to a variable or directly printed to console.

Is this feasible to implement, and do other modders think it might be useful?

[CamDawg]

I would find it interesting, not sure if I'd go so far as to say useful, namely because I'm constantly throwing regexp copies at the game. I can say unequivocally that GAME_IS inside a large regexp copy is painfully slow.

[Wisp]

What I'm asking for is to give the modder direct access to the underlying functionality:  being able to manually start a timer before a block of code and stop it after the code is executed.  The time from start to stop would then either be stored to a variable or directly printed to console.

Is this feasible to implement, and do other modders think it might be useful?

Is it necessary to have access to the time in TP2? It'll show up among the other timings, under a name of your choosing, but picking out the time for this particular task and returning it to the TP2 level is bothersome.

FWIW, the time is measured as "execution time of the process", whatever that means.

I can say unequivocally that GAME_IS inside a large regexp copy is painfully slow.

You can usually cache GAME_IS (like this, I mean, or by setting string vars or something). The things GAME_IS checks need not be constant, so I don't think I could make GAME_IS itself cache without potentially causing problems or restricting usage.

[CamDawg]

Yeah, that's exactly what I do--I set a var prior to the regexp and check that instead. I was just making an observation, not trying to shovel more work on you.

[Wisp]

What I'm asking for is to give the modder direct access to the underlying functionality:  being able to manually start a timer before a block of code and stop it after the code is executed.  The time from start to stop would then either be stored to a variable or directly printed to console.

Is this feasible to implement, and do other modders think it might be useful?

Is it necessary to have access to the time in TP2? It'll show up among the other timings, under a name of your choosing, but picking out the time for this particular task and returning it to the TP2 level is bothersome.

Okay, the snag is that if you are doing something which is already timed, the work is logged under that job, rather than you job. For example, if you are decompling scripts, the timings come out something like

Code: [Select]

marshal BCS: N seconds
parsing .bcs files: M seconds
my job: 0 seconds
because when you subtract the actual work that is already logged, my job is just some tiny amount of overhead of running the benchmark. So the straightforward implementation is out. I'll have to think about this.

[Wisp]

Code: [Select]

ACTION_TIME "my label" BEGIN TP2 Action list END
will measure the time needed to execute the TP2 Actions and report it under the label "my label" together with the other time measurements at the end of the debug file. The corresponding patch also exists.

[Sam.]

Code: [Select]

ACTION_TIME "my label" BEGIN TP2 Action list END
will measure the time needed to execute the TP2 Actions and report it under the label "my label" together with the other time measurements at the end of the debug file. The corresponding patch also exists.

Awesome!  I can't wait to try it out, thank you.

[Argent77]

That's a great debugging feature!

I've tested it with a couple of WeiDU commands with interesting results:

Code: [Select]

    Mod Timings
FILE_EXISTS_IN_GAME check        0.437
GAME_INCLUDES check              0.281
GAME_IS check                    3.869
Reference check                  0.078

Looks like GAME_IS is indeed an expensive operation.

[AL|EN]

Just for the record, using "FILE_EXISTS_IN_GAME" should never be used to detect "if a mod component can be installed for specific game"