RFR: 1552: Log relevant timer numbers

[Erik Joelsson]

On Tue, 30 Aug 2022 14:53:35 GMT, Magnus Ihse Bursie <ihse at openjdk.org> wrote:

>> bots/pr/src/main/java/org/openjdk/skara/bots/pr/CheckWorkItem.java line 360:
>> 
>>> 358:                 if (log.isLoggable(Level.INFO)) {
>>> 359:                     var updatedPr = bot.repo().pullRequest(prId);
>>> 360:                     logLatency("Time from PR updated to CheckRun done ", updatedPr.updatedAt(), log);
>> 
>> logLatency only logs at INFO level anyway. I'm not sure why you put just this one instance inside the log.isLoggable guard.
>
> Actually, I'm trying to understand why this is correct. `logLatency` looks like this:
> 
>     protected void logLatency(String message, ZonedDateTime endTime, Logger log) {
>         var latency = Duration.between(prUpdatedAt, endTime);
> ...
> 
> 
> I would have expected the endTime to be the current time. But maybe I'm just getting lost here on the difference between `updatedPr.updatedAt()` and `prUpdatedAt`.

We basically always log INFO so the guard isn't strictly necessary. Even so I tried to put guards whenever I needed to fetch data from a remote to generate the log message. In this case, it's refetching the PullRequest from the forge.

I should add a comment about this to make it clearer. Whenever possible, I want the latency numbers to be calculated between timestamps from the same clock. In this case the clock is on the forge (e.g. GitHub). The start time is the updatedAt timestamp read from the PR when we triggered this WorkItem. The endTime is the updatedAt from the PR just now, after we updated it from this WorkItem (CheckRun.execute() will always update the `check` in the PR).

-------------

PR: https://git.openjdk.org/skara/pull/1361