Skip to content

[improvement](log) Add query id info in error log for easy tracking #7975

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
morningman merged 1 commit into from
Feb 9, 2022
Merged

[improvement](log) Add query id info in error log for easy tracking #7975

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
78 changes: 52 additions & 26 deletions fe/fe-core/src/main/java/org/apache/doris/analysis/QueryStmt.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,11 +23,14 @@
import org.apache.doris.common.ErrorReport;
import org.apache.doris.common.UserException;
import org.apache.doris.rewrite.ExprRewriter;

import com.google.common.base.Preconditions;
import com.google.common.collect.Lists;
import com.google.common.collect.Sets;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

import java.util.ArrayList;
import java.util.HashMap;
import java.util.List;
Expand Down Expand Up @@ -177,8 +180,8 @@ public void analyze(Analyzer analyzer) throws AnalysisException, UserException {
private void analyzeLimit(Analyzer analyzer) throws AnalysisException {
// TODO chenhao
if (limitElement.getOffset() > 0 && !hasOrderByClause()) {
throw new AnalysisException("OFFSET requires an ORDER BY clause: " +
limitElement.toSql().trim());
throw new AnalysisException("OFFSET requires an ORDER BY clause: " +
limitElement.toSql().trim());
}
limitElement.analyze(analyzer);
}
Expand Down Expand Up @@ -213,7 +216,7 @@ public List<TupleId> getCorrelatedTupleIds(Analyzer analyzer)

List<TableRef> tblRefs = Lists.newArrayList();
collectTableRefs(tblRefs);
for (TableRef tblRef: tblRefs) {
for (TableRef tblRef : tblRefs) {
if (absoluteRef == null && !tblRef.isRelative()) absoluteRef = tblRef;
/*if (tblRef.isCorrelated()) {
*
Expand Down Expand Up @@ -313,19 +316,21 @@ protected void createSortInfo(Analyzer analyzer) throws AnalysisException {
// are ignored.
if (!hasLimit() && !hasOffset() && (!analyzer.isRootAnalyzer() || fromInsert)) {
evaluateOrderBy = false;
// Return a warning that the order by was ignored.
StringBuilder strBuilder = new StringBuilder();
strBuilder.append("Ignoring ORDER BY clause without LIMIT or OFFSET: ");
strBuilder.append("ORDER BY ");
strBuilder.append(orderByElements.get(0).toSql());
for (int i = 1; i < orderByElements.size(); ++i) {
strBuilder.append(", ").append(orderByElements.get(i).toSql());
if (LOG.isDebugEnabled()) {
// Return a warning that the order by was ignored.
StringBuilder strBuilder = new StringBuilder();
strBuilder.append("Ignoring ORDER BY clause without LIMIT or OFFSET: ");
strBuilder.append("ORDER BY ");
strBuilder.append(orderByElements.get(0).toSql());
for (int i = 1; i < orderByElements.size(); ++i) {
strBuilder.append(", ").append(orderByElements.get(i).toSql());
}
strBuilder.append(".\nAn ORDER BY appearing in a view, subquery, union operand, ");
strBuilder.append("or an insert/ctas statement has no effect on the query result ");
strBuilder.append("unless a LIMIT and/or OFFSET is used in conjunction ");
strBuilder.append("with the ORDER BY.");
LOG.debug(strBuilder.toString());
}
strBuilder.append(".\nAn ORDER BY appearing in a view, subquery, union operand, ");
strBuilder.append("or an insert/ctas statement has no effect on the query result ");
strBuilder.append("unless a LIMIT and/or OFFSET is used in conjunction ");
strBuilder.append("with the ORDER BY.");
LOG.info(strBuilder.toString());
} else {
evaluateOrderBy = true;
}
Expand Down Expand Up @@ -378,7 +383,7 @@ protected void createSortTupleInfo(Analyzer analyzer) throws AnalysisException {
* exprs is an ambiguous alias.
*/
protected Expr getFirstAmbiguousAlias(List<Expr> exprs) {
for (Expr exp: exprs) {
for (Expr exp : exprs) {
if (ambiguousAliasList.contains(exp)) return exp;
}
return null;
Expand Down Expand Up @@ -453,13 +458,15 @@ public void getWithClauseTableRefs(Analyzer analyzer, List<TableRef> tblRefs, Se
* collect all exprs of a QueryStmt to a map
* @param exprMap
*/
public void collectExprs(Map<String, Expr> exprMap) {}
public void collectExprs(Map<String, Expr> exprMap) {
}

/**
* put all rewritten exprs back to the ori QueryStmt
* @param rewrittenExprMap
*/
public void putBackExprs(Map<String, Expr> rewrittenExprMap) {}
public void putBackExprs(Map<String, Expr> rewrittenExprMap) {
}


@Override
Expand Down Expand Up @@ -551,14 +558,29 @@ public void removeOrderByElements() {
orderByElements = null;
}

public void setWithClause(WithClause withClause) { this.withClause_ = withClause; }
public boolean hasWithClause() { return withClause_ != null; }
public WithClause getWithClause() { return withClause_; }
public void setWithClause(WithClause withClause) {
this.withClause_ = withClause;
}

public boolean hasWithClause() {
return withClause_ != null;
}

public WithClause getWithClause() {
return withClause_;
}

public boolean hasOrderByClause() {
return orderByElements != null;
}
public boolean hasLimit() { return limitElement != null && limitElement.hasLimit(); }
public boolean hasOffset() { return limitElement != null && limitElement.hasOffset(); }

public boolean hasLimit() {
return limitElement != null && limitElement.hasLimit();
}

public boolean hasOffset() {
return limitElement != null && limitElement.hasOffset();
}

public long getLimit() {
return limitElement.getLimit();
Expand Down Expand Up @@ -601,7 +623,11 @@ public boolean hasLimitClause() {
public SortInfo getSortInfo() {
return sortInfo;
}
public boolean evaluateOrderBy() { return evaluateOrderBy; }

public boolean evaluateOrderBy() {
return evaluateOrderBy;
}

public ArrayList<Expr> getResultExprs() {
return resultExprs;
}
Expand Down Expand Up @@ -650,7 +676,7 @@ public Set<TupleId> getDisableTuplesMVRewriter() {
*/
protected void materializeSlots(Analyzer analyzer, List<Expr> exprs) {
List<SlotId> slotIds = Lists.newArrayList();
for (Expr e: exprs) {
for (Expr e : exprs) {
e.getIds(null, slotIds);
}
analyzer.getDescTbl().markSlotsMaterialized(slotIds);
Expand All @@ -665,7 +691,7 @@ public ArrayList<OrderByElement> cloneOrderByElements() {
if (orderByElements == null) return null;
ArrayList<OrderByElement> result =
Lists.newArrayListWithCapacity(orderByElements.size());
for (OrderByElement o: orderByElements) result.add(o.clone());
for (OrderByElement o : orderByElements) result.add(o.clone());
return result;
}

Expand Down
3 changes: 2 additions & 1 deletion fe/fe-core/src/main/java/org/apache/doris/mysql/nio/AcceptListener.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
import org.apache.doris.qe.ConnectContext;
import org.apache.doris.qe.ConnectProcessor;
import org.apache.doris.qe.ConnectScheduler;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.xnio.ChannelListener;
Expand All @@ -48,7 +49,7 @@ public void handleEvent(AcceptingChannel<StreamConnection> channel) {
if (connection == null) {
return;
}
LOG.info("Connection established. remote={}", connection.getPeerAddress());
LOG.debug("Connection established. remote={}", connection.getPeerAddress());
// connection has been established, so need to call context.cleanup()
// if exception happens.
NConnectContext context = new NConnectContext(connection);
Expand Down
5 changes: 5 additions & 0 deletions fe/fe-core/src/main/java/org/apache/doris/qe/ConnectContext.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@
import org.apache.doris.catalog.Database;
import org.apache.doris.cluster.ClusterNamespace;
import org.apache.doris.common.UserException;
import org.apache.doris.common.util.DebugUtil;
import org.apache.doris.mysql.MysqlCapability;
import org.apache.doris.mysql.MysqlChannel;
import org.apache.doris.mysql.MysqlCommand;
Expand Down Expand Up @@ -539,4 +540,8 @@ public List<String> toRow(long nowMs) {
return row;
}
}

public String getQueryIdentifier() {
return "stmt[" + stmtId + ", " + DebugUtil.printId(queryId) + "]";
}
}
18 changes: 9 additions & 9 deletions fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -364,7 +364,7 @@ public void execute(TUniqueId queryId) throws Exception {
if (scanNode instanceof OlapScanNode) {
OlapScanNode olapScanNode = (OlapScanNode) scanNode;
Catalog.getCurrentCatalog().getSqlBlockRuleMgr().checkLimitaions(olapScanNode.getSelectedPartitionNum().longValue(),
olapScanNode.getSelectedTabletsNum(), olapScanNode.getCardinality(), analyzer.getQualifiedUser());
olapScanNode.getSelectedTabletsNum(), olapScanNode.getCardinality(), analyzer.getQualifiedUser());
}
}
}
Expand Down Expand Up @@ -439,18 +439,18 @@ public void execute(TUniqueId queryId) throws Exception {
context.getState().setError(ErrorCode.ERR_NOT_SUPPORTED_YET, "Do not support this query.");
}
} catch (IOException e) {
LOG.warn("execute IOException ", e);
LOG.warn("execute IOException. {}", context.getQueryIdentifier(), e);
// the exception happens when interact with client
// this exception shows the connection is gone
context.getState().setError(ErrorCode.ERR_UNKNOWN_ERROR, e.getMessage());
throw e;
} catch (UserException e) {
// analysis exception only print message, not print the stack
LOG.warn("execute Exception. {}", e.getMessage());
LOG.warn("execute Exception. {}, {}", context.getQueryIdentifier(), e.getMessage());
context.getState().setError(e.getMysqlErrorCode(), e.getMessage());
context.getState().setErrType(QueryState.ErrType.ANALYSIS_ERR);
} catch (Exception e) {
LOG.warn("execute Exception", e);
LOG.warn("execute Exception. {}", context.getQueryIdentifier(), e);
context.getState().setError(ErrorCode.ERR_UNKNOWN_ERROR,
e.getClass().getSimpleName() + ", msg: " + e.getMessage());
if (parsedStmt instanceof KillStmt) {
Expand All @@ -466,7 +466,7 @@ public void execute(TUniqueId queryId) throws Exception {
sessionVariable.setIsSingleSetVar(false);
sessionVariable.clearSessionOriginValue();
} catch (DdlException e) {
LOG.warn("failed to revert Session value.", e);
LOG.warn("failed to revert Session value. {}", context.getQueryIdentifier(), e);
context.getState().setError(e.getMysqlErrorCode(), e.getMessage());
}
if (!context.isTxnModel() && parsedStmt instanceof InsertStmt) {
Expand All @@ -480,7 +480,7 @@ public void execute(TUniqueId queryId) throws Exception {
insertStmt.getDbObj().getId(), insertStmt.getTransactionId(),
(errMsg == null ? "unknown reason" : errMsg));
} catch (Exception abortTxnException) {
LOG.warn("errors when abort txn", abortTxnException);
LOG.warn("errors when abort txn. {}", context.getQueryIdentifier(), abortTxnException);
}
}
}
Expand Down Expand Up @@ -580,7 +580,7 @@ public void analyze(TQueryOptions tQueryOptions) throws UserException {
} catch (UserException e) {
throw e;
} catch (Exception e) {
LOG.warn("Analyze failed because ", e);
LOG.warn("Analyze failed. {}", context.getQueryIdentifier(), e);
throw new AnalysisException("Unexpected exception: " + e.getMessage());
} finally {
MetaLockUtils.readUnlockTables(tables);
Expand All @@ -591,7 +591,7 @@ public void analyze(TQueryOptions tQueryOptions) throws UserException {
} catch (UserException e) {
throw e;
} catch (Exception e) {
LOG.warn("Analyze failed because ", e);
LOG.warn("Analyze failed. {}", context.getQueryIdentifier(), e);
throw new AnalysisException("Unexpected exception: " + e.getMessage());
}
}
Expand Down Expand Up @@ -678,7 +678,7 @@ private void analyzeAndGenerateQueryPlan(TQueryOptions tQueryOptions) throws Use
}
if (explainOptions != null) parsedStmt.setIsExplain(explainOptions);
}

if (parsedStmt instanceof InsertStmt && parsedStmt.isExplain()) {
if (ConnectContext.get() != null &&
ConnectContext.get().getExecutor() != null &&
Expand Down
36 changes: 28 additions & 8 deletions fe/fe-core/src/test/java/org/apache/doris/planner/QueryPlanTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,7 +38,6 @@
import org.apache.doris.catalog.Replica;
import org.apache.doris.catalog.Tablet;
import org.apache.doris.catalog.Type;
import org.apache.doris.common.AnalysisException;
import org.apache.doris.common.Config;
import org.apache.doris.common.FeConstants;
import org.apache.doris.common.jmockit.Deencapsulation;
Expand All @@ -55,6 +54,7 @@
import org.junit.AfterClass;
import org.junit.Assert;
import org.junit.BeforeClass;
import org.junit.Ignore;
import org.junit.Test;

import java.io.File;
Expand Down Expand Up @@ -392,7 +392,7 @@ public static void beforeClass() throws Exception {
"\"driver\" = \"Oracle Driver\",\n" +
"\"odbc_type\" = \"mysql\"\n" +
");");

createTable("create table test.tbl_int_date (" +
"`date` datetime NULL," +
"`day` date NULL," +
Expand Down Expand Up @@ -422,6 +422,7 @@ private static void createTable(String sql) throws Exception {
CreateTableStmt createTableStmt = (CreateTableStmt) UtFrameUtils.parseAndAnalyzeStmt(sql, connectContext);
Catalog.getCurrentCatalog().createTable(createTableStmt);
}

private static void createView(String sql) throws Exception {
CreateViewStmt createViewStmt = (CreateViewStmt) UtFrameUtils.parseAndAnalyzeStmt(sql, connectContext);
Catalog.getCurrentCatalog().createView(createViewStmt);
Expand Down Expand Up @@ -597,7 +598,7 @@ public void testTypeCast() throws Exception {
@Test
public void testMultiStmts() throws Exception {
String sql = "SHOW VARIABLES LIKE 'lower_case_%'; SHOW VARIABLES LIKE 'sql_mode'";
List<StatementBase>stmts = UtFrameUtils.parseAndAnalyzeStmts(sql, connectContext);
List<StatementBase> stmts = UtFrameUtils.parseAndAnalyzeStmts(sql, connectContext);
Assert.assertEquals(2, stmts.size());

sql = "SHOW VARIABLES LIKE 'lower_case_%';;;";
Expand Down Expand Up @@ -670,7 +671,7 @@ public void testCreateDbQueryPlanWithSchemaSyntax() throws Exception {
String createSchemaSql = "create schema if not exists test";
String createDbSql = "create database if not exists test";
CreateDbStmt createSchemaStmt = (CreateDbStmt) UtFrameUtils.parseAndAnalyzeStmt(createSchemaSql, connectContext);
CreateDbStmt createDbStmt = (CreateDbStmt) UtFrameUtils.parseAndAnalyzeStmt(createDbSql, connectContext);
CreateDbStmt createDbStmt = (CreateDbStmt) UtFrameUtils.parseAndAnalyzeStmt(createDbSql, connectContext);
Assert.assertEquals(createDbStmt.toSql(), createSchemaStmt.toSql());
}

Expand Down Expand Up @@ -1505,7 +1506,7 @@ public void testEmptyNode() throws Exception {
sqls.add("explain select * from baseall join bigtable as b where 1 = 2");
sqls.add("explain select * from baseall join bigtable as b on null = 2");

for (String sql: sqls) {
for (String sql : sqls) {
String explainString = UtFrameUtils.getSQLPlanOrErrorMsg(connectContext, sql);
Assert.assertTrue(explainString.contains(emptyNode));
Assert.assertFalse(explainString.contains(denseRank));
Expand Down Expand Up @@ -1714,7 +1715,7 @@ public void testCheckInvalidDate() throws Exception {
sql = "select day from tbl_int_date where day = 2020-10-30";
explainString = UtFrameUtils.getSQLPlanOrErrorMsg(connectContext, "EXPLAIN " + sql);
Assert.assertTrue(explainString.contains("Incorrect datetime value: 1980 in expression: `day` = 1980"));
//invalid date
//invalid date
sql = "select day from tbl_int_date where day = 10-30";
explainString = UtFrameUtils.getSQLPlanOrErrorMsg(connectContext, "EXPLAIN " + sql);
Assert.assertTrue(explainString.contains("Incorrect datetime value: -20 in expression: `day` = -20"));
Expand Down Expand Up @@ -1785,7 +1786,7 @@ public void testCheckInvalidDate() throws Exception {
}

@Test
public void testNullColumnViewOrderBy() throws Exception{
public void testNullColumnViewOrderBy() throws Exception {
FeConstants.runningUnitTest = true;
connectContext.setDatabase("default_cluster:test");
String sql = "select * from tbl_null_column_view where add_column is not null;";
Expand Down Expand Up @@ -1876,7 +1877,7 @@ public void testOutfile() throws Exception {
String explainStr = UtFrameUtils.getSQLPlanOrErrorMsg(connectContext, "EXPLAIN " + sql);
Assert.assertTrue(explainStr.contains("PREDICATES: `date` >= '2021-10-07 00:00:00', `date` <= '2021-10-11 00:00:00'"));
}

// Fix: issue-#7929
@Test
public void testEmptyNodeWithOuterJoinAndAnalyticFunction() throws Exception {
Expand Down Expand Up @@ -1912,7 +1913,26 @@ public void testEmptyNodeWithOuterJoinAndAnalyticFunction() throws Exception {
String explainStr = UtFrameUtils.getSQLPlanOrErrorMsg(connectContext, sql, true);
Assert.assertTrue(explainStr.contains("4:EMPTYSET"));
Assert.assertTrue(explainStr.contains("tuple ids: 0 1 5"));
}

@Ignore
// Open it after fixing issue #7971
public void testGroupingSetOutOfBoundError() throws Exception {
String createDbStmtStr = "create database issue1111;";
CreateDbStmt createDbStmt = (CreateDbStmt) UtFrameUtils.parseAndAnalyzeStmt(createDbStmtStr, connectContext);
Catalog.getCurrentCatalog().createDb(createDbStmt);
createTable("CREATE TABLE issue1111.`test1` (\n" +
" `k1` tinyint(4) NULL COMMENT \"\",\n" +
" `k2` smallint(6) NULL COMMENT \"\"\n" +
") ENGINE=OLAP\n" +
"COMMENT \"OLAP\"\n" +
"DISTRIBUTED BY HASH(`k1`) BUCKETS 1\n" +
"PROPERTIES (\n" +
"\"replication_allocation\" = \"tag.location.default: 1\"\n" +
");");
String sql = "SELECT k1 ,GROUPING(k2) FROM issue1111.test1 GROUP BY CUBE (k1) ORDER BY k1";
String explainStr = UtFrameUtils.getSQLPlanOrErrorMsg(connectContext, sql, true);
System.out.println(explainStr);
}

// --begin-- implicit cast in explain verbose
Expand Down