This is an automated email from the ASF dual-hosted git repository. mmuzaf pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/ignite.git
The following commit(s) were added to refs/heads/master by this push: new f17a4cb IGNITE-13456 Extends info collected during tracing of SQL queries. (#8393) f17a4cb is described below commit f17a4cbb16d134ed207a750949b3cd981b55becd Author: Mikhail Petrov <32207922+ololo3...@users.noreply.github.com> AuthorDate: Tue Dec 29 12:34:01 2020 +0300 IGNITE-13456 Extends info collected during tracing of SQL queries. (#8393) --- .../dht/topology/GridDhtPartitionsReservation.java | 9 ++ .../internal/processors/tracing/SpanTags.java | 3 + .../internal/processors/query/h2/QueryParser.java | 5 ++ .../h2/twostep/PartitionReservationManager.java | 10 +++ .../monitoring/opencensus/AbstractTracingTest.java | 6 ++ .../opencensus/OpenCensusSqlJdbcTracingTest.java | 2 +- .../opencensus/OpenCensusSqlNativeTracingTest.java | 95 +++++++++++++++++----- 7 files changed, 109 insertions(+), 21 deletions(-) diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/topology/GridDhtPartitionsReservation.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/topology/GridDhtPartitionsReservation.java index 8e975f8..d522eb4 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/topology/GridDhtPartitionsReservation.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/cache/distributed/dht/topology/GridDhtPartitionsReservation.java @@ -26,6 +26,7 @@ import org.apache.ignite.internal.processors.cache.GridCacheContext; import org.apache.ignite.internal.processors.cache.distributed.dht.GridReservable; import org.apache.ignite.internal.util.typedef.CI1; import org.apache.ignite.internal.util.typedef.F; +import org.apache.ignite.internal.util.typedef.internal.S; /** * Reservation mechanism for multiple partitions allowing to do a reservation in one operation. @@ -281,4 +282,12 @@ public class GridDhtPartitionsReservation implements GridReservable { return result; } + + /** {@inheritDoc} */ + @Override public String toString() { + return S.toString(null, + "cache", cctx.name(), false, + "partitions", Arrays.toString(parts.get()), false, + "topology", topVer.toString(), false); + } } diff --git a/modules/core/src/main/java/org/apache/ignite/internal/processors/tracing/SpanTags.java b/modules/core/src/main/java/org/apache/ignite/internal/processors/tracing/SpanTags.java index 75c3a23..c2f37a6 100644 --- a/modules/core/src/main/java/org/apache/ignite/internal/processors/tracing/SpanTags.java +++ b/modules/core/src/main/java/org/apache/ignite/internal/processors/tracing/SpanTags.java @@ -105,6 +105,9 @@ public class SpanTags { /** Number of cache entries to be updated as a result of DML query. */ public static final String SQL_CACHE_UPDATES = "sql.cache.updates"; + /** Whether parsing of the SQL query was skipped due to the cached result. */ + public static final String SQL_PARSER_CACHE_HIT = "sql.parser.cache.hit"; + /** */ private SpanTags() {} diff --git a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/QueryParser.java b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/QueryParser.java index 751cb80..b1e5bd1 100644 --- a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/QueryParser.java +++ b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/QueryParser.java @@ -84,6 +84,7 @@ import org.h2.command.Prepared; import org.jetbrains.annotations.Nullable; import static org.apache.ignite.internal.processors.query.h2.sql.GridSqlQuerySplitter.keyColumn; +import static org.apache.ignite.internal.processors.tracing.SpanTags.SQL_PARSER_CACHE_HIT; import static org.apache.ignite.internal.processors.tracing.SpanType.SQL_QRY_PARSE; /** @@ -204,6 +205,8 @@ public class QueryParser { if (cached != null) { metricsHolder.countCacheHit(); + MTC.span().addTag(SQL_PARSER_CACHE_HIT, () -> "true"); + return new QueryParserResult( qryDesc, queryParameters(qry), @@ -217,6 +220,8 @@ public class QueryParser { metricsHolder.countCacheMiss(); + MTC.span().addTag(SQL_PARSER_CACHE_HIT, () -> "false"); + // Try parsing as native command. QueryParserResult parseRes = parseNative(schemaName, qry, remainingAllowed); diff --git a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/twostep/PartitionReservationManager.java b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/twostep/PartitionReservationManager.java index d7c9dba..4c7f351 100644 --- a/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/twostep/PartitionReservationManager.java +++ b/modules/indexing/src/main/java/org/apache/ignite/internal/processors/query/h2/twostep/PartitionReservationManager.java @@ -158,6 +158,8 @@ public class PartitionReservationManager implements PartitionsExchangeAware { "cacheName=%s]", ctx.localNodeId(), nodeId, reqId, topVer, cacheIds.get(i), cctx.name())); reserved.add(r); + + MTC.span().addLog(() -> "Cache partitions were reserved " + r); } } else { // Try to reserve partitions one by one. @@ -191,6 +193,9 @@ public class PartitionReservationManager implements PartitionsExchangeAware { // Mark that we checked this replicated cache. reservations.putIfAbsent(grpKey, REPLICATED_RESERVABLE); + + MTC.span().addLog(() -> "Cache partitions were reserved [cache=" + cctx.name() + + ", partitions=[0.." + partsCnt + ']'); } } else { // Reserve primary partitions for partitioned cache (if no explicit given). @@ -273,6 +278,11 @@ public class PartitionReservationManager implements PartitionsExchangeAware { } } + final Collection<Integer> finalPartIds = partIds; + + MTC.span().addLog(() -> "Cache partitions were reserved [cache=" + cctx.name() + + ", partitions=" + finalPartIds + ", topology=" + topVer + ']'); + if (explicitParts == null && reservedCnt > 0) { // We reserved all the primary partitions for cache, attempt to add group reservation. GridDhtPartitionsReservation grp = new GridDhtPartitionsReservation(topVer, cctx, "SQL"); diff --git a/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/AbstractTracingTest.java b/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/AbstractTracingTest.java index 007e821..450ed81 100644 --- a/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/AbstractTracingTest.java +++ b/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/AbstractTracingTest.java @@ -402,5 +402,11 @@ public abstract class AbstractTracingTest extends GridCommonAbstractTest { span.end(); } } + + /** Clears collected spans. */ + void clearCollectedSpans() { + collectedSpans.clear(); + collectedSpansByParents.clear(); + } } } diff --git a/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/OpenCensusSqlJdbcTracingTest.java b/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/OpenCensusSqlJdbcTracingTest.java index fe9aa1a..a324ada 100644 --- a/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/OpenCensusSqlJdbcTracingTest.java +++ b/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/OpenCensusSqlJdbcTracingTest.java @@ -81,7 +81,7 @@ public class OpenCensusSqlJdbcTracingTest extends OpenCensusSqlNativeTracingTest checkChildSpan(SQL_QRY_EXECUTE, iterSpan); int fetchedRows = findChildSpans(SQL_PAGE_FETCH, rootSpan).stream() - .mapToInt(span -> getAttribute(span, SQL_PAGE_ROWS)) + .mapToInt(span -> Integer.parseInt(getAttribute(span, SQL_PAGE_ROWS))) .sum(); assertEquals(TEST_TABLE_POPULATION, fetchedRows); diff --git a/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/OpenCensusSqlNativeTracingTest.java b/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/OpenCensusSqlNativeTracingTest.java index d48f91c..9698329 100644 --- a/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/OpenCensusSqlNativeTracingTest.java +++ b/modules/opencensus/src/test/java/org/apache/ignite/internal/processors/monitoring/opencensus/OpenCensusSqlNativeTracingTest.java @@ -17,14 +17,21 @@ package org.apache.ignite.internal.processors.monitoring.opencensus; +import java.util.Arrays; import java.util.List; +import java.util.Set; +import java.util.UUID; import java.util.concurrent.atomic.AtomicInteger; +import java.util.regex.Matcher; +import java.util.regex.Pattern; import java.util.stream.Collectors; import com.google.common.collect.ImmutableMap; import io.opencensus.trace.SpanId; import io.opencensus.trace.Tracing; +import org.apache.ignite.Ignite; import org.apache.ignite.IgniteCache; import org.apache.ignite.IgniteCheckedException; +import org.apache.ignite.Ignition; import org.apache.ignite.cache.CacheMode; import org.apache.ignite.cache.query.SqlFieldsQuery; import org.apache.ignite.cache.query.annotations.QuerySqlField; @@ -44,7 +51,9 @@ import org.apache.ignite.spi.tracing.opencensus.OpenCensusTracingSpi; import org.apache.ignite.testframework.GridTestUtils; import org.junit.Test; +import static java.lang.Boolean.parseBoolean; import static java.lang.Integer.parseInt; +import static java.util.regex.Pattern.compile; import static org.apache.ignite.cache.CacheMode.PARTITIONED; import static org.apache.ignite.internal.TestRecordingCommunicationSpi.spi; import static org.apache.ignite.internal.processors.query.QueryUtils.DFLT_SCHEMA; @@ -55,6 +64,7 @@ import static org.apache.ignite.internal.processors.tracing.SpanTags.NODE_ID; import static org.apache.ignite.internal.processors.tracing.SpanTags.SQL_CACHE_UPDATES; import static org.apache.ignite.internal.processors.tracing.SpanTags.SQL_IDX_RANGE_ROWS; import static org.apache.ignite.internal.processors.tracing.SpanTags.SQL_PAGE_ROWS; +import static org.apache.ignite.internal.processors.tracing.SpanTags.SQL_PARSER_CACHE_HIT; import static org.apache.ignite.internal.processors.tracing.SpanTags.SQL_QRY_TEXT; import static org.apache.ignite.internal.processors.tracing.SpanTags.SQL_SCHEMA; import static org.apache.ignite.internal.processors.tracing.SpanTags.tag; @@ -160,13 +170,13 @@ public class OpenCensusSqlNativeTracingTest extends AbstractTracingTest { checkChildSpan(SQL_QRY_EXECUTE, iterSpan); fetchedRows += findChildSpans(SQL_PAGE_FETCH, execReqSpan).stream() - .mapToInt(span -> getAttribute(span, SQL_PAGE_ROWS)) + .mapToInt(span -> parseInt(getAttribute(span, SQL_PAGE_ROWS))) .sum(); List<SpanId> cacheUpdateSpans = findChildSpans(SQL_CACHE_UPDATE, execReqSpan); cacheUpdates += cacheUpdateSpans.stream() - .mapToInt(span -> getAttribute(span, SQL_CACHE_UPDATES)) + .mapToInt(span -> parseInt(getAttribute(span, SQL_CACHE_UPDATES))) .sum(); checkChildSpan(SQL_ITER_CLOSE, execReqSpan); @@ -287,41 +297,65 @@ public class OpenCensusSqlNativeTracingTest extends AbstractTracingTest { for (int i = 0; i < GRID_CNT; i++) { SpanId execReqSpan = execReqSpans.get(i); - checkChildSpan(SQL_PARTITIONS_RESERVE, execReqSpan); + Ignite ignite = Ignition.ignite(UUID.fromString(getAttribute(execReqSpan, NODE_ID))); + + SpanId partsReserveSpan = checkChildSpan(SQL_PARTITIONS_RESERVE, execReqSpan); + + List<String> partsReserveLogs = handler().spanById(partsReserveSpan).getAnnotations().getEvents().stream() + .map(e -> e.getEvent().getDescription()) + .collect(Collectors.toList()); + + assertEquals(2, partsReserveLogs.size()); + + Pattern ptrn = compile("Cache partitions were reserved \\[cache=(.+), partitions=\\[(.+)], topology=(.+)]"); + + partsReserveLogs.forEach(l -> { + Matcher matcher = ptrn.matcher(l); + + assertTrue(matcher.matches()); + + Set<Integer> expParts = Arrays.stream(ignite.affinity(matcher.group(1)) + .primaryPartitions(ignite.cluster().localNode()) + ).boxed().collect(Collectors.toSet()); + + Set<Integer> parts = Arrays.stream(matcher.group(2).split(",")) + .map(s -> Integer.parseInt(s.trim())) + .collect(Collectors.toSet()); + + assertEquals(expParts, parts); + }); SpanId execSpan = checkChildSpan(SQL_QRY_EXECUTE, execReqSpan); List<SpanId> distrLookupReqSpans = findChildSpans(SQL_IDX_RANGE_REQ, execSpan); for (SpanId span : distrLookupReqSpans) { - idxRangeReqRows += getAttribute(span, SQL_IDX_RANGE_ROWS); + idxRangeReqRows += parseInt(getAttribute(span, SQL_IDX_RANGE_ROWS)); checkChildSpan(SQL_IDX_RANGE_RESP, span); } - preparedRows += getAttribute( - checkChildSpan(SQL_PAGE_PREPARE, execReqSpan), SQL_PAGE_ROWS); + preparedRows += parseInt(getAttribute(checkChildSpan(SQL_PAGE_PREPARE, execReqSpan), SQL_PAGE_ROWS)); checkChildSpan(SQL_PAGE_RESP, execReqSpan); } SpanId pageFetchSpan = checkChildSpan(SQL_PAGE_FETCH, iterSpan); - fetchedRows += getAttribute(pageFetchSpan, SQL_PAGE_ROWS); + fetchedRows += parseInt(getAttribute(pageFetchSpan, SQL_PAGE_ROWS)); checkChildSpan(SQL_PAGE_WAIT, pageFetchSpan); SpanId nexPageSpan = checkChildSpan(SQL_NEXT_PAGE_REQ, pageFetchSpan); - preparedRows += getAttribute( - checkChildSpan(SQL_PAGE_PREPARE, nexPageSpan), SQL_PAGE_ROWS); + preparedRows += parseInt(getAttribute(checkChildSpan(SQL_PAGE_PREPARE, nexPageSpan), SQL_PAGE_ROWS)); checkChildSpan(SQL_PAGE_RESP, nexPageSpan); List<SpanId> pageFetchSpans = findChildSpans(SQL_PAGE_FETCH, rootSpan); for (SpanId span : pageFetchSpans) { - fetchedRows += getAttribute(span, SQL_PAGE_ROWS); + fetchedRows += parseInt(getAttribute(span, SQL_PAGE_ROWS)); checkChildSpan(SQL_PAGE_WAIT, span); @@ -332,8 +366,7 @@ public class OpenCensusSqlNativeTracingTest extends AbstractTracingTest { SpanId nextPageSpan = nextPageSpans.get(0); - preparedRows += getAttribute( - checkChildSpan(SQL_PAGE_PREPARE, nextPageSpan), SQL_PAGE_ROWS); + preparedRows += parseInt(getAttribute(checkChildSpan(SQL_PAGE_PREPARE, nextPageSpan), SQL_PAGE_ROWS)); checkChildSpan(SQL_PAGE_RESP, nextPageSpan); } @@ -364,9 +397,9 @@ public class OpenCensusSqlNativeTracingTest extends AbstractTracingTest { SpanId iterOpenSpan = checkChildSpan(SQL_ITER_OPEN, rootSpan); - List<SpanId> qryExecspans = findChildSpans(SQL_QRY_EXEC_REQ, iterOpenSpan); + List<SpanId> qryExecSpans = findChildSpans(SQL_QRY_EXEC_REQ, iterOpenSpan); - assertEquals(GRID_CNT * qryParallelism, qryExecspans.size()); + assertEquals(GRID_CNT * qryParallelism, qryExecSpans.size()); } /** @@ -433,6 +466,28 @@ public class OpenCensusSqlNativeTracingTest extends AbstractTracingTest { checkChildSpan(SQL_CMD_QRY_EXECUTE, rootSpan); } + /** Tests SQL parser cache hit tag. */ + @Test + public void testParserCacheHitTag() throws Exception { + String prsnTable = createTableAndPopulate(Person.class, PARTITIONED, 1); + + SpanId rootSpan = executeAndCheckRootSpan("SELECT * FROM " + prsnTable, + TEST_SCHEMA, false, false, true); + + SpanId qryParseSpan = checkChildSpan(SQL_QRY_PARSE, rootSpan); + + assertFalse(parseBoolean(getAttribute(qryParseSpan, SQL_PARSER_CACHE_HIT))); + + handler().clearCollectedSpans(); + + rootSpan = executeAndCheckRootSpan("SELECT * FROM " + prsnTable, + TEST_SCHEMA, false, false, true); + + qryParseSpan = checkChildSpan(SQL_QRY_PARSE, rootSpan); + + assertTrue(parseBoolean(getAttribute(qryParseSpan, SQL_PARSER_CACHE_HIT))); + } + /** * Executes DML query and checks corresponding span tree. * @@ -450,14 +505,14 @@ public class OpenCensusSqlNativeTracingTest extends AbstractTracingTest { checkChildSpan(SQL_ITER_OPEN, dmlExecSpan); int fetchedRows = findChildSpans(SQL_PAGE_FETCH, null).stream() - .mapToInt(span -> getAttribute(span, SQL_PAGE_ROWS)) + .mapToInt(span -> parseInt(getAttribute(span, SQL_PAGE_ROWS))) .sum(); assertEquals(expCacheUpdates, fetchedRows); } int cacheUpdates = findChildSpans(SQL_CACHE_UPDATE, dmlExecSpan).stream() - .mapToInt(span -> getAttribute(span, SQL_CACHE_UPDATES)) + .mapToInt(span -> parseInt(getAttribute(span, SQL_CACHE_UPDATES))) .sum(); assertEquals(expCacheUpdates, cacheUpdates); @@ -491,18 +546,18 @@ public class OpenCensusSqlNativeTracingTest extends AbstractTracingTest { } /** - * Obtains integer value of the attribtute from span with specified id. + * Obtains string representation of the attribtute from span with specified id. * * @param spanId Id of the target span. * @param tag Tag of the attribute. * @return Value of the attribute. */ - protected int getAttribute(SpanId spanId, String tag) { - return parseInt(attributeValueToString(handler() + protected String getAttribute(SpanId spanId, String tag) { + return attributeValueToString(handler() .spanById(spanId) .getAttributes() .getAttributeMap() - .get(tag))); + .get(tag)); } /**