[
https://issues.apache.org/jira/browse/OAK-7272?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Stefan Egli updated OAK-7272:
-----------------------------
Description:
Example for current logging:
{noformat}
*WARN* [DocumentNodeStore lease update thread (1)]
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore
BackgroundLeaseUpdate.execute: time since last renewClusterIdLease() call
longer than expected: 5338ms
{noformat}
Source:
{noformat}
@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();
}
{noformat}
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.
was:
Example for current logging:
{noformat}
*WARN* [DocumentNodeStore lease update thread (1)]
org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore
BackgroundLeaseUpdate.execute: time since last renewClusterIdLease() call
longer than expected: 5338ms
{noformat}
Source:
{noformat}
@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();
}
{noformat}
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)
[~egli], [~mreutegg] - feedback appreciated.
> improve BackgroundLeaseUpdate warning messages
> ----------------------------------------------
>
> Key: OAK-7272
> URL: https://issues.apache.org/jira/browse/OAK-7272
> Project: Jackrabbit Oak
> Issue Type: Task
> Components: documentmk
> Reporter: Julian Reschke
> Assignee: Julian Reschke
> Priority: Minor
> Labels: candidate_oak_1_4
> Fix For: 1.9.0, 1.10.0, 1.8.4, 1.6.13
>
> Attachments: OAK-7272.diff, OAK-7272.diff
>
>
> Example for current logging:
> {noformat}
> *WARN* [DocumentNodeStore lease update thread (1)]
> org.apache.jackrabbit.oak.plugins.document.DocumentNodeStore
> BackgroundLeaseUpdate.execute: time since last renewClusterIdLease() call
> longer than expected: 5338ms
> {noformat}
> Source:
> {noformat}
> @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();
> }
> {noformat}
> 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.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
