You are viewing a plain text version of this content. The canonical link for it is here.
Posted to oak-commits@jackrabbit.apache.org by ca...@apache.org on 2016/07/12 13:26:14 UTC
svn commit: r1752290 - in /jackrabbit/oak/branches/1.2: ./
oak-core/src/main/java/org/apache/jackrabbit/oak/util/
oak-core/src/test/java/org/apache/jackrabbit/oak/util/
Author: catholicon
Date: Tue Jul 12 13:26:14 2016
New Revision: 1752290
URL: http://svn.apache.org/viewvc?rev=1752290&view=rev
Log:
OAK-4542: Implement startForInfo and add end() methods to provide info threshold (backport r1752273 and r1752274 from trunk)
Added tests for existing functionality and more for new methods.
Added:
jackrabbit/oak/branches/1.2/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java
- copied, changed from r1752273, jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java
Modified:
jackrabbit/oak/branches/1.2/ (props changed)
jackrabbit/oak/branches/1.2/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
jackrabbit/oak/branches/1.2/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerTest.java
Propchange: jackrabbit/oak/branches/1.2/
------------------------------------------------------------------------------
--- svn:mergeinfo (original)
+++ svn:mergeinfo Tue Jul 12 13:26:14 2016
@@ -1,4 +1,4 @@
/jackrabbit/oak/branches/1.0:1665962
/jackrabbit/oak/branches/1.4:1745750,1747354,1750078,1750512
-/jackrabbit/oak/trunk:1672350,1672468,1672537,1672603,1672611,1672642,1672644,1672834-1672835,1673351,1673410,1673414-1673415,1673436,1673644,1673662-1673664,1673669,1673695,1673713,1673738,1673787,1673791,1674046,1674065,1674075,1674107,1674228,1674780,1674880,1675054-1675055,1675319,1675332,1675354,1675357,1675382,1675555,1675566,1675593,1676198,1676237,1676407,1676458,1676539,1676670,1676693,1676703,1676725,1677579,1677581,1677609,1677611,1677774,1677788,1677797,1677804,1677806,1677939,1677991,1678023,1678095-1678096,1678124,1678171,1678173,1678202,1678211,1678323,1678758,1678938,1678954,1679144,1679165,1679191,1679232,1679235,1679503,1679958,1679961,1680170,1680172,1680182,1680222,1680232,1680236,1680461,1680633,1680643,1680747,1680805-1680806,1680903,1681282,1681767,1681918,1681921,1681955,1682042,1682218,1682235,1682437,1682488,1682494,1682555,1682855,1682904,1683059,1683089,1683213,1683249,1683259,1683278,1683323,1683687,1683700,1684174-1684175,1684186,1684376,1684442,1684561
,1684570,1684601,1684618,1684669,1684820,1684868,1684894,1685023,1685075,1685370,1685541,1685552,1685589-1685590,1685840,1685964,1685977,1685989,1685999,1686003,1686023,1686032,1686097,1686162,1686229,1686234,1686253,1686414,1686772,1686780,1686790,1686854,1686857,1686971,1687053-1687055,1687175,1687196,1687198,1687220,1687239-1687240,1687301,1687441,1687553,1688089-1688090,1688172,1688179,1688349,1688421,1688436,1688453,1688616,1688622,1688634,1688636,1688817,1689003-1689004,1689008,1689577,1689581,1689623,1689810,1689828,1689831,1689833,1689903,1690017,1690043,1690047,1690057,1690247,1690249,1690634-1690637,1690650,1690657,1690669,1690672,1690674,1690885,1690941,1691139,1691151,1691159,1691167,1691183,1691188,1691201,1691210,1691217-1691218,1691280,1691307,1691331-1691333,1691345,1691384-1691385,1691394,1691401,1691498,1691509,1692133-1692134,1692156,1692250,1692272,1692274,1692363,1692382,1692393,1692478,1692955,1693002,1693030,1693050,1693209,1693401,1693421,1693525-1693526,1694
007,1694393-1694394,1694651,1694653-1694654,1695032,1695050,1695122,1695280,1695299,1695420,1695457,1695482,1695492,1695507,1695521,1695540,1695571,1695829-1695830,1695905,1696190,1696194,1696242,1696285,1696375,1696522,1696578,1696759,1696916,1697363,1697373,1697383,1697410,1697582,1697589,1697616,1697672,1697896,1698096,1698144,1700191,1700231,1700397,1700403,1700506,1700571,1700709,1700718,1700720,1700727,1700749,1700769,1700775,1701065,1701613,1701619,1701733,1701743,1701750,1701768,1701806,1701810,1701814,1701907,1701948,1701955,1701959,1701965,1701986,1702014,1702022,1702045,1702051,1702241,1702272,1702371,1702387,1702405,1702423,1702426,1702428,1702860,1702866,1702942,1702960,1703212,1703382,1703395,1703411,1703428,1703430,1703568,1703592,1703758,1703858,1703878,1704256,1704282,1704285,1704457,1704479,1704490,1704614,1704629,1704636,1704655,1704670,1704886,1705005,1705027,1705043,1705055,1705250,1705268,1705273,1705323,1705677,1705701,1705871,1705992,1705998,1706009,1706037,1
706059,1706212,1706218,1706270,1706764,1706772,1707049,1707189,1707191,1707331,1707435,1707509,1707753,1708049,1708105,1708307,1708315,1708401,1708546,1708592,1708766,1709012,1709852,1709978,1710013,1710031,1710049,1710205,1710242,1710559,1710575,1710590,1710614,1710637,1710789,1710800,1710811,1710816,1710972,1711248,1711282,1711296,1711405,1711498,1711654,1712018,1712042,1712319,1712490,1712531,1712730,1712785,1712963,1713008,1713439,1713461,1713580,1713586,1713599-1713600,1713626,1713698,1713803,1713809,1714034,1714061,1714084,1714170,1714213,1714229,1714238,1714519-1714520,1714543-1714544,1714730,1714739,1714779,1714956,1714961,1715010,1715092,1715191,1715346,1715716,1715767,1715771,1715888,1715898,1716100,1716178,1716426,1716576,1716588-1716589,1716596,1716616,1716703,1716712,1716815,1716823,1716830,1716883,1717203,1717277,1717393-1717394,1717410,1717462,1717632,1717768-1717769,1717784,1717789,1717988,1718528,1718533,1718547-1718548,1718626,1718646,1718772,1718801-1718802,171889
5,1719111,1719288,1719869,1720306,1720335,1720350,1720354,1720500,1721160,1721172,1721337,1722141,1722832,1723227,1723239,1723241,1723251,1723254,1723333,1723347,1723350,1723565,1723584,1723713,1723731,1724026,1724057,1724186,1724210,1724401,1724628,1724631,1725216,1725477,1725515,1725555,1725895,1725899,1725935,1725941,1725960,1726232,1726237,1726570,1726579,1726585-1726586,1726621,1726795,1726797,1726809,1726812,1726981,1726993,1727026,1727254,1727331,1727350,1727358,1727429,1727476,1727483,1727508,1727515-1727518,1727813,1727816,1727831-1727832,1727841,1727893,1727895,1727912-1727913,1727923,1727991,1728037,1728041,1728070,1728114,1728281,1728443,1728525,1728642,1729200,1729505,1729599,1729957,1729979,1730216,1730527,1730581,1730629,1730801,1731627,1731647-1731648,1731789,1731797,1732131,1732268,1732278,1732330,1732647-1732648,1732864,1733615,1733929,1734230,1734254,1735052,1735405,1735484,1735588,1736176,1737309-1737310,1737334,1737349,1738833,1738950,1738957,1739894,1740116,174
0626,1740971,1741032,1741339,1741343,1742520,1742888,1742916,1743097,1743172,1743343,1744265,1744959,1745038,1745197,1746117,1746696,1746981,1747341-1747342,1747492,1748505,1748553,1748722,1748870,1749350,1749464,1749475,1749645,1749662,1749815,1749872,1749875,1749899,1750076-1750077,1750287,1750457,1750465,1750495,1750626,1750809,1751410,1751478,1751755
+/jackrabbit/oak/trunk:1672350,1672468,1672537,1672603,1672611,1672642,1672644,1672834-1672835,1673351,1673410,1673414-1673415,1673436,1673644,1673662-1673664,1673669,1673695,1673713,1673738,1673787,1673791,1674046,1674065,1674075,1674107,1674228,1674780,1674880,1675054-1675055,1675319,1675332,1675354,1675357,1675382,1675555,1675566,1675593,1676198,1676237,1676407,1676458,1676539,1676670,1676693,1676703,1676725,1677579,1677581,1677609,1677611,1677774,1677788,1677797,1677804,1677806,1677939,1677991,1678023,1678095-1678096,1678124,1678171,1678173,1678202,1678211,1678323,1678758,1678938,1678954,1679144,1679165,1679191,1679232,1679235,1679503,1679958,1679961,1680170,1680172,1680182,1680222,1680232,1680236,1680461,1680633,1680643,1680747,1680805-1680806,1680903,1681282,1681767,1681918,1681921,1681955,1682042,1682218,1682235,1682437,1682488,1682494,1682555,1682855,1682904,1683059,1683089,1683213,1683249,1683259,1683278,1683323,1683687,1683700,1684174-1684175,1684186,1684376,1684442,1684561
,1684570,1684601,1684618,1684669,1684820,1684868,1684894,1685023,1685075,1685370,1685541,1685552,1685589-1685590,1685840,1685964,1685977,1685989,1685999,1686003,1686023,1686032,1686097,1686162,1686229,1686234,1686253,1686414,1686772,1686780,1686790,1686854,1686857,1686971,1687053-1687055,1687175,1687196,1687198,1687220,1687239-1687240,1687301,1687441,1687553,1688089-1688090,1688172,1688179,1688349,1688421,1688436,1688453,1688616,1688622,1688634,1688636,1688817,1689003-1689004,1689008,1689577,1689581,1689623,1689810,1689828,1689831,1689833,1689903,1690017,1690043,1690047,1690057,1690247,1690249,1690634-1690637,1690650,1690657,1690669,1690672,1690674,1690885,1690941,1691139,1691151,1691159,1691167,1691183,1691188,1691201,1691210,1691217-1691218,1691280,1691307,1691331-1691333,1691345,1691384-1691385,1691394,1691401,1691498,1691509,1692133-1692134,1692156,1692250,1692272,1692274,1692363,1692382,1692393,1692478,1692955,1693002,1693030,1693050,1693209,1693401,1693421,1693525-1693526,1694
007,1694393-1694394,1694651,1694653-1694654,1695032,1695050,1695122,1695280,1695299,1695420,1695457,1695482,1695492,1695507,1695521,1695540,1695571,1695829-1695830,1695905,1696190,1696194,1696242,1696285,1696375,1696522,1696578,1696759,1696916,1697363,1697373,1697383,1697410,1697582,1697589,1697616,1697672,1697896,1698096,1698144,1700191,1700231,1700397,1700403,1700506,1700571,1700709,1700718,1700720,1700727,1700749,1700769,1700775,1701065,1701613,1701619,1701733,1701743,1701750,1701768,1701806,1701810,1701814,1701907,1701948,1701955,1701959,1701965,1701986,1702014,1702022,1702045,1702051,1702241,1702272,1702371,1702387,1702405,1702423,1702426,1702428,1702860,1702866,1702942,1702960,1703212,1703382,1703395,1703411,1703428,1703430,1703568,1703592,1703758,1703858,1703878,1704256,1704282,1704285,1704457,1704479,1704490,1704614,1704629,1704636,1704655,1704670,1704886,1705005,1705027,1705043,1705055,1705250,1705268,1705273,1705323,1705677,1705701,1705871,1705992,1705998,1706009,1706037,1
706059,1706212,1706218,1706270,1706764,1706772,1707049,1707189,1707191,1707331,1707435,1707509,1707753,1708049,1708105,1708307,1708315,1708401,1708546,1708592,1708766,1709012,1709852,1709978,1710013,1710031,1710049,1710205,1710242,1710559,1710575,1710590,1710614,1710637,1710789,1710800,1710811,1710816,1710972,1711248,1711282,1711296,1711405,1711498,1711654,1712018,1712042,1712319,1712490,1712531,1712730,1712785,1712963,1713008,1713439,1713461,1713580,1713586,1713599-1713600,1713626,1713698,1713803,1713809,1714034,1714061,1714084,1714170,1714213,1714229,1714238,1714519-1714520,1714543-1714544,1714730,1714739,1714779,1714956,1714961,1715010,1715092,1715191,1715346,1715716,1715767,1715771,1715888,1715898,1716100,1716178,1716426,1716576,1716588-1716589,1716596,1716616,1716703,1716712,1716815,1716823,1716830,1716883,1717203,1717277,1717393-1717394,1717410,1717462,1717632,1717768-1717769,1717784,1717789,1717988,1718528,1718533,1718547-1718548,1718626,1718646,1718772,1718801-1718802,171889
5,1719111,1719288,1719869,1720306,1720335,1720350,1720354,1720500,1721160,1721172,1721337,1722141,1722832,1723227,1723239,1723241,1723251,1723254,1723333,1723347,1723350,1723565,1723584,1723713,1723731,1724026,1724057,1724186,1724210,1724401,1724628,1724631,1725216,1725477,1725515,1725555,1725895,1725899,1725935,1725941,1725960,1726232,1726237,1726570,1726579,1726585-1726586,1726621,1726795,1726797,1726809,1726812,1726981,1726993,1727026,1727254,1727331,1727350,1727358,1727429,1727476,1727483,1727508,1727515-1727518,1727813,1727816,1727831-1727832,1727841,1727893,1727895,1727912-1727913,1727923,1727991,1728037,1728041,1728070,1728114,1728281,1728443,1728525,1728642,1729200,1729505,1729599,1729957,1729979,1730216,1730527,1730581,1730629,1730801,1731627,1731647-1731648,1731789,1731797,1732131,1732268,1732278,1732330,1732647-1732648,1732864,1733615,1733929,1734230,1734254,1735052,1735405,1735484,1735588,1736176,1737309-1737310,1737334,1737349,1738833,1738950,1738957,1739894,1740116,174
0626,1740971,1741032,1741339,1741343,1742520,1742888,1742916,1743097,1743172,1743343,1744265,1744959,1745038,1745197,1746117,1746696,1746981,1747341-1747342,1747492,1748505,1748553,1748722,1748870,1749350,1749464,1749475,1749645,1749662,1749815,1749872,1749875,1749899,1750076-1750077,1750287,1750457,1750465,1750495,1750626,1750809,1751410,1751478,1751755,1752273-1752274
/jackrabbit/trunk:1345480
Modified: jackrabbit/oak/branches/1.2/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.2/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java?rev=1752290&r1=1752289&r2=1752290&view=diff
==============================================================================
--- jackrabbit/oak/branches/1.2/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java (original)
+++ jackrabbit/oak/branches/1.2/oak-core/src/main/java/org/apache/jackrabbit/oak/util/PerfLogger.java Tue Jul 12 13:26:14 2016
@@ -57,32 +57,57 @@ public final class PerfLogger {
}
/**
- * Returns quickly if log level is not DEBUG or TRACE - otherwise just
- * returns the current time in millis.
- *
- * @return the current time if level is DEBUG or TRACE, -1 otherwise
+ * Shortcut to {@code #start(null, false)}
*/
public final long start() {
- if (!delegate.isDebugEnabled()) {
- // if log level is not at least DEBUG, then return fast, no-op
+ if (canExitEarly()) {
+ return -1;
+ }
+ return start(null, false);
+ }
+
+ /**
+ * Shortcut to {@code start(null, true)}
+ */
+ public final long startForInfoLog() {
+ if (canExitEarly(true)) {
+ return -1;
+ }
+ return start(null, true);
+ }
+
+ /**
+ * Shortcut to {@code start(traceMsgOrNull, false)}
+ */
+ public final long start(String traceMsgOrNull) {
+ if (canExitEarly()) {
return -1;
}
- return start(null);
+ return start(traceMsgOrNull, false);
+ }
+
+ /**
+ * Shortcut to {@code start(traceMsgOrNull, true)}
+ */
+ public final long startForInfoLog(String traceMsgOrNull) {
+ if (canExitEarly(true)) {
+ return -1;
+ }
+ return start(traceMsgOrNull, true);
}
/**
* Returns quickly if log level is not DEBUG or TRACE - if it is DEBUG, then
* just returns the current time in millis, if it is TRACE, then log the
* given message and also return the current time in millis.
- *
+ *
* @param traceMsgOrNull
* the message to log if log level is TRACE - or null if no
* message should be logged (even on TRACE level)
* @return the current time if level is DEBUG or TRACE, -1 otherwise
*/
- public final long start(String traceMsgOrNull) {
- if (!delegate.isDebugEnabled()) {
- // if log level is not at least DEBUG, then return fast, no-op
+ private long start(String traceMsgOrNull, boolean logAtInfoToo) {
+ if (canExitEarly(logAtInfoToo)) {
return -1;
}
if (traceMsgOrNull != null && delegate.isTraceEnabled()) {
@@ -92,70 +117,89 @@ public final class PerfLogger {
}
/**
- * Returns quickly if log level is not DEBUG or TRACE - if it is DEBUG
- * and the difference between now and the provided 'start' is bigger (slower)
- * than 'logAtDebugIfSlowerThanMs', then a log.debug is emitted, if at
- * TRACE then a log.trace is always emitted (independent of time measured).
- * <p>
+ * See {@link #end(long, long, long, String, Object...)}
* Note that this method exists for performance optimization only (compared
* to the other end() method with a vararg.
- * @param start the start time with which 'now' should be compared
- * @param logAtDebugIfSlowerThanMs the number of milliseconds that must
- * be surpassed to issue a log.debug (if log level is DEBUG)
- * @param logMessagePrefix the log message 'prefix' - to which the given
- * argument will be passed, plus the measured time difference in the format
- * '[took x ms']
- * @param arg1 the argument which is to be passed to the log statement
*/
public final void end(long start, long logAtDebugIfSlowerThanMs,
String logMessagePrefix, Object arg1) {
if (start < 0) {
return;
}
- end(start, logAtDebugIfSlowerThanMs, logMessagePrefix,
+ end(start, logAtDebugIfSlowerThanMs, Long.MAX_VALUE, logMessagePrefix,
new Object[] { arg1 });
}
/**
- * Returns quickly if log level is not DEBUG or TRACE - if it is DEBUG
- * and the difference between now and the provided 'start' is bigger (slower)
- * than 'logAtDebugIfSlowerThanMs', then a log.debug is emitted, if at
- * TRACE then a log.trace is always emitted (independent of time measured).
- * <p>
+ * See {@link #end(long, long, long, String, Object...)}
* Note that this method exists for performance optimization only (compared
* to the other end() method with a vararg.
- * @param start the start time with which 'now' should be compared
- * @param logAtDebugIfSlowerThanMs the number of milliseconds that must
- * be surpassed to issue a log.debug (if log level is DEBUG)
- * @param logMessagePrefix the log message 'prefix' - to which the given
- * arguments will be passed, plus the measured time difference in the format
- * '[took x ms']
- * @param arg1 the first argument which is to be passed to the log statement
- * @param arg2 the second argument which is to be passed to the log statement
*/
public final void end(long start, long logAtDebugIfSlowerThanMs,
String logMessagePrefix, Object arg1, Object arg2) {
if (start < 0) {
return;
}
- end(start, logAtDebugIfSlowerThanMs, logMessagePrefix, new Object[] {
- arg1, arg2 });
+ end(start, logAtDebugIfSlowerThanMs, Long.MAX_VALUE, logMessagePrefix,
+ new Object[] { arg1, arg2 });
}
/**
- * Returns quickly if log level is not DEBUG or TRACE - if it is DEBUG
- * and the difference between now and the provided 'start' is bigger (slower)
- * than 'logAtDebugIfSlowerThanMs', then a log.debug is emitted, if at
- * TRACE then a log.trace is always emitted (independent of time measured).
+ * Shortcut to {@link #end(long, long, long, String, Object...)} for
+ * {@code logMessagePrefix} = {@link Long#MAX_VALUE}
+ */
+ public void end(long start, long logAtDebugIfSlowerThanMs,
+ String logMessagePrefix, Object... arguments) {
+ end(start, logAtDebugIfSlowerThanMs, Long.MAX_VALUE, logMessagePrefix, arguments);
+ }
+
+ /**
+ * See {@link #end(long, long, long, String, Object...)}
+ * Note that this method exists for performance optimization only (compared
+ * to the other end() method with a vararg.
+ */
+ public final void end(long start, long logAtDebugIfSlowerThanMs, long logAtInfoIfSlowerThanMs,
+ String logMessagePrefix, Object arg1) {
+ if (start < 0) {
+ return;
+ }
+ end(start, logAtDebugIfSlowerThanMs, logAtInfoIfSlowerThanMs, logMessagePrefix,
+ new Object[] { arg1 });
+ }
+
+ /**
+ * See {@link #end(long, long, long, String, Object...)}
+ * Note that this method exists for performance optimization only (compared
+ * to the other end() method with a vararg.
+ */
+ public final void end(long start, long logAtDebugIfSlowerThanMs, long logAtInfoIfSlowerThanMs,
+ String logMessagePrefix, Object arg1, Object arg2) {
+ if (start < 0) {
+ return;
+ }
+ end(start, logAtDebugIfSlowerThanMs, logAtInfoIfSlowerThanMs, logMessagePrefix,
+ new Object[] { arg1, arg2 });
+ }
+
+ /**
+ * Returns quickly if start is negative (which is the case according to log level
+ * at the time of {@link #start()} or {@link #startForInfoLog()}).
+ * If log level is set to TRACE, log.trace is always emitted.
+ * If log level is set to DEBUG, then log.debug is emitted if 'now' is bigger (slower)
+ * than {@code start} by at least {@code logAtDebugIfSlowerThanMs}.
+ * If log level is set to INFO, then long.info is emitted if 'now' is bigger (slower)
+ * than {@code start} by at least {@code logAtInfoIfSlowerThanMs}.
* @param start the start time with which 'now' should be compared
* @param logAtDebugIfSlowerThanMs the number of milliseconds that must
* be surpassed to issue a log.debug (if log level is DEBUG)
+ * @param logAtInfoIfSlowerThanMs the number of milliseconds that must
+ * be surpassed to issue a log.info (if log level is DEBUG)
* @param logMessagePrefix the log message 'prefix' - to which the given
* arguments will be passed, plus the measured time difference in the format
* '[took x ms']
* @param arguments the arguments which is to be passed to the log statement
*/
- public void end(long start, long logAtDebugIfSlowerThanMs,
+ public void end(long start, long logAtDebugIfSlowerThanMs, long logAtInfoIfSlowerThanMs,
String logMessagePrefix, Object... arguments) {
if (start < 0) {
// if start is negative, we assume that start() returned -1 because the log level is above DEBUG
@@ -163,22 +207,57 @@ public final class PerfLogger {
}
final long diff = System.currentTimeMillis() - start;
- if (delegate.isTraceEnabled()) {
+ if (isTraceEnabled()) {
// if log level is TRACE, then always log - and do that on TRACE
// then:
delegate.trace(logMessagePrefix + " [took " + diff + "ms]",
(Object[]) arguments);
- } else if ((logAtDebugIfSlowerThanMs < 0)
- || (diff > logAtDebugIfSlowerThanMs)) {
+ } else if ( ( logAtDebugIfSlowerThanMs < 0 || diff > logAtDebugIfSlowerThanMs )
+ && isDebugEnabled()) {
// otherwise (log level is DEBUG) only log if
// logDebugIfSlowerThanMs is set to -1 (or negative)
// OR the measured diff is larger than logDebugIfSlowerThanMs -
// and then do that on DEBUG:
delegate.debug(logMessagePrefix + " [took " + diff + "ms]",
(Object[]) arguments);
+ } else if ( logAtInfoIfSlowerThanMs < 0 || diff > logAtInfoIfSlowerThanMs ) {
+ // otherwise (log level is INFO) only log if
+ // logAtInfoIfSlowerThanMs is set to -1 (or negative)
+ // OR the measured diff is larger than logAtInfoIfSlowerThanMs -
+ // and then do that on INFO:
+ delegate.info(logMessagePrefix + " [took " + diff + "ms]",
+ (Object[]) arguments);
}
}
+ /**
+ * @return same as {@code canExitEarly(false)}
+ */
+ private boolean canExitEarly() {
+ return canExitEarly(false);
+ }
+
+ /**
+ * Whether early exit is OK?
+ *
+ * @param logAtInfoToo We want to log at INFO level too
+ * @return {@code true} if log level not even at INFO
+ * or log level is not at least DEBUG as well as {@code logAtInfoToo} is false too
+ * ; false otherwise
+ */
+ private boolean canExitEarly(boolean logAtInfoToo) {
+ if (!logAtInfoToo) {
+ return !isDebugEnabled();
+ } else {
+ return !isInfoEnabled();
+ }
+ }
+
+ /** Whether or not the delegate has log level INFO configured **/
+ public final boolean isInfoEnabled() {
+ return delegate.isInfoEnabled();
+ }
+
/** Whether or not the delegate has log level DEBUG configured **/
public final boolean isDebugEnabled() {
return delegate.isDebugEnabled();
Copied: jackrabbit/oak/branches/1.2/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java (from r1752273, jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java)
URL: http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.2/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java?p2=jackrabbit/oak/branches/1.2/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java&p1=jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java&r1=1752273&r2=1752290&rev=1752290&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java (original)
+++ jackrabbit/oak/branches/1.2/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerIT.java Tue Jul 12 13:26:14 2016
@@ -1,116 +1,156 @@
-/*
- * Licensed to the Apache Software Foundation (ASF) under one or more
- * contributor license agreements. See the NOTICE file distributed with
- * this work for additional information regarding copyright ownership.
- * The ASF licenses this file to You under the Apache License, Version 2.0
- * (the "License"); you may not use this file except in compliance with
- * the License. You may obtain a copy of the License at
- *
- * http://www.apache.org/licenses/LICENSE-2.0
- *
- * Unless required by applicable law or agreed to in writing, software
- * distributed under the License is distributed on an "AS IS" BASIS,
- * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
- * See the License for the specific language governing permissions and
- * limitations under the License.
- */
-package org.apache.jackrabbit.oak.util;
-
-import org.junit.Before;
-import org.junit.Test;
-import org.mockito.Mock;
-import org.mockito.MockitoAnnotations;
-import org.slf4j.Logger;
-
-import static org.mockito.Matchers.any;
-import static org.mockito.Matchers.anyString;
-import static org.mockito.Mockito.times;
-import static org.mockito.Mockito.verify;
-import static org.mockito.Mockito.verifyNoMoreInteractions;
-import static org.mockito.Mockito.when;
-
-public class PerfLoggerIT {
- @Mock
- Logger logger;
-
- private PerfLogger perfLogger;
-
- @Before
- public void setup() {
- MockitoAnnotations.initMocks(this);
- when(logger.isTraceEnabled()).thenReturn(false);
- when(logger.isDebugEnabled()).thenReturn(false);
- when(logger.isInfoEnabled()).thenReturn(false);
-
- perfLogger = new PerfLogger(logger);
- }
-
- //test for logger set at DEBUG
- @Test
- public void logAtDebugTimeoutNotHit() {
- setupDebugLogger();
-
- long start = perfLogger.start();
- perfLogger.end(start, 100, "message", "argument");
-
- verifyTraceInteractions(1, false, false);
- verifyDebugInteractions(2, false);
- verifyNoMoreInteractions(logger);
- }
-
- @Test
- public void logAtDebugTimeoutHit() throws InterruptedException {
- setupDebugLogger();
-
- long start = perfLogger.start();
- Thread.sleep(100);
- perfLogger.end(start, 20, "message", "argument");
-
- verifyTraceInteractions(1, false, false);
- verifyDebugInteractions(2, true);
- verifyNoMoreInteractions(logger);
- }
- //end DEBUG tests
-
-
- //test for logger set at INFO
- @Test
- public void logAtInfoDebugTimeoutHit() throws InterruptedException {
- setupInfoLogger();
-
- long start = perfLogger.start();
- Thread.sleep(100);
- perfLogger.end(start, 20, "message", "argument");
-
- verifyDebugInteractions(1, false);
- verifyNoMoreInteractions(logger);
- }
- //end INFO tests
-
- private void setupDebugLogger() {
- when(logger.isDebugEnabled()).thenReturn(true);
- setupInfoLogger();
- }
- private void setupInfoLogger() {
- when(logger.isInfoEnabled()).thenReturn(true);
- }
-
- private void verifyTraceInteractions(int enabled, boolean shouldLogStart, boolean shouldLogEnd) {
- verify(logger, times(enabled)).isTraceEnabled();
-
- if (shouldLogStart) {
- verify(logger, times(1)).trace(anyString());
- }
- if (shouldLogEnd) {
- verify(logger, times(1)).trace(anyString(), any(Object[].class));
- }
- }
-
- private void verifyDebugInteractions(int enabled, boolean shouldLog) {
- verify(logger, times(enabled)).isDebugEnabled();
-
- if (shouldLog) {
- verify(logger, times(1)).debug(anyString(), any(Object[].class));
- }
- }
-}
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.jackrabbit.oak.util;
+
+import org.junit.Before;
+import org.junit.Test;
+import org.mockito.Mock;
+import org.mockito.MockitoAnnotations;
+import org.slf4j.Logger;
+
+import static org.mockito.Matchers.any;
+import static org.mockito.Matchers.anyString;
+import static org.mockito.Mockito.times;
+import static org.mockito.Mockito.verify;
+import static org.mockito.Mockito.verifyNoMoreInteractions;
+import static org.mockito.Mockito.when;
+
+/**
+ * Timing tests for {@link PerfLogger} using {@code Thread.sleep} because
+ * virtual clock requires currentTimeMillis (OAK-3877)
+ */
+public class PerfLoggerIT {
+ @Mock
+ Logger logger;
+
+ private PerfLogger perfLogger;
+
+ @Before
+ public void setup() {
+ MockitoAnnotations.initMocks(this);
+ when(logger.isTraceEnabled()).thenReturn(false);
+ when(logger.isDebugEnabled()).thenReturn(false);
+ when(logger.isInfoEnabled()).thenReturn(false);
+
+ perfLogger = new PerfLogger(logger);
+ }
+
+ //test for logger set at DEBUG
+ @Test
+ public void logAtDebugTimeoutNotHit() {
+ setupDebugLogger();
+
+ long start = perfLogger.start();
+ perfLogger.end(start, 100, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtDebugTimeoutHit() throws InterruptedException {
+ setupDebugLogger();
+
+ long start = perfLogger.start();
+ Thread.sleep(100);
+ perfLogger.end(start, 20, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(3, true);
+ verifyNoMoreInteractions(logger);
+ }
+ //end DEBUG tests
+
+
+ //test for logger set at INFO
+ @Test
+ public void logAtInfoDebugTimeoutHit() throws InterruptedException {
+ setupInfoLogger();
+
+ long start = perfLogger.start();
+ Thread.sleep(100);
+ perfLogger.end(start, 20, "message", "argument");
+
+ verifyDebugInteractions(1, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtInfoInfoTimeoutNotHit() throws InterruptedException {
+ setupInfoLogger();
+
+ long start = perfLogger.startForInfoLog();
+ Thread.sleep(100);
+ perfLogger.end(start, 20, 500, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(1, false);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtInfoInfoTimeoutHit() throws InterruptedException {
+ setupInfoLogger();
+
+ long start = perfLogger.startForInfoLog();
+ Thread.sleep(100);
+ perfLogger.end(start, 20, 50, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(1, false);
+ verifyInfoInteractions(2, true);
+ verifyNoMoreInteractions(logger);
+ }
+ //end INFO tests
+
+ private void setupDebugLogger() {
+ when(logger.isDebugEnabled()).thenReturn(true);
+ setupInfoLogger();
+ }
+ private void setupInfoLogger() {
+ when(logger.isInfoEnabled()).thenReturn(true);
+ }
+
+ private void verifyTraceInteractions(int enabled, boolean shouldLogStart, boolean shouldLogEnd) {
+ verify(logger, times(enabled)).isTraceEnabled();
+
+ if (shouldLogStart) {
+ verify(logger, times(1)).trace(anyString());
+ }
+ if (shouldLogEnd) {
+ verify(logger, times(1)).trace(anyString(), any(Object[].class));
+ }
+ }
+
+ private void verifyDebugInteractions(int enabled, boolean shouldLog) {
+ verify(logger, times(enabled)).isDebugEnabled();
+
+ if (shouldLog) {
+ verify(logger, times(1)).debug(anyString(), any(Object[].class));
+ }
+ }
+
+ private void verifyInfoInteractions(int enabled, boolean shouldLog) {
+ verify(logger, times(enabled)).isInfoEnabled();
+
+ if (shouldLog) {
+ verify(logger, times(1)).info(anyString(), any(Object[].class));
+ }
+ }
+}
Modified: jackrabbit/oak/branches/1.2/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerTest.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.2/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerTest.java?rev=1752290&r1=1752289&r2=1752290&view=diff
==============================================================================
--- jackrabbit/oak/branches/1.2/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerTest.java (original)
+++ jackrabbit/oak/branches/1.2/oak-core/src/test/java/org/apache/jackrabbit/oak/util/PerfLoggerTest.java Tue Jul 12 13:26:14 2016
@@ -16,50 +16,224 @@
*/
package org.apache.jackrabbit.oak.util;
+import org.junit.Before;
import org.junit.Test;
-import org.mockito.Mockito;
+import org.mockito.Mock;
+import org.mockito.MockitoAnnotations;
import org.slf4j.Logger;
import static org.mockito.Matchers.any;
import static org.mockito.Matchers.anyString;
-import static org.mockito.Mockito.atLeastOnce;
-import static org.mockito.Mockito.never;
import static org.mockito.Mockito.times;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.verifyNoMoreInteractions;
import static org.mockito.Mockito.when;
public class PerfLoggerTest {
+ @Mock
+ Logger logger;
- @Test
- public void testEndDebug() {
- Logger logger = Mockito.mock(Logger.class);
+ private PerfLogger perfLogger;
+
+ @Before
+ public void setup() {
+ MockitoAnnotations.initMocks(this);
when(logger.isTraceEnabled()).thenReturn(false);
- when(logger.isDebugEnabled()).thenReturn(true);
+ when(logger.isDebugEnabled()).thenReturn(false);
+ when(logger.isInfoEnabled()).thenReturn(false);
+
+ perfLogger = new PerfLogger(logger);
+ }
+
+ //test for logger set at TRACE
+ @Test
+ public void logAtTraceSimpleStart() {
+ setupTraceLogger();
- PerfLogger perfLogger = new PerfLogger(logger);
long start = perfLogger.start();
perfLogger.end(start, -1, "message", "argument");
- verify(logger, atLeastOnce()).isTraceEnabled();
- verify(logger, atLeastOnce()).isDebugEnabled();
- verify(logger, times(1)).debug(anyString(), any(Object[].class));
+ verifyTraceInteractions(1, false, true);
+ verifyDebugInteractions(2, false);
verifyNoMoreInteractions(logger);
}
@Test
- public void testEndSkipsIsDebugEnabled() {
- Logger logger = Mockito.mock(Logger.class);
- when(logger.isTraceEnabled()).thenReturn(false);
- when(logger.isDebugEnabled()).thenReturn(false);
+ public void logAtTraceMessageStart() {
+ setupTraceLogger();
+
+ long start = perfLogger.start("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(2, true, true);
+ verifyDebugInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtTraceSimpleStartWithInfoLog() {
+ setupTraceLogger();
+
+ long start = perfLogger.startForInfoLog();
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(1, false, true);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtTraceMessageStartWithInfoLog() {
+ setupTraceLogger();
+
+ long start = perfLogger.startForInfoLog("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(2, true, true);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+ //end TRACE tests
+
+ //test for logger set at DEBUG
+ @Test
+ public void logAtDebugSimpleStart() {
+ setupDebugLogger();
- PerfLogger perfLogger = new PerfLogger(logger);
long start = perfLogger.start();
perfLogger.end(start, -1, "message", "argument");
- verify(logger, never()).isTraceEnabled();
- verify(logger, times(1)).isDebugEnabled();
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(3, true);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtDebugMessageStart() {
+ setupDebugLogger();
+
+ long start = perfLogger.start("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(2, false, false);
+ verifyDebugInteractions(3, true);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtDebugSimpleStartWithInfoLog() {
+ setupDebugLogger();
+
+ long start = perfLogger.startForInfoLog();
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(1, true);
+ verifyInfoInteractions(2, false);
verifyNoMoreInteractions(logger);
}
+ @Test
+ public void logAtDebugMessageStartWithInfoLog() {
+ setupDebugLogger();
+
+ long start = perfLogger.startForInfoLog("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(2, false, false);
+ verifyDebugInteractions(1, true);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+ //end DEBUG tests
+
+ //test for logger set at INFO
+ @Test
+ public void logAtInfoSimpleStart() {
+ setupInfoLogger();
+
+ long start = perfLogger.start();
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyDebugInteractions(1, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtInfoMessageStart() {
+ setupInfoLogger();
+
+ long start = perfLogger.start("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyDebugInteractions(1, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtInfoSimpleStartWithInfoLog() {
+ setupInfoLogger();
+
+ long start = perfLogger.startForInfoLog();
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(1, false, false);
+ verifyDebugInteractions(1, false);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+
+ @Test
+ public void logAtInfoMessageStartWithInfoLog() {
+ setupInfoLogger();
+
+ long start = perfLogger.startForInfoLog("Start message");
+ perfLogger.end(start, -1, "message", "argument");
+
+ verifyTraceInteractions(2, false, false);
+ verifyDebugInteractions(1, false);
+ verifyInfoInteractions(2, false);
+ verifyNoMoreInteractions(logger);
+ }
+ //end INFO tests
+
+ private void setupTraceLogger() {
+ when(logger.isTraceEnabled()).thenReturn(true);
+ setupDebugLogger();
+ }
+ private void setupDebugLogger() {
+ when(logger.isDebugEnabled()).thenReturn(true);
+ setupInfoLogger();
+ }
+ private void setupInfoLogger() {
+ when(logger.isInfoEnabled()).thenReturn(true);
+ }
+
+ private void verifyTraceInteractions(int enabled, boolean shouldLogStart, boolean shouldLogEnd) {
+ verify(logger, times(enabled)).isTraceEnabled();
+
+ if (shouldLogStart) {
+ verify(logger, times(1)).trace(anyString());
+ }
+ if (shouldLogEnd) {
+ verify(logger, times(1)).trace(anyString(), any(Object[].class));
+ }
+ }
+
+ private void verifyDebugInteractions(int enabled, boolean shouldLog) {
+ verify(logger, times(enabled)).isDebugEnabled();
+
+ if (shouldLog) {
+ verify(logger, times(1)).debug(anyString(), any(Object[].class));
+ }
+ }
+
+ private void verifyInfoInteractions(int enabled, boolean shouldLog) {
+ verify(logger, times(enabled)).isInfoEnabled();
+
+ if (shouldLog) {
+ verify(logger, times(1)).info(anyString(), any(Object[].class));
+ }
+ }
+
}