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/03/22 13:13:02 UTC
svn commit: r1856049 - in /jackrabbit/oak/trunk/oak-store-document/src:
main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBBlobStore.java
test/java/org/apache/jackrabbit/oak/plugins/document/blob/RDBBlobStoreTest.java
Author: reschke
Date: Fri Mar 22 13:13:02 2019
New Revision: 1856049
URL: http://svn.apache.org/viewvc?rev=1856049&view=rev
Log:
OAK-8147: RDBBlobStore: add perf logging for JDBC read operations
Modified:
jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBBlobStore.java
jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/blob/RDBBlobStoreTest.java
Modified: jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBBlobStore.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBBlobStore.java?rev=1856049&r1=1856048&r2=1856049&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBBlobStore.java (original)
+++ jackrabbit/oak/trunk/oak-store-document/src/main/java/org/apache/jackrabbit/oak/plugins/document/rdb/RDBBlobStore.java Fri Mar 22 13:13:02 2019
@@ -41,6 +41,7 @@ import java.util.concurrent.TimeUnit;
import javax.sql.DataSource;
+import org.apache.jackrabbit.oak.commons.PerfLogger;
import org.apache.jackrabbit.oak.commons.StringUtils;
import org.apache.jackrabbit.oak.plugins.blob.CachingBlobStore;
import org.apache.jackrabbit.oak.plugins.document.DocumentStoreException;
@@ -121,6 +122,8 @@ public class RDBBlobStore extends Cachin
}
private static final Logger LOG = LoggerFactory.getLogger(RDBBlobStore.class);
+ private static final PerfLogger PERFLOG = new PerfLogger(
+ LoggerFactory.getLogger(RDBBlobStore.class.getName() + ".perf"));
// ID size we need to support; is 2 * (hex) size of digest length
protected static final int IDSIZE;
@@ -345,20 +348,29 @@ public class RDBBlobStore extends Cachin
// needed in test
protected byte[] readBlockFromBackend(byte[] digest) throws Exception {
- String id = StringUtils.convertBytesToHex(digest);
+ return readBlockFromBackend(StringUtils.convertBytesToHex(digest));
+ }
+
+ private byte[] readBlockFromBackend(String id) throws Exception {
Connection con = this.ch.getROConnection();
byte[] data;
try {
+ long pstart = PERFLOG.start(PERFLOG.isDebugEnabled() ? ("reading: " + id) : null);
PreparedStatement prep = con.prepareStatement("select DATA from " + this.tnData + " where ID = ?");
ResultSet rs = null;
try {
prep.setString(1, id);
rs = prep.executeQuery();
if (!rs.next()) {
+ PERFLOG.end(pstart, 10, "read: table={}, id={} -> not found", this.tnData, id);
throw new IOException("Datastore block " + id + " not found");
}
data = rs.getBytes(1);
+ PERFLOG.end(pstart, 10, "read: table={}, id={} -> data={}", this.tnData, id, (data == null ? 0 : data.length));
+ } catch (SQLException ex) {
+ PERFLOG.end(pstart, 10, "read: table={} -> exception={}", this.tnData, ex.getMessage());
+ throw ex;
} finally {
closeResultSet(rs);
closeStatement(prep);
@@ -377,32 +389,12 @@ public class RDBBlobStore extends Cachin
byte[] data = cache.get(id);
if (data == null) {
- Connection con = this.ch.getROConnection();
long start = System.nanoTime();
- try {
- PreparedStatement prep = con.prepareStatement("select DATA from " + this.tnData + " where ID = ?");
- ResultSet rs = null;
- try {
- prep.setString(1, id);
- rs = prep.executeQuery();
- if (!rs.next()) {
- throw new IOException("Datastore block " + id + " not found");
- }
- data = rs.getBytes(1);
- } finally {
- closeResultSet(rs);
- closeStatement(prep);
- }
-
- getStatsCollector().downloaded(id, System.nanoTime() - start, TimeUnit.NANOSECONDS, data.length);
- cache.put(id, data);
- } finally {
- con.commit();
- this.ch.closeConnection(con);
- }
+ data = readBlockFromBackend(id);
+ getStatsCollector().downloaded(id, System.nanoTime() - start, TimeUnit.NANOSECONDS, data.length);
+ cache.put(id, data);
}
- // System.out.println(" read block " + id + " blockLen: " +
- // data.length + " [0]: " + data[0]);
+
if (blockId.getPos() == 0) {
return data;
}
Modified: jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/blob/RDBBlobStoreTest.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/blob/RDBBlobStoreTest.java?rev=1856049&r1=1856048&r2=1856049&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/blob/RDBBlobStoreTest.java (original)
+++ jackrabbit/oak/trunk/oak-store-document/src/test/java/org/apache/jackrabbit/oak/plugins/document/blob/RDBBlobStoreTest.java Fri Mar 22 13:13:02 2019
@@ -16,6 +16,7 @@
*/
package org.apache.jackrabbit.oak.plugins.document.blob;
+import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertTrue;
import static org.junit.Assert.fail;
@@ -30,6 +31,7 @@ import java.util.List;
import java.util.Random;
import org.apache.jackrabbit.oak.commons.StringUtils;
+import org.apache.jackrabbit.oak.commons.junit.LogCustomizer;
import org.apache.jackrabbit.oak.plugins.document.rdb.RDBBlobStore;
import org.apache.jackrabbit.oak.plugins.document.rdb.RDBBlobStoreFriend;
import org.apache.jackrabbit.oak.plugins.document.rdb.RDBDataSourceWrapper;
@@ -42,6 +44,7 @@ import org.junit.runner.RunWith;
import org.junit.runners.Parameterized;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
+import org.slf4j.event.Level;
import com.google.common.collect.ImmutableList;
import com.google.common.collect.Lists;
@@ -274,4 +277,30 @@ public class RDBBlobStoreTest extends Ab
messageDigest.update(bytes, 0, bytes.length);
return messageDigest.digest();
}
+
+ @Test
+ public void testRDBJDBCPerfLog() throws Exception {
+ LogCustomizer logCustomizerRead = LogCustomizer.forLogger(RDBBlobStore.class.getName() + ".perf").enable(Level.TRACE)
+ .matchesRegex("read: .*").create();
+ logCustomizerRead.starting();
+ try {
+ byte[] data = new byte[256];
+ Random r = new Random(0);
+ r.nextBytes(data);
+ byte[] digest = getDigest(data);
+ RDBBlobStoreFriend.storeBlock(blobStore, digest, 0, data);
+ Assert.assertNotNull(RDBBlobStoreFriend.readBlockFromBackend(blobStore, digest));
+ assertEquals(1, logCustomizerRead.getLogs().size());
+
+ r.nextBytes(data);
+ digest = getDigest(data);
+ try {
+ Assert.assertNotNull(RDBBlobStoreFriend.readBlockFromBackend(blobStore, digest));
+ } catch (IOException expected) {
+ assertEquals(2, logCustomizerRead.getLogs().size());
+ }
+ } finally {
+ logCustomizerRead.finished();
+ }
+ }
}