Configure Logging operations in Logback auto scan

365 Views Asked by At

Logback Documentation says, auto scan works in conjuction with logging Operations i.e.

the check whether the scan period has elapsed or not, is too costly in itself. In order to improve performance, ReconfigureOnChangeFilter is in reality "alive" only once every N logging operations. Depending on how often your application logs, the value of N can be modified on the fly by logback. By default N is 16, although it can go as high as 2^16 (= 65536) for CPU-intensive applications.

is there any way to configure the value of 'N' in your xml OR by any other means.

1

There are 1 best solutions below

1
On BEST ANSWER

A quick look at the source code (logback 1.1.3) inside the ch.qos.logback.classic.turbo.ReconfigureOnChangeFilter class reveals the following:

The starting value of N is hardcoded as can be seen here:

  private volatile long mask = 0xF;

Short of changing the source code and recompiling a change to this constant yourself, the code doesn't provide any sort of configuration option to change this.

How the mask variable is used can be seen in this snippet of code:

// for performance reasons, skip change detection (MASK-1) times out of MASK.
// Only once every MASK calls is change detection code executed
// Note that MASK is a variable itself.
if (((invocationCounter++) & mask) != mask) {
  return FilterReply.NEUTRAL;
}

However, as the documentation suggests, this mask (or N) value is adjusted dynamically by logback as it feels that it needs to in order to maintain decent performance.

The documentation only talks about an upward adjustment of the value of N when it feels it needs it. But the code shows that it will also dynamically adjust the value downwards when it feels that the value of N is too high.

Notice the following code which determines how it dynamically adjusts the value of N:

  // experiments indicate that even for CPU intensive applications with 200 or more threads MASK
  // values in the order of 0xFFFF is appropriate
  private static final int MAX_MASK = 0xFFFF;


  // if less  than MASK_INCREASE_THRESHOLD milliseconds elapse between invocations of updateMaskIfNecessary() method,
  // then the mask should be increased
  private static final long MASK_INCREASE_THRESHOLD = 100;

  // if more than MASK_DECREASE_THRESHOLD milliseconds elapse between invocations of updateMaskIfNecessary() method,
  // then the mask should be decreased
  private static final long MASK_DECREASE_THRESHOLD = MASK_INCREASE_THRESHOLD*8;

  // update the mask so as to execute change detection code about once every 100 to 8000 milliseconds.
  private void updateMaskIfNecessary(long now) {
    final long timeElapsedSinceLastMaskUpdateCheck = now - lastMaskCheck;
    lastMaskCheck = now;
    if (timeElapsedSinceLastMaskUpdateCheck < MASK_INCREASE_THRESHOLD && (mask < MAX_MASK)) {
        mask = (mask << 1) | 1;
    } else if (timeElapsedSinceLastMaskUpdateCheck > MASK_DECREASE_THRESHOLD) {
      mask = mask >>> 2;
    }
  }

That last condition is saying that, if the last check was performed more than 800 ms ago, then the value of N is too high, and needs to be adjusted down.

Assuming you don't have very frequent logs, then you can expect that eventually the value of mask will be brought down to 0, change detection will no longer get skipped, and it will actually start honoring your scan period configuration as you would expect.