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 ch...@apache.org on 2016/02/26 11:03:03 UTC
svn commit: r1732443 - in /jackrabbit/oak/trunk:
oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/value/
oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/
oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/
Author: chetanm
Date: Fri Feb 26 10:03:03 2016
New Revision: 1732443
URL: http://svn.apache.org/viewvc?rev=1732443&view=rev
Log:
OAK-4010 - Log major operation done in Oak via specific operation logger
Added:
jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/OperationLoggerTest.java (with props)
Modified:
jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/value/ValueFactoryImpl.java
jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryManagerImpl.java
jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultImpl.java
Modified: jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/value/ValueFactoryImpl.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/value/ValueFactoryImpl.java?rev=1732443&r1=1732442&r2=1732443&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/value/ValueFactoryImpl.java (original)
+++ jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/plugins/value/ValueFactoryImpl.java Fri Feb 26 10:03:03 2016
@@ -56,13 +56,16 @@ import org.apache.jackrabbit.oak.plugins
import org.apache.jackrabbit.oak.plugins.memory.PropertyStates;
import org.apache.jackrabbit.oak.plugins.memory.StringPropertyState;
import org.apache.jackrabbit.oak.spi.query.PropertyValues;
+import org.apache.jackrabbit.oak.util.PerfLogger;
import org.apache.jackrabbit.util.ISO8601;
+import org.slf4j.LoggerFactory;
/**
* Implementation of {@link ValueFactory} interface.
*/
public class ValueFactoryImpl implements ValueFactory {
-
+ private static final PerfLogger binOpsLogger = new PerfLogger(
+ LoggerFactory.getLogger("org.apache.jackrabbit.oak.jcr.operations.binary.perf"));
private final Root root;
private final NamePathMapper namePathMapper;
@@ -290,7 +293,10 @@ public class ValueFactoryImpl implements
}
private ValueImpl createBinaryValue(InputStream value) throws IOException, RepositoryException {
- return createBinaryValue(root.createBlob(value));
+ long start = binOpsLogger.start();
+ Blob blob = root.createBlob(value);
+ binOpsLogger.end(start, -1, "Created binary property of size [{}]", blob.length());
+ return createBinaryValue(blob);
}
private ValueImpl createBinaryValue(Blob blob) throws RepositoryException {
Modified: jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryManagerImpl.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryManagerImpl.java?rev=1732443&r1=1732442&r2=1732443&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryManagerImpl.java (original)
+++ jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryManagerImpl.java Fri Feb 26 10:03:03 2016
@@ -50,12 +50,14 @@ import org.apache.jackrabbit.oak.plugins
import org.apache.jackrabbit.oak.spi.query.PropertyValues;
import org.apache.jackrabbit.oak.stats.MeterStats;
import org.apache.jackrabbit.oak.stats.TimerStats;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
/**
* The implementation of the corresponding JCR interface.
*/
public class QueryManagerImpl implements QueryManager {
-
+ private static final Logger queryOpsLogger = LoggerFactory.getLogger("org.apache.jackrabbit.oak.jcr.operations.query");
private final SessionDelegate sessionDelegate;
private final SessionContext sessionContext;
private final QueryObjectModelFactoryImpl qomFactory;
@@ -135,9 +137,10 @@ public class QueryManagerImpl implements
statement, language, limit, offset, bindMap,
sessionContext.getSessionLocalMappings());
queryCount.mark();
- long nanos = context.stop();
+ long millis = TimeUnit.NANOSECONDS.toMillis(context.stop());
+ queryOpsLogger.debug("Executed query [{}] in [{}] ms", statement, millis);
sessionContext.getStatisticManager()
- .logQueryEvaluationTime(language, statement, TimeUnit.NANOSECONDS.toMillis(nanos));
+ .logQueryEvaluationTime(language, statement, millis);
return new QueryResultImpl(sessionContext, r);
} catch (IllegalArgumentException e) {
throw new InvalidQueryException(e);
Modified: jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultImpl.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultImpl.java?rev=1732443&r1=1732442&r2=1732443&view=diff
==============================================================================
--- jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultImpl.java (original)
+++ jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/query/QueryResultImpl.java Fri Feb 26 10:03:03 2016
@@ -48,7 +48,7 @@ import org.slf4j.LoggerFactory;
* The implementation of the corresponding JCR interface.
*/
public class QueryResultImpl implements QueryResult {
-
+ private static final Logger queryOpsLogger = LoggerFactory.getLogger("org.apache.jackrabbit.oak.jcr.operations.query");
static final Logger LOG = LoggerFactory.getLogger(QueryResultImpl.class);
protected final SessionContext sessionContext;
@@ -80,6 +80,9 @@ public class QueryResultImpl implements
private final Iterator<? extends ResultRow> it = result.getRows().iterator();
private final String pathSelector;
private RowImpl current;
+ private int rowCount;
+ //Avoid log check for every row access
+ private final boolean debugEnabled = queryOpsLogger.isDebugEnabled();
{
String[] columnSelectorNames = result.getColumnSelectorNames();
@@ -95,6 +98,12 @@ public class QueryResultImpl implements
if (it.hasNext()) {
current = new RowImpl(
QueryResultImpl.this, it.next(), pathSelector);
+ if (debugEnabled) {
+ rowCount++;
+ if (rowCount % 100 == 0) {
+ queryOpsLogger.debug("Iterated over [{}] results so far", rowCount);
+ }
+ }
} else {
current = null;
}
Added: jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/OperationLoggerTest.java
URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/OperationLoggerTest.java?rev=1732443&view=auto
==============================================================================
--- jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/OperationLoggerTest.java (added)
+++ jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/OperationLoggerTest.java Fri Feb 26 10:03:03 2016
@@ -0,0 +1,135 @@
+/*
+ * 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.jcr;
+
+import java.io.ByteArrayInputStream;
+
+import javax.jcr.Binary;
+import javax.jcr.Node;
+import javax.jcr.query.Query;
+import javax.jcr.query.QueryManager;
+import javax.jcr.query.QueryResult;
+
+import ch.qos.logback.classic.Level;
+import ch.qos.logback.classic.Logger;
+import ch.qos.logback.classic.LoggerContext;
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
+import com.google.common.collect.Iterators;
+import org.apache.jackrabbit.test.AbstractJCRTest;
+import org.slf4j.LoggerFactory;
+
+/**
+ * Testcase which asserts on some std log statements. These statement
+ * are picked by tooling outside of Oak so act like a weak contract to
+ * honour.
+ */
+public class OperationLoggerTest extends AbstractJCRTest {
+ private final String[] OPS_LOGGERS = {
+ "org.apache.jackrabbit.oak.jcr.operations"
+ };
+ private static final String OPS_QUERY = "org.apache.jackrabbit.oak.jcr.operations.query";
+ private static final String OPS_BINARY = "org.apache.jackrabbit.oak.jcr.operations.binary";
+ private ListAppender<ILoggingEvent> logs = new ListAppender<ILoggingEvent>();
+
+ @Override
+ protected void tearDown() throws Exception {
+ super.tearDown();
+ stop();
+ }
+
+ public void testQueryLogger() throws Exception {
+ Node node1 = testRootNode.addNode(nodeName1);
+ //Log batch size is 100
+ for (int i = 0; i < 200; i++) {
+ node1.addNode("foo"+i, "oak:Unstructured").setProperty("foo", "bar");
+ }
+ superuser.save();
+
+ QueryManager qm = superuser.getWorkspace().getQueryManager();
+ start();
+ String stmt = "select * from [nt:base] where foo = 'bar'";
+ Query q = qm.createQuery(stmt, Query.JCR_SQL2);
+ QueryResult r = q.execute();
+ Iterators.size(r.getRows());
+ stop();
+
+ boolean queryStmtLog = false;
+ boolean queryIterationLog = false;
+ for (ILoggingEvent e : logs.list){
+ if (OPS_QUERY.equals(e.getLoggerName())){
+ if (e.getMessage().contains("Executed query")) {
+ assertEquals(stmt, e.getArgumentArray()[0]);
+ assertTrue(e.getArgumentArray()[1] instanceof Number);
+ queryStmtLog = true;
+ }
+ if (e.getMessage().contains("Iterated over")) {
+ queryIterationLog = true;
+ }
+ }
+ }
+
+ assertTrue("Did not find query log", queryStmtLog);
+ assertTrue("Did not find query iteration log", queryIterationLog);
+ }
+
+ public void testBinaryLogger() throws Exception{
+ Node node1 = testRootNode.addNode(nodeName1);
+
+ start();
+ byte[] data = "hello".getBytes();
+ Binary b = superuser.getValueFactory().createBinary(new ByteArrayInputStream(data));
+ node1.setProperty("foo", b);
+ stop();
+
+ boolean binaryLog = false;
+ for (ILoggingEvent e : logs.list){
+ if (e.getLoggerName().startsWith(OPS_BINARY)){
+ if (e.getMessage().contains("Created binary property")) {
+ assertEquals(Long.valueOf(data.length), e.getArgumentArray()[0]);
+ binaryLog = true;
+ }
+ }
+ }
+
+ assertTrue("Did not find binary upload log", binaryLog);
+ }
+
+ private void start() {
+ logs.start();
+ logs.list.clear();
+ for (String logger : OPS_LOGGERS) {
+ getLogger(logger).addAppender(logs);
+ getLogger(logger).setLevel(Level.DEBUG);
+ }
+ }
+
+ private void stop() {
+ for (String logger : OPS_LOGGERS) {
+ getLogger(logger).detachAppender(logs);
+ getLogger(logger).setLevel(null);
+ }
+ logs.stop();
+ }
+
+ private static Logger getLogger(String name) {
+ return ((LoggerContext) LoggerFactory.getILoggerFactory()).getLogger(name);
+ }
+}
Propchange: jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/OperationLoggerTest.java
------------------------------------------------------------------------------
svn:eol-style = native