Perf: Use autoclosures to prevent String construction

[djones6]

Change the Log functions to use @autoclosure, which automatically wraps the log message in a closure to delay evaluation of the String until we know the message will be logged.

Capture semantics

There is no change required to existing log messages, as the closure is implicitly non-escaping. For example, for an existing log message:

Log.info("Pool contains \(pool.count) items")

There is no requirement to add self. to the reference to pool here, as would be the case if the signature was @escaping @autoclosure.

Performance

This makes little difference when no logger is present, or at a conservative log level. At .verbose, it costs a little performance (around 1% for 'Hello World') as there is no saving (all messages are logged), but we pay for the creation of the closures.

Implementation | Avg Throughput | Max Throughput | Avg CPU | Avg RSS (kb) | Avg Lat (ms) | Max Lat (ms)
---------------|----------------|----------------|---------|--------------|--------------|--------------
          none |        51980.4 |       52931.65 |    99.4 |        19150 |          2.4 |       205.77
       none+ac |        52654.4 |       53927.23 |    99.5 |        19460 |          2.4 |       201.96
          warn |        52432.2 |       53510.81 |    99.5 |        21902 |          2.4 |       200.74
       warn+ac |        52356.6 |       53514.91 |    99.5 |        22949 |          2.4 |       205.86
       verbose |        44324.1 |       45819.22 |    91.8 |        25148 |          3.4 |       212.62
    verbose+ac |        43883.7 |       44930.28 |    91.5 |        25138 |          3.3 |       215.88

However, our current code contains few log messages overall, and those we do have are relatively cheap to construct. Making this change would enable us to add log messages in the future that are expensive to construct, but with no penalty unless the log level actually emits them.

As an example, here's what happens with an artificially expensive log message logged with Log.debug and a log level of .warn:

Implementation | Avg Throughput | Max Throughput | Avg CPU | Avg RSS (kb) | Avg Lat (ms) | Max Lat (ms)
---------------|----------------|----------------|---------|--------------|--------------|--------------
          warn |        17026.2 |       17072.40 |    84.8 |        22449 |          7.5 |        23.74
       warn+ac |        48378.6 |       49374.58 |    98.7 |        24766 |          2.6 |       203.75

Behaviour changes

This does not break the existing API, but it does introduce a subtle (intentional) difference in behaviour. Given the log statement:

Log.debug("There are \(countTheItems()) items")

Today, the function countTheItems() will be invoked regardless of whether the message is logged. With autoclosures, it will only be invoked if the message is logged. It may be worth documenting this, as it is non-obvious to the caller, and although it would be questionable to rely on side-effects of evaluating a log message, someone might trip over it.

[djones6]

I confirmed that autoclosures are implicitly non-escaping and there is no need to reference self. explicitly. There should be no impact to existing code, other than the behavioral change I described above (conditional evaluation).

[shmuelk]

Merging as David has proved it doesn't affect the API (i.e. doesn't require the user to add self.)