You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@accumulo.apache.org by ed...@apache.org on 2019/09/06 18:57:48 UTC
[accumulo] branch 1.9 updated: Fix #1338 Reduce verbose logging of
merge operations in Master log
This is an automated email from the ASF dual-hosted git repository.
edcoleman pushed a commit to branch 1.9
in repository https://gitbox.apache.org/repos/asf/accumulo.git
The following commit(s) were added to refs/heads/1.9 by this push:
new 626a408 Fix #1338 Reduce verbose logging of merge operations in Master log
626a408 is described below
commit 626a408141fab77cf53ff0419c7845142709d5bb
Author: EdColeman <de...@etcoleman.com>
AuthorDate: Fri Sep 6 14:57:43 2019 -0400
Fix #1338 Reduce verbose logging of merge operations in Master log
* reduce merge operations logging of extent info at debug level - issue #1338.
* minor cleanup removed always true param
* address comments, clean-up of MergeStats to use substition.
* code cleanup and logging changes for discussion
* code cleanup and logging changes for discussion
- address review comments
- merge changes m.miller removing unused code in TableGroupWatcher
* Stop logging during merges
* address review comments
* clarify comment after clean-up removed empty else clause.
---
.../java/org/apache/accumulo/master/Master.java | 9 ++-
.../apache/accumulo/master/TabletGroupWatcher.java | 39 +++++-----
.../apache/accumulo/master/state/MergeStats.java | 83 +++++++++++-----------
server/master/src/main/spotbugs/exclude-filter.xml | 5 ++
4 files changed, 74 insertions(+), 62 deletions(-)
diff --git a/server/master/src/main/java/org/apache/accumulo/master/Master.java b/server/master/src/main/java/org/apache/accumulo/master/Master.java
index 4e8ef48..47e45b3 100644
--- a/server/master/src/main/java/org/apache/accumulo/master/Master.java
+++ b/server/master/src/main/java/org/apache/accumulo/master/Master.java
@@ -872,8 +872,11 @@ public class Master extends AccumuloServerContext
}
// Handle merge transitions
if (mergeInfo.getExtent() != null) {
- log.debug("mergeInfo overlaps: " + extent + " " + mergeInfo.overlaps(extent));
- if (mergeInfo.overlaps(extent)) {
+
+ final boolean overlaps = mergeInfo.overlaps(extent);
+
+ if (overlaps) {
+ log.debug("mergeInfo overlaps: {} true", extent);
switch (mergeInfo.getState()) {
case NONE:
case COMPLETE:
@@ -895,6 +898,8 @@ public class Master extends AccumuloServerContext
case MERGING:
return TabletGoalState.UNASSIGNED;
}
+ } else {
+ log.trace("mergeInfo overlaps: {} false", extent);
}
}
diff --git a/server/master/src/main/java/org/apache/accumulo/master/TabletGroupWatcher.java b/server/master/src/main/java/org/apache/accumulo/master/TabletGroupWatcher.java
index 6c98f72..4880ff4 100644
--- a/server/master/src/main/java/org/apache/accumulo/master/TabletGroupWatcher.java
+++ b/server/master/src/main/java/org/apache/accumulo/master/TabletGroupWatcher.java
@@ -100,7 +100,7 @@ import com.google.common.collect.Iterators;
abstract class TabletGroupWatcher extends Daemon {
// Constants used to make sure assignment logging isn't excessive in quantity or size
private static final String ASSIGNMENT_BUFFER_SEPARATOR = ", ";
- private static final int ASSINGMENT_BUFFER_MAX_LENGTH = 4096;
+ private static final int ASSIGNMENT_BUFFER_MAX_LENGTH = 4096;
private final Master master;
private final TabletStateStore store;
@@ -194,7 +194,12 @@ abstract class TabletGroupWatcher extends Daemon {
if (tls == null) {
continue;
}
- Master.log.debug(store.name() + " location State: " + tls);
+
+ // this can get spammy during merges
+ if (currentMerges.isEmpty()) {
+ Master.log.debug("{} location State: {}", store.name(), tls);
+ }
+
// ignore entries for tables that do not exist in zookeeper
if (TableManager.getInstance().getTableState(tls.extent.getTableId()) == null)
continue;
@@ -288,9 +293,9 @@ abstract class TabletGroupWatcher extends Daemon {
// Old tablet server is back. Return this tablet to its previous owner.
if (returnInstance != null) {
assignments.add(new Assignment(tls.extent, returnInstance));
- } else {
- // leave suspended, don't ask for a new assignment.
}
+ // else - tablet server not back. Don't ask for a new assignment right now.
+
} else {
// Treat as unassigned, ask for a new assignment.
unassigned.put(tls.extent, server);
@@ -301,7 +306,7 @@ abstract class TabletGroupWatcher extends Daemon {
TServerInstance dest = this.master.migrations.get(tls.extent);
if (dest != null) {
// if destination is still good, assign it
- if (destinations.keySet().contains(dest)) {
+ if (destinations.containsKey(dest)) {
assignments.add(new Assignment(tls.extent, dest));
} else {
// get rid of this migration
@@ -566,7 +571,8 @@ abstract class TabletGroupWatcher extends Daemon {
} else {
mergeMetadataRecords(stats.getMergeInfo());
}
- this.master.setMergeState(stats.getMergeInfo(), update = MergeState.COMPLETE);
+ update = MergeState.COMPLETE;
+ this.master.setMergeState(stats.getMergeInfo(), update);
} catch (Exception ex) {
Master.log.error("Unable merge metadata table records", ex);
}
@@ -693,12 +699,16 @@ abstract class TabletGroupWatcher extends Daemon {
targetSystemTable = RootTable.NAME;
}
- BatchWriter bw = null;
+ Connector conn;
+
try {
+ conn = this.master.getConnector();
+ } catch (AccumuloSecurityException ex) {
+ throw new AccumuloException(ex);
+ }
+
+ try (BatchWriter bw = conn.createBatchWriter(targetSystemTable, new BatchWriterConfig())) {
long fileCount = 0;
- Connector conn = this.master.getConnector();
- // Make file entries in highest tablet
- bw = conn.createBatchWriter(targetSystemTable, new BatchWriterConfig());
Scanner scanner = conn.createScanner(targetSystemTable, Authorizations.EMPTY);
scanner.setRange(scanRange);
TabletsSection.TabletColumnFamily.PREV_ROW_COLUMN.fetch(scanner);
@@ -768,13 +778,6 @@ abstract class TabletGroupWatcher extends Daemon {
} catch (Exception ex) {
throw new AccumuloException(ex);
- } finally {
- if (bw != null)
- try {
- bw.close();
- } catch (Exception ex) {
- throw new AccumuloException(ex);
- }
}
}
@@ -886,7 +889,7 @@ abstract class TabletGroupWatcher extends Daemon {
builder.append(assignment);
// Don't let the log message get too gigantic
- if (builder.length() > ASSINGMENT_BUFFER_MAX_LENGTH) {
+ if (builder.length() > ASSIGNMENT_BUFFER_MAX_LENGTH) {
builder.append("]");
Master.log.debug(store.name() + " assigning tablets: [" + builder.toString());
builder.setLength(0);
diff --git a/server/master/src/main/java/org/apache/accumulo/master/state/MergeStats.java b/server/master/src/main/java/org/apache/accumulo/master/state/MergeStats.java
index 420e4e1..3dbbc46 100644
--- a/server/master/src/main/java/org/apache/accumulo/master/state/MergeStats.java
+++ b/server/master/src/main/java/org/apache/accumulo/master/state/MergeStats.java
@@ -50,14 +50,14 @@ import org.slf4j.LoggerFactory;
public class MergeStats {
final static private Logger log = LoggerFactory.getLogger(MergeStats.class);
- MergeInfo info;
- int hosted = 0;
- int unassigned = 0;
- int chopped = 0;
- int needsToBeChopped = 0;
- int total = 0;
- boolean lowerSplit = false;
- boolean upperSplit = false;
+ private final MergeInfo info;
+ private int hosted = 0;
+ private int unassigned = 0;
+ private int chopped = 0;
+ private int needsToBeChopped = 0;
+ private int total = 0;
+ private boolean lowerSplit = false;
+ private boolean upperSplit = false;
public MergeStats(MergeInfo info) {
this.info = info;
@@ -77,11 +77,11 @@ public class MergeStats {
if (info.getState().equals(MergeState.NONE))
return;
if (!upperSplit && info.getExtent().getEndRow().equals(ke.getPrevEndRow())) {
- log.info("Upper split found");
+ log.info("Upper split found: {}", ke.getPrevEndRow());
upperSplit = true;
}
if (!lowerSplit && info.getExtent().getPrevEndRow().equals(ke.getEndRow())) {
- log.info("Lower split found");
+ log.info("Lower split found: {}", ke.getEndRow());
lowerSplit = true;
}
if (!info.overlaps(ke))
@@ -108,78 +108,77 @@ public class MergeStats {
if (state == MergeState.NONE)
return state;
if (total == 0) {
- log.trace("failed to see any tablets for this range, ignoring " + info.getExtent());
+ log.trace("failed to see any tablets for this range, ignoring {}", info.getExtent());
return state;
}
- log.info("Computing next merge state for " + info.getExtent() + " which is presently " + state
- + " isDelete : " + info.isDelete());
+ log.info("Computing next merge state for {} which is presently {} isDelete : {}",
+ info.getExtent(), state, info.isDelete());
if (state == MergeState.STARTED) {
state = MergeState.SPLITTING;
}
if (state == MergeState.SPLITTING) {
- log.info(hosted + " are hosted, total " + total);
+ log.info("{} are hosted, total {}", hosted, total);
if (!info.isDelete() && total == 1) {
- log.info("Merge range is already contained in a single tablet " + info.getExtent());
+ log.info("Merge range is already contained in a single tablet {}", info.getExtent());
state = MergeState.COMPLETE;
} else if (hosted == total) {
if (info.isDelete()) {
if (!lowerSplit)
- log.info("Waiting for " + info + " lower split to occur " + info.getExtent());
+ log.info("Waiting for {} lower split to occur {}", info, info.getExtent());
else if (!upperSplit)
- log.info("Waiting for " + info + " upper split to occur " + info.getExtent());
+ log.info("Waiting for {} upper split to occur {}", info, info.getExtent());
else
state = MergeState.WAITING_FOR_CHOPPED;
} else {
state = MergeState.WAITING_FOR_CHOPPED;
}
} else {
- log.info(
- "Waiting for " + hosted + " hosted tablets to be " + total + " " + info.getExtent());
+ log.info("Waiting for {} hosted tablets to be {} {}", hosted, total, info.getExtent());
}
}
if (state == MergeState.WAITING_FOR_CHOPPED) {
- log.info(chopped + " tablets are chopped " + info.getExtent());
+ log.info("{} tablets are chopped {}", chopped, info.getExtent());
if (chopped == needsToBeChopped) {
state = MergeState.WAITING_FOR_OFFLINE;
} else {
- log.info("Waiting for " + chopped + " chopped tablets to be " + needsToBeChopped + " "
- + info.getExtent());
+ log.info("Waiting for {} chopped tablets to be {} {}", chopped, needsToBeChopped,
+ info.getExtent());
}
}
if (state == MergeState.WAITING_FOR_OFFLINE) {
if (chopped != needsToBeChopped) {
- log.warn("Unexpected state: chopped tablets should be " + needsToBeChopped + " was "
- + chopped + " merge " + info.getExtent());
+ log.warn("Unexpected state: chopped tablets should be {} was {} merge {}", needsToBeChopped,
+ chopped, info.getExtent());
// Perhaps a split occurred after we chopped, but before we went offline: start over
state = MergeState.WAITING_FOR_CHOPPED;
} else {
- log.info(
- chopped + " tablets are chopped, " + unassigned + " are offline " + info.getExtent());
+ log.info("{} tablets are chopped, {} are offline {}", chopped, unassigned,
+ info.getExtent());
if (unassigned == total && chopped == needsToBeChopped) {
if (verifyMergeConsistency(connector, master))
state = MergeState.MERGING;
else
- log.info("Merge consistency check failed " + info.getExtent());
+ log.info("Merge consistency check failed {}", info.getExtent());
} else {
- log.info("Waiting for " + unassigned + " unassigned tablets to be " + total + " "
- + info.getExtent());
+ log.info("Waiting for {} unassigned tablets to be {} {}", unassigned, total,
+ info.getExtent());
}
}
}
if (state == MergeState.MERGING) {
if (hosted != 0) {
// Shouldn't happen
- log.error("Unexpected state: hosted tablets should be zero " + hosted + " merge "
- + info.getExtent());
+ log.error("Unexpected state: hosted tablets should be zero {} merge {}", hosted,
+ info.getExtent());
state = MergeState.WAITING_FOR_OFFLINE;
}
if (unassigned != total) {
// Shouldn't happen
- log.error("Unexpected state: unassigned tablets should be " + total + " was " + unassigned
- + " merge " + info.getExtent());
+ log.error("Unexpected state: unassigned tablets should be {} was {} merge {}", total,
+ unassigned, info.getExtent());
state = MergeState.WAITING_FOR_CHOPPED;
}
- log.info(unassigned + " tablets are unassigned " + info.getExtent());
+ log.info("{} tablets are unassigned {}", unassigned, info.getExtent());
}
return state;
}
@@ -201,7 +200,7 @@ public class MergeStats {
scanner.setRange(range.clip(MetadataSchema.TabletsSection.getRange()));
KeyExtent prevExtent = null;
- log.debug("Scanning range " + range);
+ log.debug("Scanning range {}", range);
for (Entry<Key,Value> entry : scanner) {
TabletLocationState tls;
try {
@@ -210,13 +209,13 @@ public class MergeStats {
log.error("{}", e.getMessage(), e);
return false;
}
- log.debug("consistency check: " + tls + " walogs " + tls.walogs.size());
+ log.debug("consistency check: {} walogs {}", tls, tls.walogs.size());
if (!tls.extent.getTableId().equals(tableId)) {
break;
}
if (!tls.walogs.isEmpty() && verify.getMergeInfo().needsToBeChopped(tls.extent)) {
- log.debug("failing consistency: needs to be chopped" + tls.extent);
+ log.debug("failing consistency: needs to be chopped {}", tls.extent);
return false;
}
@@ -224,18 +223,18 @@ public class MergeStats {
// this is the first tablet observed, it must be offline and its prev row must be less than
// the start of the merge range
if (tls.extent.getPrevEndRow() != null && tls.extent.getPrevEndRow().compareTo(start) > 0) {
- log.debug("failing consistency: prev row is too high " + start);
+ log.debug("failing consistency: prev row is too high {}", start);
return false;
}
if (tls.getState(master.onlineTabletServers()) != TabletState.UNASSIGNED
&& tls.getState(master.onlineTabletServers()) != TabletState.SUSPENDED) {
- log.debug("failing consistency: assigned or hosted " + tls);
+ log.debug("failing consistency: assigned or hosted {}", tls);
return false;
}
} else if (!tls.extent.isPreviousExtent(prevExtent)) {
- log.debug("hole in " + MetadataTable.NAME);
+ log.debug("hole in {}", MetadataTable.NAME);
return false;
}
@@ -249,8 +248,8 @@ public class MergeStats {
break;
}
}
- log.debug("chopped " + chopped + " v.chopped " + verify.chopped + " unassigned " + unassigned
- + " v.unassigned " + verify.unassigned + " verify.total " + verify.total);
+ log.debug("chopped {} v.chopped {} unassigned {} v.unassigned {} verify.total {}", chopped,
+ verify.chopped, unassigned, verify.unassigned, verify.total);
return chopped == verify.chopped && unassigned == verify.unassigned
&& unassigned == verify.total;
}
diff --git a/server/master/src/main/spotbugs/exclude-filter.xml b/server/master/src/main/spotbugs/exclude-filter.xml
index 32f3c4b..84d5c23 100644
--- a/server/master/src/main/spotbugs/exclude-filter.xml
+++ b/server/master/src/main/spotbugs/exclude-filter.xml
@@ -40,4 +40,9 @@
</Or>
<Bug code="DM" pattern="DM_EXIT" />
</Match>
+ <Match>
+ <!-- Must ignore these everywhere, because of a javac byte code generation bug -->
+ <!-- https://github.com/spotbugs/spotbugs/issues/756 -->
+ <Bug pattern="RCN_REDUNDANT_NULLCHECK_WOULD_HAVE_BEEN_A_NPE" />
+ </Match>
</FindBugsFilter>