Author: reschke
Date: Tue Jul 24 05:28:07 2018
New Revision: 1836528
URL: http://svn.apache.org/viewvc?rev=1836528&view=rev
Log:
OAK-7272: improve BackgroundLeaseUpdate warning messages (ported to 1.6)
Modified:
jackrabbit/oak/branches/1.6/oak-core/ (props changed)
jackrabbit/oak/branches/1.6/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
Propchange: jackrabbit/oak/branches/1.6/oak-core/
------------------------------------------------------------------------------
--- svn:mergeinfo (original)
+++ svn:mergeinfo Tue Jul 24 05:28:07 2018
@@ -2,5 +2,5 @@
/jackrabbit/oak/trunk:1834823
/jackrabbit/oak/trunk/oak-blob-plugins:1819950
/jackrabbit/oak/trunk/oak-core:1781068,1781075,1781248,1781386,1781846,1781907,1782000,1782029,1782196,1782447,1782476,1782770,1782945,1782966,1782973,1782990,1783061,1783066,1783089,1783104-1783105,1783110,1783619,1783720,1783731,1783733,1783738,1783742,1783773,1783855,1783891,1784023,1784034,1784130,1784162,1784251,1784401,1784551,1784574,1784689,1785095,1785108,1785283,1785652,1785838,1785917,1785919,1785946,1786122,1787074,1787145,1787151,1787217,1787425,1788056,1788378,1788387-1788389,1788463,1788476,1788850,1789056,1789441,1789534,1789925,1789940,1789987,1790006,1790013,1790069,1790077,1790079,1790382,1792049,1792463,1792742,1792746,1793013,1793088,1793618,1793627,1793644,1794393,1794417,1794683,1795138,1795314,1795330,1795475,1795488,1795491,1795502,1795594,1795613,1795618,1796144,1796230,1796239,1796274,1796278,1796988,1797378,1798035,1798832,1798834,1799219,1799389,1799393,1799861,1799924,1800269,1800606,1800613,1800974,1801011,1801013,1801118-1801119,1801675,1802260,180226
2,1802286,1802548,1802905,1802934,1802938,1802973,1803026,1803247-1803249,1803951,1803953-1803955,1804437,1805851-1805852,1806668,1807308,1807688,1808125,1808128,1808142,1808240,1808246,1809024,1809026,1809131,1809163,1809178-1809179,1809253,1809255-1809256,1811380,1811952,1811963,1811986,1814332,1818645,1821325,1821358,1821516,1830160
-/jackrabbit/oak/trunk/oak-store-document:1809866,1811575,1811702,1811709,1811823,1811835,1811931,1812739,1812750,1812753,1814407,1814499,1814579,1815450,1815466,1815940,1816436,1817379,1817772,1818301,1818303,1818903,1818906,1819421,1820199,1820661,1821130,1821477,1821487,1823163,1823169,1824962,1825442,1825470,1834610,1834823
+/jackrabbit/oak/trunk/oak-store-document:1809866,1811575,1811702,1811709,1811823,1811835,1811931,1812739,1812750,1812753,1814407,1814499,1814579,1815450,1815466,1815940,1816436,1817379,1817772,1818301,1818303,1818903,1818906,1819421,1820199,1820661,1821130,1821477,1821487,1823163,1823169,1824962,1825065,1825442,1825470,1834610,1834823
/jackrabbit/trunk/oak-core:1345480
Modified:
jackrabbit/oak/branches/1.6/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
URL:
http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.6/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java?rev=1836528&r1=1836527&r2=1836528&view=diff
==============================================================================
---
jackrabbit/oak/branches/1.6/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
(original)
+++
jackrabbit/oak/branches/1.6/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/document/DocumentNodeStore.java
Tue Jul 24 05:28:07 2018
@@ -2941,27 +2941,38 @@ public final class DocumentNodeStore
/** OAK-4859 : log if time between two renewClusterIdLease calls is
too long **/
private long lastRenewClusterIdLeaseCall = -1;
+ /** elapsed time for previous update operation **/
+ private long elapsedForPreviousRenewal = -1;
+
+ private static int INTERVAL_MS = 1000;
+ private static int TOLERANCE_FOR_WARNING_MS = 2000;
+
BackgroundLeaseUpdate(DocumentNodeStore nodeStore,
AtomicBoolean isDisposed) {
- super(nodeStore, isDisposed, Suppliers.ofInstance(1000));
+ super(nodeStore, isDisposed, Suppliers.ofInstance(INTERVAL_MS));
}
@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 {
+ Clock clock = nodeStore.getClock();
+ long now = clock.getTime();
+
+ if (lastRenewClusterIdLeaseCall >= 0) {
final long diff = now - lastRenewClusterIdLeaseCall;
- if (diff > 5000) {
- LOG.warn("BackgroundLeaseUpdate.execute: time since last
renewClusterIdLease() call longer than expected: {}ms", diff);
+ if (diff > INTERVAL_MS + TOLERANCE_FOR_WARNING_MS) {
+ String renewTimeMessage = elapsedForPreviousRenewal <= 0 ?
""
+ : String.format(" (of which the last update
operation took %dms)", elapsedForPreviousRenewal);
+ LOG.warn(
+ "BackgroundLeaseUpdate.execute: time since last
renewClusterIdLease() call longer than expected: {}ms{} (expected ~{}ms)",
+ diff, renewTimeMessage, INTERVAL_MS);
}
- lastRenewClusterIdLeaseCall = now;
}
- // first renew the clusterId lease
+ lastRenewClusterIdLeaseCall = now;
+
nodeStore.renewClusterIdLease();
+ elapsedForPreviousRenewal = clock.getTime() - now;
}
}
