collect avg timings for module subcmds

[boegel]

This needs more work before it can go in, this is just a (useable) mockup.

@rtmclay is using this to work on speeding up --terse avail .

[boegel]

@rtmclay: I cleaned this up a bit further, to make sure the timings are only collecting when testing, and that they're only printed when requested (i.e. when $EASYBUILD_TEST_MODULE_CMD_TIMINGS is defined).

@JensTimmerman, @stdweird: please review?

[wpoely86]

Looks good

[JensTimmerman]

Is this really something you want to just print out?
Do you really want to use the unit tests as a benchmark for the modules tool?

Imho it's better to actually create a benchmark for that tool then, instead of pushing this in the master unittests.
if the unittests change your results might change here and past data will be useless.

The speed of the module commands should not be something the unittests are concerned with.
And if they should be, then you should add a unittest checking if command's don't take to long.

[hpcugentbot]

EasyBuild framework unit test suite FAILed.

See https://jenkins1.ugent.be/job/easybuild-framework-pr-builder/2923/console for more details.

Please fix the reported issues by pushing additional commits to the branch corresponding with this pull request; contact @boegel if you're not sure what to do.

[boegel]

Timings collected with full test suite with EasyBuild v2.8.0dev (very close to v2.7.0), cfr https://travis-ci.org/boegel/easybuild-framework/builds/119748444.

main conclusion: waaaay too many use calls (cfr #1661), and we should cache the --version output

• environment modules 3.2.10:

Ran 391 tests in 371.292s
OK
avg time for --version:   0.0058s (cnt: 2649, total:  15.365s)
avg time for       1.0:   0.0090s (cnt: 192, total:   1.728s)
avg time for     avail:   0.0117s (cnt: 305, total:   3.563s)
avg time for      list:   0.0064s (cnt: 308, total:   1.957s)
avg time for      load:   0.0309s (cnt: 393, total:  12.155s)
avg time for     purge:   0.0160s (cnt: 117, total:   1.868s)
avg time for      show:   0.0092s (cnt: 673, total:   6.197s)
avg time for    unload:   0.0078s (cnt: 135, total:   1.050s)
avg time for     unuse:   0.0065s (cnt: 4729, total:  30.660s)
avg time for       use:   0.0077s (cnt: 10094, total:  78.104s)
total time in module commands:  152.646s

• Lmod 5.6.3, modules in Tcl syntax

Ran 391 tests in 949.766s
OK
avg time for --version:   0.0251s (cnt: 2659, total:  66.723s)
avg time for       1.0:   0.0088s (cnt: 192, total:   1.696s)
avg time for     avail:   0.0610s (cnt: 310, total:  18.902s)
avg time for      list:   0.0375s (cnt: 310, total:  11.612s)
avg time for      load:   0.1024s (cnt: 395, total:  40.447s)
avg time for     purge:   0.0963s (cnt: 117, total:  11.271s)
avg time for      show:   0.0750s (cnt: 675, total:  50.632s)
avg time for    unload:   0.0554s (cnt: 137, total:   7.593s)
avg time for     unuse:   0.0304s (cnt: 752, total:  22.834s)
avg time for       use:   0.0497s (cnt: 9348, total: 464.456s)
total time in module commands:  696.166s

• Lmod 5.6.3, modules in Lua syntax

Ran 391 tests in 863.362s
OK
avg time for --version:   0.0225s (cnt: 2659, total:  59.869s)
avg time for       1.0:   0.0086s (cnt: 192, total:   1.659s)
avg time for     avail:   0.0537s (cnt: 310, total:  16.634s)
avg time for      list:   0.0322s (cnt: 310, total:   9.975s)
avg time for      load:   0.0834s (cnt: 387, total:  32.284s)
avg time for     purge:   0.0795s (cnt: 117, total:   9.297s)
avg time for      show:   0.0639s (cnt: 663, total:  42.345s)
avg time for    unload:   0.0422s (cnt: 137, total:   5.780s)
avg time for     unuse:   0.0269s (cnt: 752, total:  20.252s)
avg time for       use:   0.0438s (cnt: 9316, total: 408.078s)
total time in module commands:  606.172s

• Lmod 6.1, modules in Tcl syntax:

Ran 391 tests in 959.277s
OK
avg time for --version:   0.0258s (cnt: 2659, total:  68.700s)
avg time for       1.0:   0.0088s (cnt: 192, total:   1.687s)
avg time for     avail:   0.0553s (cnt: 310, total:  17.156s)
avg time for      list:   0.0355s (cnt: 310, total:  11.001s)
avg time for      load:   0.1015s (cnt: 395, total:  40.110s)
avg time for     purge:   0.0910s (cnt: 117, total:  10.650s)
avg time for      show:   0.0739s (cnt: 675, total:  49.891s)
avg time for    unload:   0.0526s (cnt: 137, total:   7.206s)
avg time for     unuse:   0.0312s (cnt: 752, total:  23.434s)
avg time for       use:   0.0513s (cnt: 9348, total: 479.610s)
total time in module commands:  709.445s

[hpcugentbot]

EasyBuild framework unit test suite FAILed.

See https://jenkins1.ugent.be/job/easybuild-framework-pr-builder/2938/console for more details.

Please fix the reported issues by pushing additional commits to the branch corresponding with this pull request; contact @boegel if you're not sure what to do.

[akesandgren]

@boegel Relevance of this one?

[akesandgren]

Ping @boegel again