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 re...@apache.org on 2019/02/13 15:19:38 UTC
svn commit: r1853514 - in /jackrabbit/oak/branches/1.8: ./
oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/
oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/rdb/
Author: reschke
Date: Wed Feb 13 15:19:38 2019
New Revision: 1853514
URL: http://svn.apache.org/viewvc?rev=1853514&view=rev
Log:
OAK-7894: RDBDocumentStore: add perf logging for JDBC read operations (ported to 1.8)
Modified:
jackrabbit/oak/branches/1.8/ (props changed)
jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreJDBC.java
jackrabbit/oak/branches/1.8/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreTest.java
Propchange: jackrabbit/oak/branches/1.8/
------------------------------------------------------------------------------
--- svn:mergeinfo (original)
+++ svn:mergeinfo Wed Feb 13 15:19:38 2019
@@ -1,3 +1,3 @@
/jackrabbit/oak/branches/1.0:1665962
-/jackrabbit/oak/trunk:1820660-1820661,1820729,1820734,1820859,1820861,1820878,1820888,1820947,1821027,1821130,1821140-1821141,1821178,1821237,1821240,1821249,1821258,1821325,1821358,1821361-1821362,1821370,1821375,1821393,1821477,1821487,1821516,1821617,1821663,1821665,1821668,1821681,1821847,1821975-1821983,1822121,1822201,1822207,1822527,1822642,1822723,1822808,1822850,1822934,1823135,1823163,1823169,1823172,1823655,1823669,1824196,1824198,1824253,1824255,1824896,1824962,1825065,1825362,1825381,1825442,1825448,1825466,1825470-1825471,1825475,1825523,1825525,1825561,1825619-1825621,1825651,1825654,1825992,1826079,1826090,1826096,1826216,1826237,1826338,1826516,1826532,1826551,1826560,1826638,1826640,1826730,1826833,1826932,1826957,1827423,1827472,1827486,1827816,1827977,1828349,1828439,1828502,1828529,1828948,1829527,1829534,1829546,1829569,1829587,1829665,1829854,1829864,1829978,1829985,1829987,1829998,1830019,1830048,1830160,1830171,1830197,1830209,1830239,1830347,1830748,1830911
,1830923,1831157-1831158,1831163,1831190,1831374,1831560,1831689,1832258,1832376,1832379,1832535,1833308,1833347,1833833,1834112,1834117,1834287,1834291,1834302,1834326,1834328,1834336,1834428,1834468,1834483,1834610,1834648-1834649,1834681,1834823,1834857-1834858,1835060,1835518,1835521,1835635,1835642,1835780,1835819,1836082,1836121,1836167-1836168,1836170-1836187,1836189-1836196,1836206,1836487,1836493,1836548,1837057,1837274,1837296,1837326,1837475,1837503,1837547,1837569,1837600,1837657,1837718,1837998,1838076,1838637,1839549,1839570,1839637,1839746,1840019,1840024,1840031,1840226,1840455,1840462,1840574,1840769,1841314,1841352,1842089,1842677,1843175,1843222,1843231,1843398,1843618,1843652,1843911,1844325,1844549,1844625,1844627,1844642,1844728,1844775,1844932,1845135,1845336,1845405,1845415,1845730-1845731,1845863,1845865,1846057,1846396,1846617,1848073,1848181-1848182,1848191,1848217,1848822-1848823,1850837,1851533-1851535,1851619,1852120,1852451,1852492,1853393,1853433
+/jackrabbit/oak/trunk:1820660-1820661,1820729,1820734,1820859,1820861,1820878,1820888,1820947,1821027,1821130,1821140-1821141,1821178,1821237,1821240,1821249,1821258,1821325,1821358,1821361-1821362,1821370,1821375,1821393,1821477,1821487,1821516,1821617,1821663,1821665,1821668,1821681,1821847,1821975-1821983,1822121,1822201,1822207,1822527,1822642,1822723,1822808,1822850,1822934,1823135,1823163,1823169,1823172,1823655,1823669,1824196,1824198,1824253,1824255,1824896,1824962,1825065,1825362,1825381,1825442,1825448,1825466,1825470-1825471,1825475,1825523,1825525,1825561,1825619-1825621,1825651,1825654,1825992,1826079,1826090,1826096,1826216,1826237,1826338,1826516,1826532,1826551,1826560,1826638,1826640,1826730,1826833,1826932,1826957,1827423,1827472,1827486,1827816,1827977,1828349,1828439,1828502,1828529,1828948,1829527,1829534,1829546,1829569,1829587,1829665,1829854,1829864,1829978,1829985,1829987,1829998,1830019,1830048,1830160,1830171,1830197,1830209,1830239,1830347,1830748,1830911
,1830923,1831157-1831158,1831163,1831190,1831374,1831560,1831689,1832258,1832376,1832379,1832535,1833308,1833347,1833833,1834112,1834117,1834287,1834291,1834302,1834326,1834328,1834336,1834428,1834468,1834483,1834610,1834648-1834649,1834681,1834823,1834857-1834858,1835060,1835518,1835521,1835635,1835642,1835780,1835819,1836082,1836121,1836167-1836168,1836170-1836187,1836189-1836196,1836206,1836487,1836493,1836548,1837057,1837274,1837296,1837326,1837475,1837503,1837547,1837569,1837600,1837657,1837718,1837998,1838076,1838637,1839549,1839570,1839637,1839746,1840019,1840024,1840031,1840226,1840455,1840462,1840574,1840769,1841314,1841352,1842089,1842677,1843175,1843222,1843231,1843398,1843618,1843652,1843911,1844325,1844549,1844625,1844627,1844642,1844728,1844775,1844932,1845135,1845336,1845405,1845415,1845730-1845731,1845863,1845865,1846057,1846396,1846429,1846617,1848073,1848181-1848182,1848191,1848217,1848822-1848823,1850837,1851533-1851535,1851619,1852120,1852451,1852492,1853393,1853
433
/jackrabbit/trunk:1345480
Modified: jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreJDBC.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreJDBC.java?rev=1853514&r1=1853513&r2=1853514&view=diff
==============================================================================
--- jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreJDBC.java (original)
+++ jackrabbit/oak/branches/1.8/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreJDBC.java Wed Feb 13 15:19:38 2019
@@ -46,6 +46,7 @@ import java.util.Map.Entry;
import java.util.NoSuchElementException;
import java.util.Set;
+import org.apache.jackrabbit.oak.commons.PerfLogger;
import org.apache.jackrabbit.oak.plugins.document.Document;
import org.apache.jackrabbit.oak.plugins.document.DocumentStoreException;
import org.apache.jackrabbit.oak.plugins.document.NodeDocument;
@@ -68,6 +69,8 @@ import com.google.common.collect.Lists;
public class RDBDocumentStoreJDBC {
private static final Logger LOG = LoggerFactory.getLogger(RDBDocumentStoreJDBC.class);
+ private static final PerfLogger PERFLOG = new PerfLogger(
+ LoggerFactory.getLogger(RDBDocumentStoreJDBC.class.getName() + ".perf"));
private static final String COLLISIONSMODCOUNT = RDBDocumentStore.COLLISIONSMODCOUNT;
private static final String MODCOUNT = NodeDocument.MOD_COUNT;
@@ -428,6 +431,10 @@ public class RDBDocumentStoreJDBC {
}
ResultSet rs = null;
try {
+ long pstart = PERFLOG.start(PERFLOG.isDebugEnabled()
+ ? ("querying: table=" + tmd.getName() + ", minId=" + minId + ", maxId=" + maxId + ", excludeKeyPatterns="
+ + excludeKeyPatterns + ", conditions=" + conditions + ", limit=" + limit)
+ : null);
stmt = prepareQuery(connection, tmd, fields, minId,
maxId, excludeKeyPatterns, conditions, limit, "ID");
rs = stmt.executeQuery();
@@ -453,6 +460,8 @@ public class RDBDocumentStoreJDBC {
sdMaxRevTime, data, bdata));
dataTotal += data.length();
bdataTotal += bdata == null ? 0 : bdata.length;
+ PERFLOG.end(pstart, 10, "queried: table={} -> id={}, modcount={}, modified={}, data={}, bdata={}", tmd.getName(), id,
+ modcount, modified, (data == null ? 0 : data.length()), (bdata == null ? 0 : bdata.length));
}
} finally {
closeStatement(stmt);
@@ -538,6 +547,7 @@ public class RDBDocumentStoreJDBC {
private long elapsed = 0;
private String message = null;
private long cnt = 0;
+ private long pstart;
public ResultSetIterator(RDBConnectionHandler ch, RDBTableMetaData tmd, String minId, String maxId,
List<String> excludeKeyPatterns, List<QueryCondition> conditions, int limit, String sortBy) throws SQLException {
@@ -562,6 +572,10 @@ public class RDBDocumentStoreJDBC {
if (LOG.isDebugEnabled()) {
callstack = new Exception("call stack");
}
+ pstart = PERFLOG.start(PERFLOG.isDebugEnabled()
+ ? ("querying: table=" + tmd.getName() + ", minId=" + minId + ", maxId=" + maxId + ", excludeKeyPatterns="
+ + excludeKeyPatterns + ", conditions=" + conditions + ", limit=" + limit + ", sortBy=" + sortBy)
+ : null);
} finally {
this.elapsed += (System.currentTimeMillis() - start);
}
@@ -605,6 +619,9 @@ public class RDBDocumentStoreJDBC {
long sdMaxRevTime = tmd.hasSplitDocs() ? readLongFromResultSet(rs, field++) : RDBRow.LONG_UNSET;
String data = this.rs.getString(field++);
byte[] bdata = this.rs.getBytes(field++);
+ PERFLOG.end(pstart, 10, "queried: table={} -> id={}, modcount={}, modified={}, data={}, bdata={}",
+ tmd.getName(), id, modcount, modified, (data == null ? 0 : data.length()),
+ (bdata == null ? 0 : bdata.length));
return new RDBRow(id, hasBinary, deletedOnce, modified, modcount, cmodcount, schemaVersion, sdType,
sdMaxRevTime, data, bdata);
} else {
@@ -719,6 +736,8 @@ public class RDBDocumentStoreJDBC {
List<RDBRow> rows = new ArrayList<RDBRow>();
for (List<String> keys : Iterables.partition(allKeys, RDBJDBCTools.MAX_IN_CLAUSE)) {
+ long pstart = PERFLOG.start(PERFLOG.isDebugEnabled() ? ("reading: " + keys) : null);
+
PreparedStatementComponent inClause = RDBJDBCTools.createInStatement("ID", keys, tmd.isIdBinary());
StringBuilder query = new StringBuilder();
if (tmd.hasSplitDocs()) {
@@ -754,9 +773,13 @@ public class RDBDocumentStoreJDBC {
RDBRow row = new RDBRow(id, hasBinary, deletedOnce, modified, modcount, cmodcount, schemaVersion, sdType,
sdMaxRevTime, data, bdata);
rows.add(row);
+ PERFLOG.end(pstart, 10, "read: table={}, id={} -> modcount={}, modified={}, data={}, bdata={}", tmd.getName(), id,
+ modcount, modified, (data == null ? 0 : data.length()), (bdata == null ? 0 : bdata.length));
}
} catch (SQLException ex) {
LOG.debug("attempting to read " + keys, ex);
+ PERFLOG.end(pstart, 10, "read: table={} -> exception={}", tmd.getName(), ex.getMessage());
+
// DB2 throws an SQLException for invalid keys; handle this more
// gracefully
if ("22001".equals(ex.getSQLState())) {
@@ -780,6 +803,8 @@ public class RDBDocumentStoreJDBC {
@Nullable
public RDBRow read(Connection connection, RDBTableMetaData tmd, String id, long lastmodcount, long lastmodified) throws SQLException {
+ long pstart = PERFLOG.start();
+
boolean useCaseStatement = lastmodcount != -1 && lastmodified >= 1;
StringBuffer sql = new StringBuffer();
String fields;
@@ -829,13 +854,22 @@ public class RDBDocumentStoreJDBC {
long sdMaxRevTime = tmd.hasSplitDocs() ? readLongFromResultSet(rs, field++) : RDBRow.LONG_UNSET;
String data = rs.getString(field++);
byte[] bdata = rs.getBytes(field++);
+ PERFLOG.end(pstart, 10,
+ "read: table={}, id={}, lastmodcount={}, lastmodified={} -> modcount={}, modified={}, data={}, bdata={}",
+ tmd.getName(), id, lastmodcount, lastmodified, modcount, modified, (data == null ? 0 : data.length()),
+ (bdata == null ? 0 : bdata.length));
return new RDBRow(id, hasBinary, deletedOnce, modified, modcount, cmodcount, schemaVersion, sdType, sdMaxRevTime,
data, bdata);
} else {
+ PERFLOG.end(pstart, 10, "read: table={}, id={}, lastmodcount={}, lastmodified={} -> not found", tmd.getName(), id,
+ lastmodcount, lastmodified);
return null;
}
} catch (SQLException ex) {
LOG.debug("attempting to read " + id + " (id length is " + id.length() + ")", ex);
+ PERFLOG.end(pstart, 10, "read: table={}, id={}, lastmodcount={}, lastmodified={} -> exception={}", tmd.getName(), id,
+ lastmodcount, lastmodified, ex.getMessage());
+
// DB2 throws an SQLException for invalid keys; handle this more
// gracefully
if ("22001".equals(ex.getSQLState())) {
Modified: jackrabbit/oak/branches/1.8/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreTest.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/branches/1.8/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreTest.java?rev=1853514&r1=1853513&r2=1853514&view=diff
==============================================================================
--- jackrabbit/oak/branches/1.8/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreTest.java (original)
+++ jackrabbit/oak/branches/1.8/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBDocumentStoreTest.java Wed Feb 13 15:19:38 2019
@@ -28,6 +28,7 @@ import java.util.Collections;
import java.util.List;
import java.util.Map;
+import org.apache.jackrabbit.oak.commons.junit.LogCustomizer;
import org.apache.jackrabbit.oak.plugins.document.AbstractDocumentStoreTest;
import org.apache.jackrabbit.oak.plugins.document.Collection;
import org.apache.jackrabbit.oak.plugins.document.DocumentStoreFixture;
@@ -36,6 +37,7 @@ import org.apache.jackrabbit.oak.plugins
import org.apache.jackrabbit.oak.plugins.document.rdb.RDBDocumentStore.QueryCondition;
import org.apache.jackrabbit.oak.plugins.document.util.Utils;
import org.junit.Test;
+import org.slf4j.event.Level;
public class RDBDocumentStoreTest extends AbstractDocumentStoreTest {
@@ -137,4 +139,47 @@ public class RDBDocumentStoreTest extend
// info.forEach((k, v) -> System.err.println(k +": " + v));
}
}
+
+ @Test
+ public void testRDBJDBCPerfLog() {
+ if (ds instanceof RDBDocumentStore) {
+ LogCustomizer logCustomizerRead = LogCustomizer.forLogger(RDBDocumentStoreJDBC.class.getName() + ".perf")
+ .enable(Level.TRACE).matchesRegex("read: .*").create();
+ logCustomizerRead.starting();
+ LogCustomizer logCustomizerQuery = LogCustomizer.forLogger(RDBDocumentStoreJDBC.class.getName() + ".perf")
+ .enable(Level.TRACE).matchesRegex("quer.*").create();
+ logCustomizerQuery.starting();
+
+ try {
+ String id1 = Utils.getIdFromPath("/testRDBJDBCPerfLog");
+ String id2 = Utils.getIdFromPath("/testRDBJDBCPerfLog/foo");
+ UpdateOp up1 = new UpdateOp(id1, true);
+ up1.set(NodeDocument.MODIFIED_IN_SECS, 12345L);
+ super.removeMe.add(id1);
+ super.ds.create(Collection.NODES, Collections.singletonList(up1));
+ super.ds.invalidateCache();
+ super.ds.find(Collection.NODES, id1);
+ int count = logCustomizerRead.getLogs().size();
+ assertTrue(count > 0);
+ super.ds.find(Collection.NODES, id1);
+ assertEquals("no new log entry expected but got: " + logCustomizerRead.getLogs(), count,
+ logCustomizerRead.getLogs().size());
+ count = logCustomizerRead.getLogs().size();
+
+ // add a child node
+ UpdateOp up2 = new UpdateOp(id2, true);
+ up1.set(NodeDocument.MODIFIED_IN_SECS, 12346L);
+ super.removeMe.add(id2);
+ super.ds.create(Collection.NODES, Collections.singletonList(up2));
+
+ // query
+ List<NodeDocument> results = super.ds.query(Collection.NODES, Utils.getKeyLowerLimit("/testRDBJDBCPerfLog"), Utils.getKeyUpperLimit("/testRDBJDBCPerfLog"), 10);
+ assertEquals(1, results.size());
+ assertEquals(2, logCustomizerQuery.getLogs().size());
+ } finally {
+ logCustomizerRead.finished();
+ logCustomizerQuery.finished();
+ }
+ }
+ }
}