KYLIN-2856 Log pushdown query as a kind of BadQuery
Project: http://git-wip-us.apache.org/repos/asf/kylin/repo Commit: http://git-wip-us.apache.org/repos/asf/kylin/commit/25d2fd9a Tree: http://git-wip-us.apache.org/repos/asf/kylin/tree/25d2fd9a Diff: http://git-wip-us.apache.org/repos/asf/kylin/diff/25d2fd9a Branch: refs/heads/ranger Commit: 25d2fd9a77a1f2a2afadd97b9ca0725032e9f5c9 Parents: aa9e73e Author: Li Yang <liy...@apache.org> Authored: Thu Sep 7 14:49:13 2017 +0800 Committer: Hongbin Ma <m...@kyligence.io> Committed: Thu Sep 7 20:03:20 2017 +0800 ---------------------------------------------------------------------- .../kylin/metadata/badquery/BadQueryEntry.java | 3 ++ .../kylin/rest/service/BadQueryDetector.java | 40 ++++++++++++++------ .../apache/kylin/rest/service/QueryService.java | 10 +++-- .../rest/service/BadQueryDetectorTest.java | 9 +++-- 4 files changed, 43 insertions(+), 19 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/kylin/blob/25d2fd9a/core-metadata/src/main/java/org/apache/kylin/metadata/badquery/BadQueryEntry.java ---------------------------------------------------------------------- diff --git a/core-metadata/src/main/java/org/apache/kylin/metadata/badquery/BadQueryEntry.java b/core-metadata/src/main/java/org/apache/kylin/metadata/badquery/BadQueryEntry.java index 60ce4ce..1e9311f 100644 --- a/core-metadata/src/main/java/org/apache/kylin/metadata/badquery/BadQueryEntry.java +++ b/core-metadata/src/main/java/org/apache/kylin/metadata/badquery/BadQueryEntry.java @@ -29,6 +29,9 @@ import com.fasterxml.jackson.annotation.JsonProperty; @SuppressWarnings("serial") @JsonAutoDetect(fieldVisibility = JsonAutoDetect.Visibility.NONE, getterVisibility = JsonAutoDetect.Visibility.NONE, isGetterVisibility = JsonAutoDetect.Visibility.NONE, setterVisibility = JsonAutoDetect.Visibility.NONE) public class BadQueryEntry extends RootPersistentEntity implements Comparable<BadQueryEntry> { + + public static final String ADJ_SLOW = "Slow"; + public static final String ADJ_PUSHDOWN = "Pushdown"; @JsonProperty("adj") private String adj; http://git-wip-us.apache.org/repos/asf/kylin/blob/25d2fd9a/server-base/src/main/java/org/apache/kylin/rest/service/BadQueryDetector.java ---------------------------------------------------------------------- diff --git a/server-base/src/main/java/org/apache/kylin/rest/service/BadQueryDetector.java b/server-base/src/main/java/org/apache/kylin/rest/service/BadQueryDetector.java index 617584a..7410c9c 100644 --- a/server-base/src/main/java/org/apache/kylin/rest/service/BadQueryDetector.java +++ b/server-base/src/main/java/org/apache/kylin/rest/service/BadQueryDetector.java @@ -36,8 +36,9 @@ import com.google.common.collect.Maps; public class BadQueryDetector extends Thread { - public static final int ONE_MB = 1024 * 1024; private static final Logger logger = LoggerFactory.getLogger(BadQueryDetector.class); + public static final int ONE_MB = 1024 * 1024; + private final ConcurrentMap<Thread, Entry> runningQueries = Maps.newConcurrentMap(); private final long detectionInterval; private final int alertMB; @@ -92,12 +93,15 @@ public class BadQueryDetector extends Thread { notifiers.add(notifier); } - private void notify(String adj, float runningSec, long startTime, String project, String sql, String user, Thread t) { + private void notify(String adj, Entry e) { + float runningSec = (float) (System.currentTimeMillis() - e.startTime) / 1000; + for (Notifier notifier : notifiers) { try { - notifier.badQueryFound(adj, runningSec, startTime, project, sql, user, t); - } catch (Exception e) { - logger.error("", e); + notifier.badQueryFound(adj, runningSec, // + e.startTime, e.sqlRequest.getProject(), e.sqlRequest.getSql(), e.user, e.thread); + } catch (Exception ex) { + logger.error("", ex); } } } @@ -107,7 +111,14 @@ public class BadQueryDetector extends Thread { } public void queryEnd(Thread thread) { - runningQueries.remove(thread); + queryEnd(thread, null); + } + + public void queryEnd(Thread thread, String badReason) { + Entry entry = runningQueries.remove(thread); + + if (badReason != null) + notify(badReason, entry); } public void run() { @@ -137,7 +148,7 @@ public class BadQueryDetector extends Thread { for (Entry e : entries) { float runningSec = (float) (now - e.startTime) / 1000; if (runningSec >= alertRunningSec) { - notify("Slow", runningSec, e.startTime, e.sqlRequest.getProject(), e.sqlRequest.getSql(), e.user, e.thread); + notify(BadQueryEntry.ADJ_SLOW, e); dumpStackTrace(e.thread); } else { break; // entries are sorted by startTime @@ -168,13 +179,16 @@ public class BadQueryDetector extends Thread { } public interface Notifier { - void badQueryFound(String adj, float runningSec, long startTime, String project, String sql, String user, Thread t); + void badQueryFound(String adj, float runningSec, long startTime, String project, String sql, String user, + Thread t); } private class LoggerNotifier implements Notifier { @Override - public void badQueryFound(String adj, float runningSec, long startTime, String project, String sql, String user, Thread t) { - logger.info("{} query has been running {} seconds (project:{}, thread: 0x{}, user:{}) -- {}", adj, runningSec, project, Long.toHexString(t.getId()), user, sql); + public void badQueryFound(String adj, float runningSec, long startTime, String project, String sql, String user, + Thread t) { + logger.info("{} query has been running {} seconds (project:{}, thread: 0x{}, user:{}) -- {}", adj, + runningSec, project, Long.toHexString(t.getId()), user, sql); } } @@ -192,9 +206,11 @@ public class BadQueryDetector extends Thread { } @Override - public void badQueryFound(String adj, float runningSec, long startTime, String project, String sql, String user, Thread t) { + public void badQueryFound(String adj, float runningSec, long startTime, String project, String sql, String user, + Thread t) { try { - BadQueryEntry entry = new BadQueryEntry(sql, adj, startTime, runningSec, serverHostname, t.getName(), user); + BadQueryEntry entry = new BadQueryEntry(sql, adj, startTime, runningSec, serverHostname, t.getName(), + user); badQueryManager.upsertEntryToProject(entry, project); } catch (IOException e) { logger.error("Error in bad query persistence.", e); http://git-wip-us.apache.org/repos/asf/kylin/blob/25d2fd9a/server-base/src/main/java/org/apache/kylin/rest/service/QueryService.java ---------------------------------------------------------------------- diff --git a/server-base/src/main/java/org/apache/kylin/rest/service/QueryService.java b/server-base/src/main/java/org/apache/kylin/rest/service/QueryService.java index e1d0712..2cbe516 100644 --- a/server-base/src/main/java/org/apache/kylin/rest/service/QueryService.java +++ b/server-base/src/main/java/org/apache/kylin/rest/service/QueryService.java @@ -68,6 +68,7 @@ import org.apache.kylin.common.util.SetThreadName; import org.apache.kylin.cube.CubeInstance; import org.apache.kylin.cube.CubeManager; import org.apache.kylin.cube.cuboid.Cuboid; +import org.apache.kylin.metadata.badquery.BadQueryEntry; import org.apache.kylin.metadata.model.DataModelDesc; import org.apache.kylin.metadata.model.JoinDesc; import org.apache.kylin.metadata.model.JoinTableDesc; @@ -172,14 +173,17 @@ public class QueryService extends BasicService { } public SQLResponse query(SQLRequest sqlRequest) throws Exception { + SQLResponse ret = null; try { final String user = SecurityContextHolder.getContext().getAuthentication().getName(); badQueryDetector.queryStart(Thread.currentThread(), sqlRequest, user); - return queryWithSqlMassage(sqlRequest); + ret = queryWithSqlMassage(sqlRequest); + return ret; } finally { - badQueryDetector.queryEnd(Thread.currentThread()); + String badReason = (ret != null && ret.isPushDown()) ? BadQueryEntry.ADJ_PUSHDOWN : null; + badQueryDetector.queryEnd(Thread.currentThread(), badReason); } } @@ -550,7 +554,6 @@ public class QueryService extends BasicService { } finally { DBUtils.closeQuietly(conn); } - } protected List<TableMeta> getMetadata(CubeManager cubeMgr, String project, boolean cubedOnly) throws SQLException { @@ -855,7 +858,6 @@ public class QueryService extends BasicService { close(resultSet, stat, null); //conn is passed in, not my duty to close } - return buildSqlResponse(isPushDown, results, columnMetas); } http://git-wip-us.apache.org/repos/asf/kylin/blob/25d2fd9a/server/src/test/java/org/apache/kylin/rest/service/BadQueryDetectorTest.java ---------------------------------------------------------------------- diff --git a/server/src/test/java/org/apache/kylin/rest/service/BadQueryDetectorTest.java b/server/src/test/java/org/apache/kylin/rest/service/BadQueryDetectorTest.java index 7aabb0e..fc18d92 100644 --- a/server/src/test/java/org/apache/kylin/rest/service/BadQueryDetectorTest.java +++ b/server/src/test/java/org/apache/kylin/rest/service/BadQueryDetectorTest.java @@ -24,6 +24,7 @@ import static org.junit.Assert.assertEquals; import java.util.ArrayList; import org.apache.kylin.common.util.LocalFileMetadataTestCase; +import org.apache.kylin.metadata.badquery.BadQueryEntry; import org.apache.kylin.rest.request.SQLRequest; import org.junit.After; import org.junit.Before; @@ -68,13 +69,15 @@ public class BadQueryDetectorTest extends LocalFileMetadataTestCase { // make sure bad query check happens twice Thread.sleep((alertRunningSec * 2 + 1) * 1000); - badQueryDetector.queryEnd(Thread.currentThread()); + badQueryDetector.queryEnd(Thread.currentThread(), BadQueryEntry.ADJ_PUSHDOWN); } badQueryDetector.stop(); - assertEquals(1, alerts.size()); + assertEquals(2, alerts.size()); // second check founds a Slow - assertArrayEquals(new String[] { "Slow", mockSql }, alerts.get(0)); + assertArrayEquals(new String[] { BadQueryEntry.ADJ_SLOW, mockSql }, alerts.get(0)); + // end notifies a Pushdown + assertArrayEquals(new String[] { BadQueryEntry.ADJ_PUSHDOWN, mockSql }, alerts.get(1)); } }
