HBASE-21242 [amv2] Miscellaneous minor log and assign procedure create improvements
For RIT Duration, do better than print ms/seconds. Remove redundant UI column dedicated to duration when we log it in the status field too. Make bypass log at INFO level. Make it so on complete of subprocedure, we note count of outstanding siblings so we have a clue how much further the parent has to go before it is done (Helpful when hundreds of servers doing SCP). Have the SCP run the AP preflight check before creating an AP; saves creation of thousands of APs during fixup. Don't log tablename three times when reporting remote call failed. If lock is held already, note who has it. Also log after we get lock or if we have to wait rather than log on entrance though we may later have to wait (or we may have just picked up the lock). Signed-off-by: Mike Drob <mdrob@apache.org>
This commit is contained in:
Michael Stack
parent
8fc90a23ae
commit
9d34b4581c
|
|
@ -371,9 +371,9 @@ public class RegionState {
|
|||
public String toDescriptiveString() {
|
||||
long relTime = System.currentTimeMillis() - stamp;
|
||||
return hri.getRegionNameAsString()
|
||||
+ " state=" + state
|
||||
+ ", ts=" + new Date(stamp) + " (" + (relTime/1000) + "s ago)"
|
||||
+ ", server=" + serverName;
|
||||
+ " state=" + state + ", ts=" + new Date(stamp) + " (" +
|
||||
java.time.Duration.ofMillis(relTime).toString() +
|
||||
" ago), server=" + serverName;
|
||||
}
|
||||
|
||||
/**
|
||||
|
|
|
|||
|
|
@ -883,6 +883,9 @@ public abstract class Procedure<TEnvironment> implements Comparable<Procedure<TE
|
|||
return childrenLatch > 0;
|
||||
}
|
||||
|
||||
/**
|
||||
* @return Count of children outstanding (Badly named).
|
||||
*/
|
||||
protected synchronized int getChildrenLatch() {
|
||||
return childrenLatch;
|
||||
}
|
||||
|
|
|
|||
|
|
@ -1015,21 +1015,21 @@ public class ProcedureExecutor<TEnvironment> {
|
|||
return false;
|
||||
}
|
||||
|
||||
LOG.debug("Begin bypass {} with lockWait={}, override={}, recursive={}",
|
||||
LOG.info("Begin bypass {} with lockWait={}, override={}, recursive={}",
|
||||
procedure, lockWait, override, recursive);
|
||||
IdLock.Entry lockEntry = procExecutionLock.tryLockEntry(procedure.getProcId(), lockWait);
|
||||
if (lockEntry == null && !override) {
|
||||
LOG.debug("Waited {} ms, but {} is still running, skipping bypass with force={}",
|
||||
LOG.info("Waited {} ms, but {} is still running, skipping bypass with override={}",
|
||||
lockWait, procedure, override);
|
||||
return false;
|
||||
} else if (lockEntry == null) {
|
||||
LOG.debug("Waited {} ms, but {} is still running, begin bypass with force={}",
|
||||
LOG.info("Waited {} ms, but {} is still running, begin bypass with override={}",
|
||||
lockWait, procedure, override);
|
||||
}
|
||||
try {
|
||||
// check whether the procedure is already finished
|
||||
if (procedure.isFinished()) {
|
||||
LOG.debug("{} is already finished, skipping bypass", procedure);
|
||||
LOG.info("{} is already finished, skipping bypass", procedure);
|
||||
return false;
|
||||
}
|
||||
|
||||
|
|
@ -1054,7 +1054,7 @@ public class ProcedureExecutor<TEnvironment> {
|
|||
}
|
||||
});
|
||||
} else {
|
||||
LOG.debug("{} has children, skipping bypass", procedure);
|
||||
LOG.info("{} has children, skipping bypass", procedure);
|
||||
return false;
|
||||
}
|
||||
}
|
||||
|
|
@ -1063,7 +1063,7 @@ public class ProcedureExecutor<TEnvironment> {
|
|||
if (procedure.hasParent() && procedure.getState() != ProcedureState.RUNNABLE
|
||||
&& procedure.getState() != ProcedureState.WAITING
|
||||
&& procedure.getState() != ProcedureState.WAITING_TIMEOUT) {
|
||||
LOG.debug("Bypassing procedures in RUNNABLE, WAITING and WAITING_TIMEOUT states "
|
||||
LOG.info("Bypassing procedures in RUNNABLE, WAITING and WAITING_TIMEOUT states "
|
||||
+ "(with no parent), {}",
|
||||
procedure);
|
||||
// Question: how is the bypass done here?
|
||||
|
|
@ -1075,7 +1075,7 @@ public class ProcedureExecutor<TEnvironment> {
|
|||
// finished yet
|
||||
Procedure current = procedure;
|
||||
while (current != null) {
|
||||
LOG.debug("Bypassing {}", current);
|
||||
LOG.info("Bypassing {}", current);
|
||||
current.bypass(getEnvironment());
|
||||
store.update(procedure);
|
||||
long parentID = current.getParentProcId();
|
||||
|
|
@ -1095,9 +1095,9 @@ public class ProcedureExecutor<TEnvironment> {
|
|||
if (lockEntry != null) {
|
||||
// add the procedure to run queue,
|
||||
scheduler.addFront(procedure);
|
||||
LOG.debug("Bypassing {} and its ancestors successfully, adding to queue", procedure);
|
||||
LOG.info("Bypassing {} and its ancestors successfully, adding to queue", procedure);
|
||||
} else {
|
||||
LOG.debug("Bypassing {} and its ancestors successfully, but since it is already running, "
|
||||
LOG.info("Bypassing {} and its ancestors successfully, but since it is already running, "
|
||||
+ "skipping add to queue", procedure);
|
||||
}
|
||||
return true;
|
||||
|
|
@ -1507,9 +1507,17 @@ public class ProcedureExecutor<TEnvironment> {
|
|||
procStack.release(proc);
|
||||
|
||||
if (proc.isSuccess()) {
|
||||
// update metrics on finishing the procedure
|
||||
// update metrics on finishing the procedure.
|
||||
proc.updateMetricsOnFinish(getEnvironment(), proc.elapsedTime(), true);
|
||||
LOG.info("Finished " + proc + " in " + StringUtils.humanTimeDiff(proc.elapsedTime()));
|
||||
// Print out count of outstanding siblings if this procedure has a parent.
|
||||
Procedure<TEnvironment> parent = null;
|
||||
if (proc.hasParent()) {
|
||||
parent = procedures.get(proc.getParentProcId());
|
||||
}
|
||||
LOG.info("Finished {} in {}{}",
|
||||
proc,
|
||||
StringUtils.humanTimeDiff(proc.elapsedTime()),
|
||||
parent != null? (", unfinishedSiblingCount=" + parent.getChildrenLatch()): "");
|
||||
// Finalize the procedure state
|
||||
if (proc.getProcId() == rootProcId) {
|
||||
procedureFinished(proc);
|
||||
|
|
|
|||
|
|
@ -73,7 +73,7 @@ int numOfPages = (int) Math.ceil(numOfRITs * 1.0 / ritsPerPage);
|
|||
<div class="tab-pane" id="tab_rits<% (recordItr / ritsPerPage) + 1 %>">
|
||||
</%if>
|
||||
<table class="table table-striped" style="margin-bottom:0px;"><tr><th>Region</th>
|
||||
<th>State</th><th>RIT time (ms)</th> <th>Retries </th></tr>
|
||||
<th>State</th><th>Retries </th></tr>
|
||||
</%if>
|
||||
|
||||
<%if ritStat.isRegionTwiceOverThreshold(rs.getRegion()) %>
|
||||
|
|
@ -96,7 +96,6 @@ int numOfPages = (int) Math.ceil(numOfRITs * 1.0 / ritsPerPage);
|
|||
<td><% rs.getRegion().getEncodedName() %></td><td>
|
||||
<% RegionInfoDisplay.getDescriptiveNameFromRegionStateForDisplay(rs,
|
||||
assignmentManager.getConfiguration()) %></td>
|
||||
<td><% (currentTime - rs.getStamp()) %> </td>
|
||||
<td> <% retryStatus %> </td>
|
||||
</tr>
|
||||
<%java recordItr++; %>
|
||||
|
|
|
|||
|
|
@ -26,7 +26,9 @@ import org.apache.hadoop.hbase.ServerName;
|
|||
import org.apache.hadoop.hbase.TableName;
|
||||
import org.apache.hadoop.hbase.client.RegionInfo;
|
||||
import org.apache.hadoop.hbase.client.RetriesExhaustedException;
|
||||
import org.apache.hadoop.hbase.client.TableState;
|
||||
import org.apache.hadoop.hbase.exceptions.UnexpectedStateException;
|
||||
import org.apache.hadoop.hbase.master.MasterServices;
|
||||
import org.apache.hadoop.hbase.master.RegionState.State;
|
||||
import org.apache.hadoop.hbase.master.TableStateManager;
|
||||
import org.apache.hadoop.hbase.master.assignment.RegionStates.RegionStateNode;
|
||||
|
|
@ -164,19 +166,43 @@ public class AssignProcedure extends RegionTransitionProcedure {
|
|||
}
|
||||
}
|
||||
|
||||
@Override
|
||||
protected boolean startTransition(final MasterProcedureEnv env, final RegionStateNode regionNode)
|
||||
/**
|
||||
* Used by ServerCrashProcedure too skip creating Assigns if not needed.
|
||||
* @return Skip out on the assign; returns 'true'/assign if exception.
|
||||
*/
|
||||
public static boolean assign(MasterServices masterServices, RegionInfo ri) {
|
||||
try {
|
||||
return assign(masterServices,
|
||||
masterServices.getAssignmentManager().getRegionStates().getOrCreateRegionStateNode(ri));
|
||||
} catch (IOException e) {
|
||||
LOG.warn("Letting assign proceed", e);
|
||||
}
|
||||
return true;
|
||||
}
|
||||
|
||||
protected static boolean assign(MasterServices masterServices, final RegionStateNode regionNode)
|
||||
throws IOException {
|
||||
// If the region is already open we can't do much...
|
||||
if (regionNode.isInState(State.OPEN) && isServerOnline(env, regionNode)) {
|
||||
LOG.info("Assigned, not reassigning; " + this + "; " + regionNode.toShortString());
|
||||
if (regionNode.isInState(State.OPEN) &&
|
||||
masterServices.getServerManager().isServerOnline(regionNode.getRegionLocation())) {
|
||||
LOG.info("Assigned, not reassigning {}", regionNode.toShortString());
|
||||
return false;
|
||||
}
|
||||
// Don't assign if table is in disabling or disabled state.
|
||||
TableStateManager tsm = env.getMasterServices().getTableStateManager();
|
||||
TableStateManager tsm = masterServices.getTableStateManager();
|
||||
TableName tn = regionNode.getRegionInfo().getTable();
|
||||
if (tsm.getTableState(tn).isDisabledOrDisabling()) {
|
||||
LOG.info("Table " + tn + " state=" + tsm.getTableState(tn) + ", skipping " + this);
|
||||
TableState ts = tsm.getTableState(tn);
|
||||
if (ts.isDisabledOrDisabling()) {
|
||||
LOG.info("{} so SKIPPING assign of {}", ts, regionNode.getRegionInfo().getEncodedName());
|
||||
return false;
|
||||
}
|
||||
return true;
|
||||
}
|
||||
|
||||
@Override
|
||||
protected boolean startTransition(final MasterProcedureEnv env, final RegionStateNode regionNode)
|
||||
throws IOException {
|
||||
if (!assign(env.getMasterServices(), regionNode)) {
|
||||
return false;
|
||||
}
|
||||
// If the region is SPLIT, we can't assign it. But state might be CLOSED, rather than
|
||||
|
|
|
|||
|
|
@ -241,8 +241,7 @@ public abstract class RegionTransitionProcedure
|
|||
public synchronized void remoteCallFailed(final MasterProcedureEnv env,
|
||||
final ServerName serverName, final IOException exception) {
|
||||
final RegionStateNode regionNode = getRegionState(env);
|
||||
LOG.warn("Remote call failed {}; {}; {}; exception={}", serverName,
|
||||
this, regionNode.toShortString(), exception.getClass().getSimpleName(), exception);
|
||||
LOG.warn("Remote call failed {}; {}", regionNode.toShortString(), this, exception);
|
||||
if (remoteCallFailed(env, regionNode, exception)) {
|
||||
// NOTE: This call to wakeEvent puts this Procedure back on the scheduler.
|
||||
// Thereafter, another Worker can be in here so DO NOT MESS WITH STATE beyond
|
||||
|
|
|
|||
|
|
@ -306,7 +306,7 @@ public class UnassignProcedure extends RegionTransitionProcedure {
|
|||
exception.getClass().getSimpleName());
|
||||
if (!env.getMasterServices().getServerManager().expireServer(serverName)) {
|
||||
// Failed to queue an expire. Lots of possible reasons including it may be already expired.
|
||||
// In ServerCrashProcedure and RecoverMetaProcedure, there is a handleRIT stage where we
|
||||
// In ServerCrashProcedure, there is a handleRIT stage where we
|
||||
// will iterator over all the RIT procedures for the related regions of a crashed RS and
|
||||
// fail them with ServerCrashException. You can see the isSafeToProceed method above for
|
||||
// more details.
|
||||
|
|
|
|||
|
|
@ -686,7 +686,6 @@ public class MasterProcedureScheduler extends AbstractProcedureScheduler {
|
|||
boolean hasLock = true;
|
||||
final LockAndQueue[] regionLocks = new LockAndQueue[regionInfo.length];
|
||||
for (int i = 0; i < regionInfo.length; ++i) {
|
||||
LOG.info("{} checking lock on {}", procedure, regionInfo[i].getEncodedName());
|
||||
assert regionInfo[i] != null;
|
||||
assert regionInfo[i].getTable() != null;
|
||||
assert regionInfo[i].getTable().equals(table): regionInfo[i] + " " + procedure;
|
||||
|
|
@ -694,12 +693,16 @@ public class MasterProcedureScheduler extends AbstractProcedureScheduler {
|
|||
|
||||
regionLocks[i] = locking.getRegionLock(regionInfo[i].getEncodedName());
|
||||
if (!regionLocks[i].tryExclusiveLock(procedure)) {
|
||||
LOG.info("Waiting xlock for {} held by pid={}", procedure,
|
||||
regionLocks[i].getExclusiveLockProcIdOwner());
|
||||
waitProcedure(regionLocks[i], procedure);
|
||||
hasLock = false;
|
||||
while (i-- > 0) {
|
||||
regionLocks[i].releaseExclusiveLock(procedure);
|
||||
}
|
||||
break;
|
||||
} else {
|
||||
LOG.info("xlock for {}", procedure);
|
||||
}
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -30,6 +30,7 @@ import org.apache.hadoop.hbase.client.RegionInfoBuilder;
|
|||
import org.apache.hadoop.hbase.client.RegionReplicaUtil;
|
||||
import org.apache.hadoop.hbase.master.MasterServices;
|
||||
import org.apache.hadoop.hbase.master.MasterWalManager;
|
||||
import org.apache.hadoop.hbase.master.assignment.AssignProcedure;
|
||||
import org.apache.hadoop.hbase.master.assignment.AssignmentManager;
|
||||
import org.apache.hadoop.hbase.master.assignment.RegionTransitionProcedure;
|
||||
import org.apache.hadoop.hbase.procedure2.ProcedureMetrics;
|
||||
|
|
@ -176,6 +177,13 @@ public class ServerCrashProcedure
|
|||
// it does the check by calling am#isLogSplittingDone.
|
||||
List<RegionInfo> toAssign = handleRIT(env, regionsOnCrashedServer);
|
||||
AssignmentManager am = env.getAssignmentManager();
|
||||
// Do not create assigns for Regions on disabling or disabled Tables.
|
||||
// We do this inside in the AssignProcedure.
|
||||
int size = toAssign.size();
|
||||
if (toAssign.removeIf(r -> !AssignProcedure.assign(env.getMasterServices(), r))) {
|
||||
LOG.debug("Dropped {} assigns because against disabling/disabled tables",
|
||||
size - toAssign.size());
|
||||
}
|
||||
// CreateAssignProcedure will try to use the old location for the region deploy.
|
||||
addChildProcedure(am.createAssignProcedures(toAssign));
|
||||
setNextState(ServerCrashState.SERVER_CRASH_HANDLE_RIT2);
|
||||
|
|
|
|||
Loading…
Reference in New Issue