Skip to content
Permalink
Browse files
DRILL-6496: Added print methods for debugging tests, and fixed missin…
…g log statement in VectorUtils.

closes #1336
  • Loading branch information
ilooner authored and Ben-Zvi committed Jul 19, 2018
1 parent 6bb0879 commit 2c92ea22d9aa098cf3aaaf7893bd2fc33a08af31
Show file tree
Hide file tree
Showing 33 changed files with 447 additions and 172 deletions.
@@ -55,11 +55,11 @@ protected List<QueryDataBatch> runHBaseSQLlWithResults(String sql) throws Except

protected void runSQLAndVerifyCount(String sql, int expectedRowCount) throws Exception{
List<QueryDataBatch> results = runHBaseSQLlWithResults(sql);
printResultAndVerifyRowCount(results, expectedRowCount);
logResultAndVerifyRowCount(results, expectedRowCount);
}

private void printResultAndVerifyRowCount(List<QueryDataBatch> results, int expectedRowCount) throws SchemaChangeException {
int rowCount = printResult(results);
private void logResultAndVerifyRowCount(List<QueryDataBatch> results, int expectedRowCount) throws SchemaChangeException {
int rowCount = logResult(results);
if (expectedRowCount != -1) {
Assert.assertEquals(expectedRowCount, rowCount);
}
@@ -79,7 +79,7 @@ protected String getPlanText(String planFile, String tableName) throws IOExcepti
protected void runHBasePhysicalVerifyCount(String planFile, String tableName, int expectedRowCount) throws Exception{
String physicalPlan = getPlanText(planFile, tableName);
List<QueryDataBatch> results = testPhysicalWithResults(physicalPlan);
printResultAndVerifyRowCount(results, expectedRowCount);
logResultAndVerifyRowCount(results, expectedRowCount);
}

protected List<QueryDataBatch> runHBaseSQLlWithResults(String sql) throws Exception {
@@ -89,11 +89,11 @@ protected List<QueryDataBatch> runHBaseSQLlWithResults(String sql) throws Except

protected void runHBaseSQLVerifyCount(String sql, int expectedRowCount) throws Exception{
List<QueryDataBatch> results = runHBaseSQLlWithResults(sql);
printResultAndVerifyRowCount(results, expectedRowCount);
logResultAndVerifyRowCount(results, expectedRowCount);
}

private void printResultAndVerifyRowCount(List<QueryDataBatch> results, int expectedRowCount) throws SchemaChangeException {
int rowCount = printResult(results);
private void logResultAndVerifyRowCount(List<QueryDataBatch> results, int expectedRowCount) throws SchemaChangeException {
int rowCount = logResult(results);
if (expectedRowCount != -1) {
Assert.assertEquals(expectedRowCount, rowCount);
}
@@ -55,7 +55,7 @@ public static void closeMyClient() throws IOException {
public void testColumnFamiliesAsJSONString() throws Exception {
setColumnWidths(new int[] {112, 12});
List<QueryDataBatch> resultList = runHBaseSQLlWithResults("SELECT f, f2 FROM hbase.`[TABLE_NAME]` tableName LIMIT 1");
printResult(resultList);
logResult(resultList);
}

}
@@ -96,7 +96,7 @@ public void testCastEmptyStrings() throws Exception {
List<QueryDataBatch> resultList = runHBaseSQLlWithResults("SELECT row_key,\n"
+ " CAST(t.f.c1 as INT) c1, CAST(t.f.c2 as BIGINT) c2, CAST(t.f.c3 as INT) c3,\n"
+ " CAST(t.f.c4 as INT) c4 FROM hbase.TestTableNullStr t where row_key='a1'");
printResult(resultList);
logResult(resultList);
}
finally {
test("alter system reset `drill.exec.functions.cast_empty_string_to_null`;");
@@ -66,12 +66,12 @@ public List<QueryDataBatch> runKafkaSQLWithResults(String sql) throws Exception

public void runKafkaSQLVerifyCount(String sql, int expectedRowCount) throws Exception {
List<QueryDataBatch> results = runKafkaSQLWithResults(sql);
printResultAndVerifyRowCount(results, expectedRowCount);
logResultAndVerifyRowCount(results, expectedRowCount);
}

public void printResultAndVerifyRowCount(List<QueryDataBatch> results, int expectedRowCount)
public void logResultAndVerifyRowCount(List<QueryDataBatch> results, int expectedRowCount)
throws SchemaChangeException {
int rowCount = printResult(results);
int rowCount = logResult(results);
if (expectedRowCount != -1) {
Assert.assertEquals(expectedRowCount, rowCount);
}
@@ -89,4 +89,4 @@ public static void tearDownKafkaTestBase() throws Exception {
TestKafkaSuit.tearDownCluster();
}

}
}
@@ -64,12 +64,12 @@ public List<QueryDataBatch> runMongoSQLWithResults(String sql)
public void runMongoSQLVerifyCount(String sql, int expectedRowCount)
throws Exception {
List<QueryDataBatch> results = runMongoSQLWithResults(sql);
printResultAndVerifyRowCount(results, expectedRowCount);
logResultAndVerifyRowCount(results, expectedRowCount);
}

public void printResultAndVerifyRowCount(List<QueryDataBatch> results,
int expectedRowCount) throws SchemaChangeException {
int rowCount = printResult(results);
public void logResultAndVerifyRowCount(List<QueryDataBatch> results,
int expectedRowCount) throws SchemaChangeException {
int rowCount = logResult(results);
if (expectedRowCount != -1) {
Assert.assertEquals(expectedRowCount, rowCount);
}
@@ -92,4 +92,4 @@ public static void tearDownMongoTestBase() throws Exception {
storagePlugin = null;
}

}
}
@@ -103,3 +103,40 @@ Then, if for some reason you want to see the Logback logging, add the following
-Dlogback.statusListenerClass=ch.qos.logback.core.status.OnConsoleStatusListener
```
The launch configuration option overrides (appears on the Java command line after) the global setting.

## Test Logging Configurations

### Default Test Log Levels

There is a global `logback-test.xml` configuration file in [common/src/test/resources/logback-test.xml](../../common/src/test/resources/logback-test.xml). This
logging configuration by default outputs error level logs to stdout.

Debug level logging to lilith can be turned on by adding `-Ddrill.lilith.enable=true` to the command used to run tests.

### Changing Test Log Levels

Often times it is most convenient to output logs to the console for debugging. This is best done programatically
by using the [LogFixture](../../exec/java-exec/src/test/java/org/apache/drill/test/LogFixture.java). The [LogFixture](../../exec/java-exec/src/test/java/org/apache/drill/test/LogFixture.java)
allows temporarily changing log levels for blocks of code programatically for debugging. An example of doing this is
the following.

```
try(LogFixture logFixture = new LogFixture.LogFixtureBuilder()
.logger(MyClass.class, Level.INFO)
.toConsole() // This redirects output to stdout
.build()) {
// Code block with different log levels.
}
```

More details on how to use the [LogFixture](../../exec/java-exec/src/test/java/org/apache/drill/test/LogFixture.java) can be found
int the javadocs for the class. Additionally, there are several methods that allow printing of query results to the console for debugging:

* BaseTestQuery.printResult
* QueryTestUtil.testRunAndPrint
* QueryBuilder.print
* ClusterTest.runAndPrint
* ClientFixture.runQueriesAndPrint

**IMPORTANT NOTE:** The methods described above along with LogFixtureBuilder.toConsole() should only be used for debugging. Code
that uses these methods should not be committed, since it produces excess logging on our build servers.
@@ -149,7 +149,6 @@ Drill uses the [Maven Surefire plugin](http://maven.apache.org/components/surefi
-Ddrill.exec.sys.store.provider.local.write=false
-Dorg.apache.drill.exec.server.Drillbit.system_options=\
"org.apache.drill.exec.compile.ClassTransformer.scalar_replacement=on"
-Ddrill.test.query.printing.silent=true
-Ddrill.catastrophic_to_standard_out=true
-XX:MaxPermSize=512M -XX:MaxDirectMemorySize=3072M
-Djava.net.preferIPv4Stack=true
@@ -261,7 +261,7 @@ private void showSingleBatch (VectorAccessibleSerializable vcSerializable, boole
}

/* show the contents in the batch */
VectorUtil.showVectorAccessibleContent(vectorContainer);
VectorUtil.logVectorAccessibleContent(vectorContainer);
}

/* Get batch meta info : rows, selectedRows, dataSize */
@@ -40,8 +40,8 @@

import io.netty.buffer.DrillBuf;

public class PrintingResultsListener implements UserResultsListener {
private static final org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(PrintingResultsListener.class);
public class LoggingResultsListener implements UserResultsListener {
private static final org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(LoggingResultsListener.class);

private final AtomicInteger count = new AtomicInteger();
private final Stopwatch w = Stopwatch.createUnstarted();
@@ -50,7 +50,7 @@ public class PrintingResultsListener implements UserResultsListener {
private final int columnWidth;
private final BufferAllocator allocator;

public PrintingResultsListener(DrillConfig config, Format format, int columnWidth) {
public LoggingResultsListener(DrillConfig config, Format format, int columnWidth) {
this.allocator = RootAllocatorFactory.newRoot(config);
this.loader = new RecordBatchLoader(allocator);
this.format = format;
@@ -59,15 +59,13 @@ public PrintingResultsListener(DrillConfig config, Format format, int columnWidt

@Override
public void submissionFailed(UserException ex) {
System.out.println("Exception (no rows returned): " + ex + ". Returned in " + w.elapsed(TimeUnit.MILLISECONDS)
+ "ms.");
logger.info("Exception (no rows returned). Returned in {} ms.", w.elapsed(TimeUnit.MILLISECONDS), ex);
}

@Override
public void queryCompleted(QueryState state) {
DrillAutoCloseables.closeNoChecked(allocator);
System.out.println("Total rows returned : " + count.get() + ". Returned in " + w.elapsed(TimeUnit.MILLISECONDS)
+ "ms.");
logger.info("Total rows returned: {}. Returned in {} ms.", count.get(), w.elapsed(TimeUnit.MILLISECONDS));
}

@Override
@@ -90,13 +88,13 @@ public void dataArrived(QueryDataBatch result, ConnectionThrottle throttle) {
try {
switch(format) {
case TABLE:
VectorUtil.showVectorAccessibleContent(loader, columnWidth);
VectorUtil.logVectorAccessibleContent(loader, columnWidth);
break;
case TSV:
VectorUtil.showVectorAccessibleContent(loader, "\t");
VectorUtil.logVectorAccessibleContent(loader, "\t");
break;
case CSV:
VectorUtil.showVectorAccessibleContent(loader, ",");
VectorUtil.logVectorAccessibleContent(loader, ",");
break;
default:
throw new IllegalStateException(format.toString());
@@ -189,7 +189,7 @@ public int submitQuery(DrillClient client, String plan, String type, String form
Stopwatch watch = Stopwatch.createUnstarted();
for (String query : queries) {
AwaitableUserResultsListener listener =
new AwaitableUserResultsListener(new PrintingResultsListener(client.getConfig(), outputFormat, width));
new AwaitableUserResultsListener(new LoggingResultsListener(client.getConfig(), outputFormat, width));
watch.start();
client.runQuery(queryType, query, listener);
int rows = listener.await();
@@ -0,0 +1,29 @@
/*
* 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.drill.exec.util;

/**
* The java standard library does not provide a lambda function interface for funtions that take no arguments,
* but that throw an exception. So, we have to define our own here.
* @param <T> The return type of the lambda function.
* @param <E> The type of exception thrown by the lambda function.
*/
@FunctionalInterface
public interface CheckedSupplier<T, E extends Exception> {
T get() throws E;
}
@@ -39,7 +39,7 @@ public class VectorUtil {
private static final org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger(VectorUtil.class);
public static final int DEFAULT_COLUMN_WIDTH = 15;

public static void showVectorAccessibleContent(VectorAccessible va, final String delimiter) {
public static void logVectorAccessibleContent(VectorAccessible va, final String delimiter) {
final StringBuilder sb = new StringBuilder();
int rows = va.getRecordCount();
sb.append(rows).append(" row(s):\n");
@@ -133,15 +133,15 @@ public static void appendVectorAccessibleContent(VectorAccessible va, StringBuil
}
}

public static void showVectorAccessibleContent(VectorAccessible va) {
showVectorAccessibleContent(va, DEFAULT_COLUMN_WIDTH);
public static void logVectorAccessibleContent(VectorAccessible va) {
logVectorAccessibleContent(va, DEFAULT_COLUMN_WIDTH);
}

public static void showVectorAccessibleContent(VectorAccessible va, int columnWidth) {
showVectorAccessibleContent(va, new int[]{ columnWidth });
public static void logVectorAccessibleContent(VectorAccessible va, int columnWidth) {
logVectorAccessibleContent(va, new int[]{ columnWidth });
}

public static void showVectorAccessibleContent(VectorAccessible va, int[] columnWidths) {
public static void logVectorAccessibleContent(VectorAccessible va, int[] columnWidths) {
final StringBuilder sb = new StringBuilder();
int width = 0;
int columnIndex = 0;
@@ -194,6 +194,8 @@ public static void showVectorAccessibleContent(VectorAccessible va, int[] column
for (VectorWrapper<?> vw : va) {
vw.clear();
}

logger.info(sb.toString());
}

private static String expandMapSchema(MaterializedField mapField) {
@@ -181,7 +181,7 @@ public void run() {

@Test
public void testConcurrentQueries() throws Exception {
QueryTestUtil.testRunAndPrint(client, UserBitShared.QueryType.SQL, alterSession);
QueryTestUtil.testRunAndLog(client, UserBitShared.QueryType.SQL, alterSession);

testThread = Thread.currentThread();
final QuerySubmitter querySubmitter = new QuerySubmitter();
@@ -518,7 +518,7 @@ public void testBigIntVarCharReturnTripConvertLogical() throws Exception {
count += result.getHeader().getRowCount();
loader.load(result.getHeader().getDef(), result.getData());
if (loader.getRecordCount() > 0) {
VectorUtil.showVectorAccessibleContent(loader);
VectorUtil.logVectorAccessibleContent(loader);
}
loader.clear();
result.release();

0 comments on commit 2c92ea2

Please sign in to comment.