[OAK-7272] improve BackgroundLeaseUpdate warning messages

• Type: Task
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Fix Version/s: 1.9.0, 1.10.0, 1.8.4, 1.6.13, 1.4.25
• Component/s: documentmk
• Assignee: Julian Reschke
• Reporter: Julian Reschke
• Created: 15/Feb/18 12:50
• Updated: 02/Nov/19 17:40
• Resolved: 22/Feb/18 14:04

Description

Example for current logging:

*WARN* [DocumentNodeStore lease update thread (1)] org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore BackgroundLeaseUpdate.execute: time since last renewClusterIdLease() call longer than expected: 5338ms

Source:

        @Override
        protected void execute(@Nonnull DocumentNodeStore nodeStore) {
            // OAK-4859 : keep track of invocation time of renewClusterIdLease
            // and warn if time since last call is longer than 5sec
            final long now = System.currentTimeMillis();
            if (lastRenewClusterIdLeaseCall <= 0) {
                lastRenewClusterIdLeaseCall = now;
            } else {
                final long diff = now - lastRenewClusterIdLeaseCall;
                if (diff > 5000) {
                    LOG.warn("BackgroundLeaseUpdate.execute: time since last renewClusterIdLease() call longer than expected: {}ms", diff);
                }
                lastRenewClusterIdLeaseCall = now;
            }
            // first renew the clusterId lease
            nodeStore.renewClusterIdLease();
        }

Observations:

• the warning message doesn't actually say what the expected delay is
• we only log when it's exceeded by factor 5
• the threshold is hardwired; it should be computed based on the actual config (I think)

Also:

• we don't measure the time of the actual update operation, so we don't know whether it's a thread scheduling problem or a persistence problem (again, I think)

stefanegli, mreutegg - feedback appreciated.

Issue Links

• relates to: OAK-4859 Warn if lease update is invoked with large delay