GitHub Actions Timestamps: Not for the current line?

Does anyone know if the timestamps in the GitHub Actions logs are added before or after the current line is finished processing?

We are trying to track down a slowdown in our tests. I know it’s happening here:

Wed, 13 Jan 2021 15:41:27 GMT test_GLOA_8PP_force_NLP (pyomo.contrib.gdpopt.tests.test_gdpopt.TestGLOA) ... SKIP: Global NLP solver license not available.
Wed, 13 Jan 2021 15:41:27 GMT test_GLOA_constrained_layout_default_init (pyomo.contrib.gdpopt.tests.test_gdpopt.TestGLOA) ... SKIP: Global NLP solver license not available.
Wed, 13 Jan 2021 15:49:49 GMT test_GLOA_disjunctive_bounds (pyomo.contrib.gdpopt.tests.test_gdpopt.TestGLOA) ... ok
Wed, 13 Jan 2021 15:49:50 GMT test_GLOA_ex_633_trespalacios (pyomo.contrib.gdpopt.tests.test_gdpopt.TestGLOA) ... ok

The timestamps make it look like the line test_GLOA_constrained_layout_default_init is taking 8 minutes to process, but we think it is unlikely that it is taking 8 minutes to skip a test (specifically because other tests are skipped for the same reason and take fractions of a second). We think it’s more likely that the test immediately proceeding (test_GLOA_disjunctive_bounds (pyomo.contrib.gdpopt.tests.test_gdpopt.TestGLOA)) is taking 8 minutes.

Does anyone have any insight into the timestamps?

:wave: Hey @mrmundt,

Timestamps in log lines are added when that line is printed to the runner/stdout.
So ultimately it will depend on what that individual process is doing, does it run a test and then output the result or output first and then start the test?

I’d recommend trying it out locally to see the behavior for the tool you’re using.