accumulo-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From edcole...@apache.org
Subject [accumulo] branch 1.9 updated: Fix #1338 Reduce verbose logging of merge operations in Master log
Date Fri, 06 Sep 2019 18:57:48 GMT
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 <dev1@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>


Mime
View raw message