RFR: 1552: Log relevant timer numbers

[Magnus Ihse Bursie]

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

>> This is a pretty big patch, but it shouldn't be too scary as it's only supposed to change logging, mainly by adding more logging (and also removing some now redundant log calls).
>> 
>> The main focus here is to add structured timing data to some log messages. To do this, I'm using the optional `parameters` `Object[]` that you can supply to the logger from `java.util.logging`. If the LogstashHandler finds a `Duration` instance in that array, it will add it as a "duration" field in the logstash log document. In the BotRunner, we were already using parameters for a different purpose, so it got a little bit messy, but I think it's ok.
>> 
>> There are two kinds of timings I'm adding logging for. The obvious one is timing external HTTP calls and running processes, as well as total running/pending/scheduled times for WorkItems and getPeriodicItems in the BotRunner. The other kind are more complex as I'm trying to measure the user perceived latency from when a PR or bug is updated to when the bot actually reacts with a response to that update. This is of course tricky to get right and needs to be carefully implemented for each instance, but I believe I have at least added some reasonably relevant approximations that will make sense to measure and track. To generate these, I had to introduce a new field in various WorkItems that stores the timestamp from the external change that triggered it (e.g. `prUpdatedAt`).
>> 
>> In addition to this, there are a ton more regular log messages, mostly on info level, that detail actions performed by various WorkItems. This is something I have been missing a lot when browsing logs.
>
> 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`.

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

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