test runtime statistics with incorrect run and total values

[ebirn]

Using ReFrame 3.10.0, the timing stats look off. this is a set of tests that gets executed sequentially (there is only 1 node, using it exclusively). The run and total stats per test look like total offset from when reframe was launched. I expected the test (job) runtime (roughly), and total = compile+run.
See also the perf report below, that shows the actual test runtimes, 1,5 - 5 minutes

[----------] start processing checks
[ RUN      ] VASPCpuCheck %tasks=88 %node_type=m1 @cbe:mem+intelmpi2019b
[ RUN      ] VASPCpuCheck %tasks=76 %node_type=m2 @cbe:mem+intelmpi2019b
[ RUN      ] VASPCpuCheck %tasks=76 %node_type=m1 @cbe:mem+intelmpi2019b
[ RUN      ] VASPCpuCheck %tasks=64 %node_type=m2 @cbe:mem+intelmpi2019b
[ RUN      ] VASPCpuCheck %tasks=64 %node_type=m1 @cbe:mem+intelmpi2019b
[ RUN      ] VASPCpuCheck %tasks=32 %node_type=m2 @cbe:mem+intelmpi2019b
[ RUN      ] VASPCpuCheck %tasks=32 %node_type=m1 @cbe:mem+intelmpi2019b
[ RUN      ] VASPCpuCheck %tasks=16 %node_type=m2 @cbe:mem+intelmpi2019b
[ RUN      ] VASPCpuCheck %tasks=16 %node_type=m1 @cbe:mem+intelmpi2019b
[       OK ] (1/9) VASPCpuCheck %tasks=88 %node_type=m1 @cbe:mem+intelmpi2019b [compile: 0.013s run: 172.772s total: 173.114s]
[       OK ] (2/9) VASPCpuCheck %tasks=76 %node_type=m1 @cbe:mem+intelmpi2019b [compile: 0.015s run: 293.105s total: 295.378s]
[       OK ] (3/9) VASPCpuCheck %tasks=64 %node_type=m1 @cbe:mem+intelmpi2019b [compile: 0.015s run: 423.151s total: 427.416s]
[       OK ] (4/9) VASPCpuCheck %tasks=32 %node_type=m1 @cbe:mem+intelmpi2019b [compile: 0.015s run: 593.286s total: 599.524s]
[       OK ] (5/9) VASPCpuCheck %tasks=16 %node_type=m1 @cbe:mem+intelmpi2019b [compile: 0.014s run: 934.704s total: 942.955s]
^C[     FAIL ] (6/9) VASPCpuCheck %tasks=76 %node_type=m2 @cbe:mem+intelmpi2019b [compile: 0.014s run: 1072.532s total: 1073.872s]
==> test failed during 'run': test staged in '/users/adm_ebirn/projects/clip-reframe-dev/stage/2022-02-02T23_36/cbe/mem/intelmpi2019b/VASPCpuCheck_76_m2'
[     FAIL ] (7/9) VASPCpuCheck %tasks=64 %node_type=m2 @cbe:mem+intelmpi2019b [compile: 0.015s run: 1070.522s total: 1073.807s]
==> test failed during 'run': test staged in '/users/adm_ebirn/projects/clip-reframe-dev/stage/2022-02-02T23_36/cbe/mem/intelmpi2019b/VASPCpuCheck_64_m2'
[     FAIL ] (8/9) VASPCpuCheck %tasks=32 %node_type=m2 @cbe:mem+intelmpi2019b [compile: 0.016s run: 1068.480s total: 1073.738s]
==> test failed during 'run': test staged in '/users/adm_ebirn/projects/clip-reframe-dev/stage/2022-02-02T23_36/cbe/mem/intelmpi2019b/VASPCpuCheck_32_m2'
[     FAIL ] (9/9) VASPCpuCheck %tasks=16 %node_type=m2 @cbe:mem+intelmpi2019b [compile: 0.016s run: 1066.398s total: 1073.671s]
==> test failed during 'run': test staged in '/users/adm_ebirn/projects/clip-reframe-dev/stage/2022-02-02T23_36/cbe/mem/intelmpi2019b/VASPCpuCheck_16_m2'
[  FAILED  ] Ran 5/9 test case(s) from 9 check(s) (0 failure(s), 0 skipped)
[==========] Finished on Wed Feb  2 23:54:11 2022 

==============================================================================
PERFORMANCE REPORT
------------------------------------------------------------------------------
VASPCpuCheck %tasks=88 %node_type=m1
- cbe:mem
   - intelmpi2019b
      * num_tasks: 88
      * time: 88.653 s
------------------------------------------------------------------------------
VASPCpuCheck %tasks=76 %node_type=m1
   - intelmpi2019b
      * num_tasks: 76
      * time: 91.34 s
------------------------------------------------------------------------------
VASPCpuCheck %tasks=64 %node_type=m1
   - intelmpi2019b
      * num_tasks: 64
      * time: 104.521 s
------------------------------------------------------------------------------
VASPCpuCheck %tasks=32 %node_type=m1
   - intelmpi2019b
      * num_tasks: 32
      * time: 155.553 s
------------------------------------------------------------------------------
VASPCpuCheck %tasks=16 %node_type=m1
   - intelmpi2019b
      * num_tasks: 16
      * time: 261.269 s

[vkarak]

Those timings were never accurate, but probably got completely off with the reimplementation of the runtime in #2194. @ekouts any chance that we can make those more accurate as requested in #1527 or we could completely hide them.

[teojgo]

@ebirn I cannot reproduce this. Can you do a separate reframe run for 88 and 16 tasks and see what is the reported runtime?

[ebirn]

I can try to reproduce later. The cause for the timing values in brackets is that we only have 1 node of special node_type "m1" therefore the tests effectively execute serially and that leads to the adding up of run-time values.
i.e. it depends on the number of reframe tests that will be executed, not the specific job size (in that case)

[ekouts]

I expected the test (job) runtime (roughly), and total = compile+run.

Total time includes the time that it took for the test to setup, compile, run, check sanity and performance. But it does include more, since it is actually the difference from a timestamp just before setup begins until the end of the last stage (it is usually performance but a test can fail earlier).

Another important clarification is that the run time includes the waiting time on the scheduler queue. It is showing the time that this test is in the run phase for ReFrame and not for how long it actually runs. This stage begins with the submission of the job and finishes as soon as ReFrame realizes that the job has finished.

@ebirn what scheduler are you using? If you are using a scheduler like slurm with max_jobs>=9, the output would make sense, since all the jobs are submitted but run one after the other. You could check the log to see when exactly each test enters the run phase or share with us (part of) the log and have a look to make sure there is no other problem.

Do you think we could improve this section to make it more complete? https://reframe-hpc.readthedocs.io/en/stable/pipeline.html#timing-the-test-pipeline
These timings may indeed cause more confusion than help. Not sure if it's worth another, bigger warning or removing them.

[ebirn]

It is in fact Slurm, and I think me paying closer attention at the documentation will fix the issue completely ;)
How you explain it, and what is written in the docs says it basically all. For completeness, it could make sense to mention in the docs that the max_jobs parameter can have influence on these numbers, as - reframe will make sure to have less than this amount of jobs submitted. (for our mem partition max_jobs=20 - this is something that could make sense to reduce on our end.)
Keeping this output concise while running the tests makes sense, but it wasn't obvious to me previously that these are the Reframe lifecycle phases - maybe adding some example output to that doc section would also help.

Ultimately, the same information is still in the logs, i.e.
[2022-02-10T11:59:11] verbose: reframe: ==> setup: 0.024s compile: 0.033s run: 1508.068s sanity: 0.012s performance: 0.029s total: 1508.158s
So de-cluttering the console output and removing it, might just be the simplest and best option.

[ekouts]

(for our mem partition max_jobs=20 - this is something that could make sense to reduce on our end.)

I probably wouldn't decrease the max_jobs further. I would only use these statistics to know in which ReFrame stage the test spends most of its time. I understand that this information is not too relevant for most users.

By decreasing the max jobs (and delaying the submission) the "run" time of the test is closer to the actual runtime of the job but by submitting early the jobs you will get a better job priority in a system that many users are submitting jobs simultaneously. Overall the run of ReFrame will be faster if the scheduler picks up your tests as soon as the node is available (instead of giving it to a different user).