[feat] Add support for logging all performance variables to a single line

[stevenvdb]

This PR introduces log record attributes such as %(check_perf_all_values)s that will be filled in with a comma-separated list of values from all entries in perf_patterns. When the existing log record attributes such as %(check_perf_value)s are omitted, this changes the existing behavior that a separate line is logged for each entry in per_patterns.

Closes #1543

[jenkins-cscs]

Can I test this patch?

[codecov-io]

Codecov Report

Merging #1545 into master will increase coverage by 0.06%.
The diff coverage is 100.00%.

@@            Coverage Diff             @@
##           master    #1545      +/-   ##
==========================================
+ Coverage   87.90%   87.97%   +0.06%     
==========================================
  Files          43       43              
  Lines        6848     6862      +14     
==========================================
+ Hits         6020     6037      +17     
+ Misses        828      825       -3     

Impacted Files	Coverage Δ
reframe/core/pipeline.py	92.68% <100.00%> (+0.26%)	⬆️
reframe/core/exceptions.py	90.00% <0.00%> (-0.21%)	⬇️
reframe/core/logging.py	83.43% <0.00%> (-0.16%)	⬇️
reframe/core/environments.py	96.70% <0.00%> (-0.04%)	⬇️
reframe/frontend/cli.py	79.61% <0.00%> (ø)
reframe/utility/__init__.py	91.55% <0.00%> (ø)
reframe/utility/typecheck.py	94.54% <0.00%> (ø)
reframe/utility/os_ext.py
reframe/utility/json.py
reframe/utility/jsonext.py	91.66% <0.00%> (ø)
... and 1 more

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update be9de13...868e2c5. Read the comment docs.

[vkarak]

Hi @stevenvdb, thanks for your PR. Instead of having the different check_perf_all_* format specifiers, I was wondering wether it would make more sense to have a single one, say check_perf_data that would actually print all performance variables and values at once as key value pairs. Something like this:

perfX=valX[unitX],perfY=valY[unitY],...

We could even have check_perf_data_fmt (similarly to datefmt) that would allow users to explicitly specify the perf data format that they want based on the existing check_perf_* values. This will allow to even log check_perf_data as JSON:

'check_perf_data_fmt': '{"perfvar": %(check_perf_var)s, "value": %(check_perf_value)s, ...}'

[vkarak]

@stevenvdb After merging #1600 and #1644, we will no more need the check_perf_all variables you introduce here. You will now be able to use %(check_perf_patterns)s and this will log all the performance variables and values at once in JSON format. From this PR, we still need the part about creating a single log entry for the performance. If you are fine with I propose here, I can update the PR and schedule it for ReFrame 3.4.

[vkarak]

Also if you need a different formatting of the performance variables, you can define an arbitrary field in your test and log that always. In this case, we probably need to find another way to force logging of performance data to happen only once.

[stevenvdb]

@stevenvdb After merging #1600 and #1644, we will no more need the check_perf_all variables you introduce here. You will now be able to use %(check_perf_patterns)s and this will log all the performance variables and values at once in JSON format. From this PR, we still need the part about creating a single log entry for the performance. If you are fine with I propose here, I can update the PR and schedule it for ReFrame 3.4.

Your proposition sounds good, the %(check_perf_patterns)s is nicer than what I did. What do you think is the best way to trigger the single log entry on or off? You could set it based on the presence of %(check_perf_patterns)s or let the user specify it explicitly in the configuration file.

[vkarak]

@stevenvdb Sorry for getting back to you late. I was quite busy and then I can't figure out which is the best way to handle this :-) First of all, I think that the logic of whether to iterate or not over the performance variables should be moved inside the log_performance() function in core/logging.py. The signature of this function would need to be updated, too, so that it simply takes the evaluated perf_patterns. It's then the logger that will decide whether to do log each performance variable separately or not. The question is how this behaviour is controlled. Doing this automatically and having the logger inspecting its handlers for this, hmm, it may be convenient for the user, but implementation-wise breaks encapsulation and separation of concerns and I am a bit skeptical about it. Having a configuration variable that controls this, it's much cleaner from the implementation point of view, but that would require the users to remember to set this configuration parameter if they're using %(check_perf_patterns)s in their format string, which can be error-prone. If you have any suggestions, I'm more than happy to hear them.

[vkarak]

Hi @stevenvdb, #1816 allows you also to log all the references in a single line, so now you can have %(check_perf_patterns)s and %(check_reference)s to get everything in a single line. You will still have redundant lines, but there is no need to join them anymore. If you don't mind, I will close this PR, but keep #1543 open and schedule it for the next major release. The reason for this is that it's probably better to drop altogether the log_performance() function and the redundant lines, but this is a breaking change, so it should be scheduled for 4.0. Meanwhile, I think that you can use the format specifiers I just mentioned to achieve what you want. Let me know if that fits you.

[stevenvdb]

Hi @stevenvdb, #1816 allows you also to log all the references in a single line, so now you can have %(check_perf_patterns)s and %(check_reference)s to get everything in a single line. You will still have redundant lines, but there is no need to join them anymore. If you don't mind, I will close this PR, but keep #1543 open and schedule it for the next major release. The reason for this is that it's probably better to drop altogether the log_performance() function and the redundant lines, but this is a breaking change, so it should be scheduled for 4.0. Meanwhile, I think that you can use the format specifiers I just mentioned to achieve what you want. Let me know if that fits you.

Hi @vkarak,

That sounds look a good solution to me, thanks. I will close this PR.