perflogging timestamps with async policy

[brandongc]

All of the timestamps in perflogs are the same when tests are run with the async policy. Is it possible for the performance logging to be triggered closer to the completion time of each test? This complicates correlation with other sources with large or long running test suites.

1 2019-08-27T11:35:49.198249-07:00 gert01 ReFramePerf - - [nerscjson@42] {"reframeversion": "2.19-nersc", "name": "AllocSpeedTest_no", "jobid": 1546259, "env": "PrgEnv-cray", "partition": "haswell", "system": "gerty", "tags": "benchmarks", "var": "2MB", "val": 0.000522142, "unit": "seconds", "ref": 0.00389933, "lbound": -1, "ubound": 4}
1 2019-08-27T11:35:49.201164-07:00 gert01 ReFramePerf - - [nerscjson@42] {"reframeversion": "2.19-nersc", "name": "AllocSpeedTest_no", "jobid": 1546259, "env": "PrgEnv-cray", "partition": "haswell", "system": "gerty", "tags": "benchmarks", "var": "4MB", "val": 0.000434982, "unit": "seconds", "ref": 0.000519077, "lbound": -1, "ubound": 4}
1 2019-08-27T11:35:49.202126-07:00 gert01 ReFramePerf - - [nerscjson@42] {"reframeversion": "2.19-nersc", "name": "AllocSpeedTest_no", "jobid": 1546259, "env": "PrgEnv-cray", "partition": "haswell", "system": "gerty", "tags": "benchmarks", "var": "8MB", "val": 0.00112756, "unit": "seconds", "ref": 0.000557189, "lbound": -1, "ubound": 4}
1 2019-08-27T11:35:49.203101-07:00 gert01 ReFramePerf - - [nerscjson@42] {"reframeversion": "2.19-nersc", "name": "AllocSpeedTest_no", "jobid": 1546259, "env": "PrgEnv-cray", "partition": "haswell", "system": "gerty", "tags": "benchmarks", "var": "16MB", "val": 0.00204565, "unit": "seconds", "ref": 0.000976913, "lbound": -1, "ubound": 4}
1 2019-08-27T11:35:49.204043-07:00 gert01 ReFramePerf - - [nerscjson@42] {"reframeversion": "2.19-nersc", "name": "AllocSpeedTest_no", "jobid": 1546259, "env": "PrgEnv-cray", "partition": "haswell", "system": "gerty", "tags": "benchmarks", "var": "32MB", "val": 0.00385665, "unit": "seconds", "ref": 0.00172543, "lbound": -1, "ubound": 4}

[vkarak]

Hi @brandongc, by "completion time" you mean the job completion time, I guess. Is this right?

Currently, this log record is produced at the performance phase. In the serial policy, this is very close to the job completion, since tests are going through the pipeline at once. In the async policy, you don't know exactly when a test is going to be finalized and exit the pipeline. However, I think we can easily add such support, by adding a timestamp field in regression tests, that you could then use in your log formatting, such as %(check_completion_time)s.

[brandongc]

Sure a new timestamp that I could use in my log formatter would be sufficient.