Updated Branches: refs/heads/trunk f725ed139 -> a37c2564f
update tracing messages for index scans Project: http://git-wip-us.apache.org/repos/asf/cassandra/repo Commit: http://git-wip-us.apache.org/repos/asf/cassandra/commit/a37c2564 Tree: http://git-wip-us.apache.org/repos/asf/cassandra/tree/a37c2564 Diff: http://git-wip-us.apache.org/repos/asf/cassandra/diff/a37c2564 Branch: refs/heads/trunk Commit: a37c2564f80af99f5652c621d12dfc8c96e4c2f0 Parents: f725ed1 Author: Jonathan Ellis <[email protected]> Authored: Sat Nov 3 09:51:23 2012 -0500 Committer: Jonathan Ellis <[email protected]> Committed: Sat Nov 3 10:26:22 2012 -0500 ---------------------------------------------------------------------- .../org/apache/cassandra/db/ColumnFamilyStore.java | 6 +++- .../apache/cassandra/db/filter/ExtendedFilter.java | 4 +- .../db/index/composites/CompositesSearcher.java | 14 +++++---- .../cassandra/db/index/keys/KeysSearcher.java | 24 +++++++------- 4 files changed, 27 insertions(+), 21 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/cassandra/blob/a37c2564/src/java/org/apache/cassandra/db/ColumnFamilyStore.java ---------------------------------------------------------------------- diff --git a/src/java/org/apache/cassandra/db/ColumnFamilyStore.java b/src/java/org/apache/cassandra/db/ColumnFamilyStore.java index 8740c8d..b212a1c 100644 --- a/src/java/org/apache/cassandra/db/ColumnFamilyStore.java +++ b/src/java/org/apache/cassandra/db/ColumnFamilyStore.java @@ -1458,17 +1458,18 @@ public class ColumnFamilyStore implements ColumnFamilyStoreMBean logger.trace("Filtering {} for rows matching {}", rowIterator, filter); List<Row> rows = new ArrayList<Row>(); int columnsCount = 0; + int total = 0, matched = 0; try { while (rowIterator.hasNext() && rows.size() < filter.maxRows() && columnsCount < filter.maxColumns()) { // get the raw columns requested, and additional columns for the expressions if necessary Row rawRow = rowIterator.next(); + total++; ColumnFamily data = rawRow.cf; if (rowIterator.needsFiltering()) { - // roughtly IDiskAtomFilter extraFilter = filter.getExtraFilter(data); if (extraFilter != null) { @@ -1487,12 +1488,15 @@ public class ColumnFamilyStore implements ColumnFamilyStoreMBean } rows.add(new Row(rawRow.key, data)); + matched++; if (data != null) columnsCount += filter.lastCounted(data); // Update the underlying filter to avoid querying more columns per slice than necessary and to handle paging filter.updateFilter(columnsCount); } + + logger.debug("Scanned {} rows and matched {}", total, matched); return rows; } finally http://git-wip-us.apache.org/repos/asf/cassandra/blob/a37c2564/src/java/org/apache/cassandra/db/filter/ExtendedFilter.java ---------------------------------------------------------------------- diff --git a/src/java/org/apache/cassandra/db/filter/ExtendedFilter.java b/src/java/org/apache/cassandra/db/filter/ExtendedFilter.java index 89479c9..65c4563 100644 --- a/src/java/org/apache/cassandra/db/filter/ExtendedFilter.java +++ b/src/java/org/apache/cassandra/db/filter/ExtendedFilter.java @@ -182,7 +182,7 @@ public abstract class ExtendedFilter // otherwise, the extraFilter (lazily created) will fetch by name the columns referenced by the additional expressions. if (cfs.getMaxRowSize() < DatabaseDescriptor.getColumnIndexSize()) { - logger.debug("Expanding slice filter to entire row to cover additional expressions"); + logger.trace("Expanding slice filter to entire row to cover additional expressions"); return new SliceQueryFilter(ByteBufferUtil.EMPTY_BYTE_BUFFER, ByteBufferUtil.EMPTY_BYTE_BUFFER, ((SliceQueryFilter) originalFilter).reversed, @@ -191,7 +191,7 @@ public abstract class ExtendedFilter } else { - logger.debug("adding columns to original Filter to cover additional expressions"); + logger.trace("adding columns to original Filter to cover additional expressions"); assert originalFilter instanceof NamesQueryFilter; if (!clause.isEmpty()) { http://git-wip-us.apache.org/repos/asf/cassandra/blob/a37c2564/src/java/org/apache/cassandra/db/index/composites/CompositesSearcher.java ---------------------------------------------------------------------- diff --git a/src/java/org/apache/cassandra/db/index/composites/CompositesSearcher.java b/src/java/org/apache/cassandra/db/index/composites/CompositesSearcher.java index 8327154..d16b759 100644 --- a/src/java/org/apache/cassandra/db/index/composites/CompositesSearcher.java +++ b/src/java/org/apache/cassandra/db/index/composites/CompositesSearcher.java @@ -91,6 +91,8 @@ public class CompositesSearcher extends SecondaryIndexSearcher // TODO: allow merge join instead of just one index + loop final IndexExpression primary = highestSelectivityPredicate(filter.getClause()); final SecondaryIndex index = indexManager.getIndexForColumn(primary.column_name); + if (logger.isDebugEnabled()) + logger.debug("Most-selective indexed predicate is on {}", baseCfs.getComparator().getString(primary.column_name)); assert index != null; final DecoratedKey indexKey = index.getIndexKeyFor(primary.value); @@ -204,7 +206,7 @@ public class CompositesSearcher extends SecondaryIndexSearcher { if (columnsRead < rowsPerQuery) { - logger.debug("Read only {} (< {}) last page through, must be done", columnsRead, rowsPerQuery); + logger.trace("Read only {} (< {}) last page through, must be done", columnsRead, rowsPerQuery); return makeReturn(currentKey, data); } @@ -233,13 +235,13 @@ public class CompositesSearcher extends SecondaryIndexSearcher { // skip the row we already saw w/ the last page of results indexColumns.poll(); - logger.debug("Skipping {}", indexComparator.getString(firstColumn.name())); + logger.trace("Skipping {}", indexComparator.getString(firstColumn.name())); } else if (range instanceof Range && !indexColumns.isEmpty() && firstColumn.name().equals(startPrefix)) { // skip key excluded by range indexColumns.poll(); - logger.debug("Skipping first key as range excludes it"); + logger.trace("Skipping first key as range excludes it"); } } @@ -249,7 +251,7 @@ public class CompositesSearcher extends SecondaryIndexSearcher lastSeenPrefix = column.name(); if (column.isMarkedForDelete()) { - logger.debug("skipping {}", column.name()); + logger.trace("skipping {}", column.name()); continue; } @@ -276,7 +278,7 @@ public class CompositesSearcher extends SecondaryIndexSearcher if (!range.right.isMinimum(baseCfs.partitioner) && range.right.compareTo(dk) < 0) { - logger.debug("Reached end of assigned scan range"); + logger.trace("Reached end of assigned scan range"); return endOfData(); } if (!range.contains(dk)) @@ -285,7 +287,7 @@ public class CompositesSearcher extends SecondaryIndexSearcher continue; } - logger.debug("Adding index hit to current row for {}", indexComparator.getString(lastSeenPrefix)); + logger.trace("Adding index hit to current row for {}", indexComparator.getString(lastSeenPrefix)); // For sparse composites, we're good querying the whole logical row // Obviously if this index is used for other usage, that might be inefficient CompositeType.Builder builder = baseComparator.builder(); http://git-wip-us.apache.org/repos/asf/cassandra/blob/a37c2564/src/java/org/apache/cassandra/db/index/keys/KeysSearcher.java ---------------------------------------------------------------------- diff --git a/src/java/org/apache/cassandra/db/index/keys/KeysSearcher.java b/src/java/org/apache/cassandra/db/index/keys/KeysSearcher.java index 5d7adfe..590f629 100644 --- a/src/java/org/apache/cassandra/db/index/keys/KeysSearcher.java +++ b/src/java/org/apache/cassandra/db/index/keys/KeysSearcher.java @@ -98,7 +98,7 @@ public class KeysSearcher extends SecondaryIndexSearcher final IndexExpression primary = highestSelectivityPredicate(filter.getClause()); final SecondaryIndex index = indexManager.getIndexForColumn(primary.column_name); if (logger.isDebugEnabled()) - logger.debug("Primary scan clause is " + baseCfs.getComparator().getString(primary.column_name)); + logger.debug("Most-selective indexed predicate is on {}", baseCfs.getComparator().getString(primary.column_name)); assert index != null; final DecoratedKey indexKey = index.getIndexKeyFor(primary.value); @@ -129,12 +129,12 @@ public class KeysSearcher extends SecondaryIndexSearcher { if (columnsRead < rowsPerQuery) { - logger.debug("Read only {} (< {}) last page through, must be done", columnsRead, rowsPerQuery); + logger.trace("Read only {} (< {}) last page through, must be done", columnsRead, rowsPerQuery); return endOfData(); } - if (logger.isDebugEnabled()) - logger.debug("Scanning index {} starting with {}", + if (logger.isTraceEnabled()) + logger.trace("Scanning index {} starting with {}", expressionString(primary), index.getBaseCfs().metadata.getKeyValidator().getString(startKey)); QueryFilter indexFilter = QueryFilter.getSliceFilter(indexKey, @@ -144,10 +144,10 @@ public class KeysSearcher extends SecondaryIndexSearcher false, rowsPerQuery); ColumnFamily indexRow = index.getIndexCfs().getColumnFamily(indexFilter); - logger.debug("fetched {}", indexRow); + logger.trace("fetched {}", indexRow); if (indexRow == null) { - logger.debug("no data, all done"); + logger.trace("no data, all done"); return endOfData(); } @@ -161,13 +161,13 @@ public class KeysSearcher extends SecondaryIndexSearcher { // skip the row we already saw w/ the last page of results indexColumns.next(); - logger.debug("Skipping {}", baseCfs.metadata.getKeyValidator().getString(firstColumn.name())); + logger.trace("Skipping {}", baseCfs.metadata.getKeyValidator().getString(firstColumn.name())); } else if (range instanceof Range && indexColumns.hasNext() && firstColumn.name().equals(startKey)) { // skip key excluded by range indexColumns.next(); - logger.debug("Skipping first key as range excludes it"); + logger.trace("Skipping first key as range excludes it"); } } @@ -177,23 +177,23 @@ public class KeysSearcher extends SecondaryIndexSearcher lastSeenKey = column.name(); if (column.isMarkedForDelete()) { - logger.debug("skipping {}", column.name()); + logger.trace("skipping {}", column.name()); continue; } DecoratedKey dk = baseCfs.partitioner.decorateKey(lastSeenKey); if (!range.right.isMinimum(baseCfs.partitioner) && range.right.compareTo(dk) < 0) { - logger.debug("Reached end of assigned scan range"); + logger.trace("Reached end of assigned scan range"); return endOfData(); } if (!range.contains(dk)) { - logger.debug("Skipping entry {} outside of assigned scan range", dk.token); + logger.trace("Skipping entry {} outside of assigned scan range", dk.token); continue; } - logger.debug("Returning index hit for {}", dk); + logger.trace("Returning index hit for {}", dk); ColumnFamily data = baseCfs.getColumnFamily(new QueryFilter(dk, path, filter.initialFilter())); // While the column family we'll get in the end should contains the primary clause column, the initialFilter may not have found it and can thus be null if (data == null)
