From f35a721e1d584237f9f1024ed7ae1cc13c7a5ceb Mon Sep 17 00:00:00 2001 From: Sergey Kosarev Date: Wed, 6 Mar 2019 20:17:41 +0300 Subject: [PATCH 1/4] debug logging queries --- .../apache/ignite/cache/query/SqlFieldsQuery.java | 1 + .../query/GridCacheDistributedQueryManager.java | 10 +++++----- .../cache/query/GridCacheLocalQueryManager.java | 4 ++-- .../cache/query/GridCacheQueryManager.java | 6 +++--- .../processors/query/h2/IgniteH2Indexing.java | 12 +++++++----- 5 files changed, 18 insertions(+), 15 deletions(-) diff --git a/modules/core/src/main/java/org/apache/ignite/cache/query/SqlFieldsQuery.java b/modules/core/src/main/java/org/apache/ignite/cache/query/SqlFieldsQuery.java index 4e12b8ca03ecc..7fc4d9c981926 100644 --- a/modules/core/src/main/java/org/apache/ignite/cache/query/SqlFieldsQuery.java +++ b/modules/core/src/main/java/org/apache/ignite/cache/query/SqlFieldsQuery.java @@ -75,6 +75,7 @@ public class SqlFieldsQuery extends Query> { private boolean lazy; /** Partitions for query */ + @GridToStringInclude private int[] parts; /** Schema. */ diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheDistributedQueryManager.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheDistributedQueryManager.java index aac1659c0fd24..fa85516d9a053 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheDistributedQueryManager.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheDistributedQueryManager.java @@ -24,6 +24,7 @@ import java.util.NoSuchElementException; import java.util.UUID; import java.util.concurrent.Callable; +import java.util.concurrent.ConcurrentHashMap; import java.util.concurrent.ConcurrentMap; import org.apache.ignite.IgniteCheckedException; import org.apache.ignite.cluster.ClusterNode; @@ -50,7 +51,6 @@ import org.apache.ignite.lang.IgniteFuture; import org.apache.ignite.lang.IgniteReducer; import org.jetbrains.annotations.Nullable; -import java.util.concurrent.ConcurrentHashMap; import static org.apache.ignite.cache.CacheMode.LOCAL; import static org.apache.ignite.events.EventType.EVT_NODE_FAILED; @@ -518,8 +518,8 @@ else if (!cancelled.contains(res.requestId())) @Override public CacheQueryFuture queryDistributed(GridCacheQueryBean qry, final Collection nodes) { assert cctx.config().getCacheMode() != LOCAL; - if (log.isDebugEnabled()) - log.debug("Executing distributed query: " + qry); + if (log.isInfoEnabled()) + log.info("Executing distributed query: " + qry); long reqId = cctx.io().nextIoId(); @@ -718,8 +718,8 @@ private Object convert(Object obj) { Collection nodes) { assert cctx.config().getCacheMode() != LOCAL; - if (log.isDebugEnabled()) - log.debug("Executing distributed query: " + qry); + if (log.isInfoEnabled()) + log.info("Executing distributed query: " + qry); long reqId = cctx.io().nextIoId(); diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheLocalQueryManager.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheLocalQueryManager.java index 147725bd6353f..75a90163b972e 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheLocalQueryManager.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheLocalQueryManager.java @@ -106,8 +106,8 @@ public class GridCacheLocalQueryManager extends GridCacheQueryManager queryFieldsLocal(GridCacheQueryBean qry) { assert cctx.config().getCacheMode() == LOCAL; - if (log.isDebugEnabled()) - log.debug("Executing query on local node: " + qry); + if (log.isInfoEnabled()) + log.info("Executing query on local node: " + qry); GridCacheLocalFieldsQueryFuture fut = new GridCacheLocalFieldsQueryFuture(cctx, qry); diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheQueryManager.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheQueryManager.java index 5d22decad4b29..b5018b18d5146 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheQueryManager.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/query/GridCacheQueryManager.java @@ -75,8 +75,8 @@ import org.apache.ignite.internal.processors.cache.IgniteInternalCache; import org.apache.ignite.internal.processors.cache.KeyCacheObject; import org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtCacheAdapter; -import org.apache.ignite.internal.processors.cache.distributed.dht.topology.GridDhtLocalPartition; import org.apache.ignite.internal.processors.cache.distributed.dht.GridDhtUnreservedPartitionException; +import org.apache.ignite.internal.processors.cache.distributed.dht.topology.GridDhtLocalPartition; import org.apache.ignite.internal.processors.cache.persistence.CacheDataRow; import org.apache.ignite.internal.processors.datastructures.DataStructuresProcessor; import org.apache.ignite.internal.processors.datastructures.GridSetQueryPredicate; @@ -449,8 +449,8 @@ public void remove(KeyCacheObject key, @Nullable CacheDataRow prevRow) throws Ig CacheQueryFuture queryLocal(GridCacheQueryBean qry) { assert qry.query().type() != GridCacheQueryType.SCAN : qry; - if (log.isDebugEnabled()) - log.debug("Executing query on local node: " + qry); + if (log.isInfoEnabled()) + log.info("Executing query on local node: " + qry); GridCacheLocalQueryFuture fut = new GridCacheLocalQueryFuture<>(cctx, qry); diff --git a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java index a848d8a7f6b03..8f718162c9df5 100644 --- a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java +++ b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java @@ -114,6 +114,7 @@ import org.apache.ignite.internal.processors.query.h2.sql.GridSqlQuerySplitter; import org.apache.ignite.internal.processors.query.h2.sql.GridSqlStatement; import org.apache.ignite.internal.processors.query.h2.sys.SqlSystemTableEngine; +import org.apache.ignite.internal.processors.query.h2.sys.view.SqlSystemView; import org.apache.ignite.internal.processors.query.h2.sys.view.SqlSystemViewBaselineNodes; import org.apache.ignite.internal.processors.query.h2.sys.view.SqlSystemViewNodeAttributes; import org.apache.ignite.internal.processors.query.h2.sys.view.SqlSystemViewNodeMetrics; @@ -121,7 +122,6 @@ import org.apache.ignite.internal.processors.query.h2.twostep.GridMapQueryExecutor; import org.apache.ignite.internal.processors.query.h2.twostep.GridReduceQueryExecutor; import org.apache.ignite.internal.processors.query.h2.twostep.MapQueryLazyWorker; -import org.apache.ignite.internal.processors.query.h2.sys.view.SqlSystemView; import org.apache.ignite.internal.processors.query.schema.SchemaIndexCacheVisitor; import org.apache.ignite.internal.processors.query.schema.SchemaIndexCacheVisitorClosure; import org.apache.ignite.internal.processors.query.schema.SchemaIndexCacheVisitorImpl; @@ -129,15 +129,14 @@ import org.apache.ignite.internal.sql.SqlParseException; import org.apache.ignite.internal.sql.SqlParser; import org.apache.ignite.internal.sql.command.SqlAlterTableCommand; -import org.apache.ignite.internal.sql.command.SqlBulkLoadCommand; import org.apache.ignite.internal.sql.command.SqlAlterUserCommand; import org.apache.ignite.internal.sql.command.SqlBulkLoadCommand; import org.apache.ignite.internal.sql.command.SqlCommand; import org.apache.ignite.internal.sql.command.SqlCreateIndexCommand; import org.apache.ignite.internal.sql.command.SqlCreateUserCommand; import org.apache.ignite.internal.sql.command.SqlDropIndexCommand; -import org.apache.ignite.internal.sql.command.SqlSetStreamingCommand; import org.apache.ignite.internal.sql.command.SqlDropUserCommand; +import org.apache.ignite.internal.sql.command.SqlSetStreamingCommand; import org.apache.ignite.internal.util.GridBoundedConcurrentLinkedHashMap; import org.apache.ignite.internal.util.GridEmptyCloseableIterator; import org.apache.ignite.internal.util.GridSpinBusyLock; @@ -1804,13 +1803,16 @@ private List>> doRunPrepared(String schemaNa } if (twoStepQry != null) { - if (log.isDebugEnabled()) - log.debug("Parsed query: `" + sqlQry + "` into two step query: " + twoStepQry); + if (log.isInfoEnabled()) + log.info("Executing distributed query: '" + qry + "' into two step query: " + twoStepQry); checkQueryType(qry, true); return Collections.singletonList(doRunDistributedQuery(schemaName, qry, twoStepQry, meta, keepBinary, cancel)); + } else { + if (log.isInfoEnabled()) + log.info("Executing query on local node: '" + qry+ "'"); } // We've encountered a local query, let's just run it. From 6caeb9c74f53f8dd7112caf962885c2ac03451eb Mon Sep 17 00:00:00 2001 From: Sergey Kosarev Date: Wed, 6 Mar 2019 20:19:59 +0300 Subject: [PATCH 2/4] debug logging queries --- .../ignite/internal/processors/query/h2/IgniteH2Indexing.java | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java index 8f718162c9df5..7e42023726361 100644 --- a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java +++ b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java @@ -1804,7 +1804,7 @@ private List>> doRunPrepared(String schemaNa if (twoStepQry != null) { if (log.isInfoEnabled()) - log.info("Executing distributed query: '" + qry + "' into two step query: " + twoStepQry); + log.info("Executing query distributed: '" + qry + "' into two step query: " + twoStepQry); checkQueryType(qry, true); @@ -1812,7 +1812,7 @@ private List>> doRunPrepared(String schemaNa cancel)); } else { if (log.isInfoEnabled()) - log.info("Executing query on local node: '" + qry+ "'"); + log.info("Executing query local: '" + qry+ "'"); } // We've encountered a local query, let's just run it. From ef41fb9499051342df9f08bf0699d8099c4f0445 Mon Sep 17 00:00:00 2001 From: Sergey Kosarev Date: Thu, 7 Mar 2019 15:56:08 +0300 Subject: [PATCH 3/4] debug logging queries 2 --- .../processors/query/h2/IgniteH2Indexing.java | 32 +++++++++++++++++++ 1 file changed, 32 insertions(+) diff --git a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java index 7e42023726361..0bc6132919086 100644 --- a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java +++ b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java @@ -140,12 +140,14 @@ import org.apache.ignite.internal.util.GridBoundedConcurrentLinkedHashMap; import org.apache.ignite.internal.util.GridEmptyCloseableIterator; import org.apache.ignite.internal.util.GridSpinBusyLock; +import org.apache.ignite.internal.util.GridStringBuilder; import org.apache.ignite.internal.util.lang.GridCloseableIterator; import org.apache.ignite.internal.util.lang.GridPlainRunnable; import org.apache.ignite.internal.util.lang.IgniteInClosure2X; import org.apache.ignite.internal.util.typedef.F; import org.apache.ignite.internal.util.typedef.internal.CU; import org.apache.ignite.internal.util.typedef.internal.LT; +import org.apache.ignite.internal.util.typedef.internal.S; import org.apache.ignite.internal.util.typedef.internal.SB; import org.apache.ignite.internal.util.typedef.internal.U; import org.apache.ignite.lang.IgniteBiClosure; @@ -165,6 +167,7 @@ import org.h2.engine.Session; import org.h2.engine.SysProperties; import org.h2.index.Index; +import org.h2.jdbc.JdbcResultSet; import org.h2.jdbc.JdbcStatement; import org.h2.server.web.WebServer; import org.h2.table.IndexColumn; @@ -1253,8 +1256,24 @@ private ResultSet executeSqlQueryWithTimer(PreparedStatement stmt, Connection co long start = U.currentTimeMillis(); try { + + if (log.isInfoEnabled()) { + String msg = "Executing query sql=" + sql + sql + '\'' + + ", parameters=" + (params == null ? "[]" : Arrays.deepToString(params.toArray())) + "]" + + ", lazy=" + (MapQueryLazyWorker.currentWorker() != null) ; + + log.info(msg); + } + ResultSet rs = executeSqlQuery(conn, stmt, timeoutMillis, cancel); + if (log.isInfoEnabled()) { + if (rs instanceof JdbcResultSet) + log.info(" ResultSet: " + S.toString(JdbcResultSet.class, (JdbcResultSet)rs)); + else + log.info(" ResultSet class: " + rs.getClass()); + } + long time = U.currentTimeMillis() - start; long longQryExecTimeout = ctx.config().getLongQueryWarningTimeout(); @@ -1302,6 +1321,19 @@ public void bindParameters(PreparedStatement stmt, /** {@inheritDoc} */ @Override public FieldsQueryCursor> queryLocalSqlFields(String schemaName, SqlFieldsQuery qry, final boolean keepBinary, IndexingQueryFilter filter, GridQueryCancel cancel) throws IgniteCheckedException { + + if (log.isInfoEnabled()) { + GridStringBuilder sb = new GridStringBuilder("Local query stack trace:"); + + U.printStackTrace( + Thread.currentThread().getId(), + sb); + + String msg = sb.toString(); + + log.info(msg); + } + String sql = qry.getSql(); Object[] args = qry.getArgs(); From 5844b6bb75a577d11af49d9f6fad71ed720e51dc Mon Sep 17 00:00:00 2001 From: Sergey Kosarev Date: Thu, 7 Mar 2019 16:17:47 +0300 Subject: [PATCH 4/4] debug logging queries 2 --- .../ignite/internal/processors/query/h2/IgniteH2Indexing.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java index 0bc6132919086..581fe7d90fe28 100644 --- a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java +++ b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/IgniteH2Indexing.java @@ -1258,7 +1258,7 @@ private ResultSet executeSqlQueryWithTimer(PreparedStatement stmt, Connection co try { if (log.isInfoEnabled()) { - String msg = "Executing query sql=" + sql + sql + '\'' + + String msg = "Executing query sql=" + sql + '\'' + ", parameters=" + (params == null ? "[]" : Arrays.deepToString(params.toArray())) + "]" + ", lazy=" + (MapQueryLazyWorker.currentWorker() != null) ;