You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@lucene.apache.org by is...@apache.org on 2022/06/27 08:49:57 UTC
[lucene-solr] 01/01: More instrumentation, identified some TODOFORNOBLE to resolve
This is an automated email from the ASF dual-hosted git repository.
ishan pushed a commit to branch jira/solr15138-4
in repository https://gitbox.apache.org/repos/asf/lucene-solr.git
commit 2efc600218c9a94cee34f908f55338f02b640b89
Author: Ubuntu <ro...@ubuntu>
AuthorDate: Mon Jun 27 14:18:30 2022 +0530
More instrumentation, identified some TODOFORNOBLE to resolve
---
.../java/org/apache/solr/cloud/LeaderElector.java | 35 ++++++++++++++++-
.../solr/cloud/ShardLeaderElectionContext.java | 44 ++++++++++++++++++++--
.../solr/cloud/ShardLeaderElectionContextBase.java | 17 +++++++++
.../java/org/apache/solr/cloud/ZkController.java | 38 ++++++++++++++++++-
.../java/org/apache/solr/core/CoreContainer.java | 6 +++
5 files changed, 134 insertions(+), 6 deletions(-)
diff --git a/solr/core/src/java/org/apache/solr/cloud/LeaderElector.java b/solr/core/src/java/org/apache/solr/cloud/LeaderElector.java
index e55ce2b620a..c8249214b16 100644
--- a/solr/core/src/java/org/apache/solr/cloud/LeaderElector.java
+++ b/solr/core/src/java/org/apache/solr/cloud/LeaderElector.java
@@ -29,6 +29,7 @@ import java.util.regex.Pattern;
import org.apache.solr.cloud.ZkController.ContextKey;
import org.apache.solr.common.AlreadyClosedException;
import org.apache.solr.common.SolrException;
+import org.apache.solr.common.Timer;
import org.apache.solr.common.cloud.SolrZkClient;
import org.apache.solr.common.cloud.ZkCmdExecutor;
import org.apache.solr.common.cloud.ZooKeeperException;
@@ -228,6 +229,8 @@ public class LeaderElector {
* @return sequential node number
*/
public int joinElection(ElectionContext context, boolean replacement,boolean joinAtHead) throws KeeperException, InterruptedException, IOException {
+ Timer.TLInst.start("LeaderElector#joinElection()_0");
+
context.joinedElectionFired();
final String shardsElectZkPath = context.electionPath + LeaderElector.ELECTION_NODE;
@@ -237,9 +240,14 @@ public class LeaderElector {
String leaderSeqPath = null;
boolean cont = true;
int tries = 0;
+
+ Timer.TLInst.end("LeaderElector#joinElection()_0");
+
while (cont) {
try {
if(joinAtHead){
+ Timer.TLInst.start("LeaderElector#joinElection()_0.5");
+
log.debug("Node {} trying to join election at the head", id);
List<String> nodes = OverseerTaskProcessor.getSortedElectionNodes(zkClient, shardsElectZkPath);
if(nodes.size() <2){
@@ -256,15 +264,24 @@ public class LeaderElector {
leaderSeqPath = shardsElectZkPath + "/" + id + "-n_"+ m.group(1);
zkClient.create(leaderSeqPath, null, CreateMode.EPHEMERAL, false);
}
+ Timer.TLInst.end("LeaderElector#joinElection()_0.5");
+
} else {
+ Timer.TLInst.start("LeaderElector#joinElection()_1");
+
leaderSeqPath = zkClient.create(shardsElectZkPath + "/" + id + "-n_", null,
CreateMode.EPHEMERAL_SEQUENTIAL, false);
+
+ Timer.TLInst.end("LeaderElector#joinElection()_1");
+
}
log.debug("Joined leadership election with path: {}", leaderSeqPath);
context.leaderSeqPath = leaderSeqPath;
cont = false;
} catch (ConnectionLossException e) {
+ Timer.TLInst.start("LeaderElector#joinElection()_CONNLOSS");
+
// we don't know if we made our node or not...
List<String> entries = zkClient.getChildren(shardsElectZkPath, null, true);
@@ -289,8 +306,13 @@ public class LeaderElector {
Thread.currentThread().interrupt();
}
}
+
+ Timer.TLInst.end("LeaderElector#joinElection()_CONNLOSS");
+
} catch (KeeperException.NoNodeException e) {
+ Timer.TLInst.start("LeaderElector#joinElection()_NONODE");
+
// we must have failed in creating the election node - someone else must
// be working on it, lets try again
if (tries++ > 20) {
@@ -304,11 +326,22 @@ public class LeaderElector {
} catch (InterruptedException e2) {
Thread.currentThread().interrupt();
}
+
+ Timer.TLInst.end("LeaderElector#joinElection()_NONODE");
+
}
}
+ Timer.TLInst.start("LeaderElector#joinElection()_2");
+
checkIfIamLeader(context, replacement);
+ Timer.TLInst.end("LeaderElector#joinElection()_2");
- return getSeq(context.leaderSeqPath);
+ Timer.TLInst.start("LeaderElector#joinElection()_3");
+ int abc = getSeq(context.leaderSeqPath);
+ Timer.TLInst.end("LeaderElector#joinElection()_3");
+
+
+ return abc;
}
private class ElectionWatcher implements Watcher {
diff --git a/solr/core/src/java/org/apache/solr/cloud/ShardLeaderElectionContext.java b/solr/core/src/java/org/apache/solr/cloud/ShardLeaderElectionContext.java
index 68b062ed876..623124a9a0a 100644
--- a/solr/core/src/java/org/apache/solr/cloud/ShardLeaderElectionContext.java
+++ b/solr/core/src/java/org/apache/solr/cloud/ShardLeaderElectionContext.java
@@ -25,6 +25,7 @@ import java.util.concurrent.TimeUnit;
import org.apache.lucene.search.MatchAllDocsQuery;
import org.apache.solr.cloud.overseer.OverseerAction;
import org.apache.solr.common.SolrException;
+import org.apache.solr.common.Timer;
import org.apache.solr.common.SolrException.ErrorCode;
import org.apache.solr.common.cloud.ClusterState;
import org.apache.solr.common.cloud.DocCollection;
@@ -94,23 +95,30 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
void runLeaderProcess(boolean weAreReplacement, int pauseBeforeStart) throws KeeperException,
InterruptedException, IOException {
String coreName = leaderProps.getStr(ZkStateReader.CORE_NAME_PROP);
- ActionThrottle lt;
+ //ActionThrottle lt;
try (SolrCore core = cc.getCore(coreName)) {
if (core == null) {
// shutdown or removed
return;
}
MDCLoggingContext.setCore(core);
- lt = core.getUpdateHandler().getSolrCoreState().getLeaderThrottle();
+ // lt = core.getUpdateHandler().getSolrCoreState().getLeaderThrottle();
}
try {
- lt.minimumWaitBetweenActions();
- lt.markAttemptingAction();
+ //lt.minimumWaitBetweenActions();
+ //lt.markAttemptingAction();
+ Timer.TLInst.start("runLeader#leaderVote");
int leaderVoteWait = cc.getZkController().getLeaderVoteWait();
+ Timer.TLInst.end("runLeader#leaderVote");
+
+ Timer.TLInst.start("runLeader#2");
+
+ // TODOFORNOBLE: we don't need this leader message for PRS
+
log.debug("Running the leader process for shard={} and weAreReplacement={} and leaderVoteWait={}", shardId, weAreReplacement, leaderVoteWait);
if (zkController.getClusterState().getCollection(collection).getSlice(shardId).getReplicas().size() > 1) {
// Clear the leader in clusterstate. We only need to worry about this if there is actually more than one replica.
@@ -122,9 +130,12 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
if (!weAreReplacement) {
waitForReplicasToComeUp(leaderVoteWait);
} else {
+ // SUSPICIOUS, this takes time 6s max, 2.7s avg, and does nothing
areAllReplicasParticipating();
}
+ Timer.TLInst.end("runLeader#2");
+
if (isClosed) {
// Solr is shutting down or the ZooKeeper session expired while waiting for replicas. If the later,
// we cannot be sure we are still the leader, so we should bail out. The OnReconnect handler will
@@ -137,6 +148,8 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
boolean setTermToMax = false;
try (SolrCore core = cc.getCore(coreName)) {
+ Timer.TLInst.start("runLeader#3");
+
if (core == null) {
return;
}
@@ -159,6 +172,10 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
return;
}
+ Timer.TLInst.end("runLeader#3");
+
+ Timer.TLInst.start("runLeader#4");
+
log.info("I may be the new leader - try and sync");
// we are going to attempt to be the leader
@@ -175,6 +192,9 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
}
}
+ // TODOFORNOBLE: Remove this entire peersync block if (a) numTLOGReplicas+numNRTreplicas=1 && (b) weAreReplacement==false
+ // If we are not replacement and there's just one replica in the shard, why do we need peer sync?
+ // this is costing 5sec max, 2.2sec avg
PeerSync.PeerSyncResult result = null;
boolean success = false;
try {
@@ -185,8 +205,12 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
result = PeerSync.PeerSyncResult.failure();
}
+ Timer.TLInst.end("runLeader#4");
+
UpdateLog ulog = core.getUpdateHandler().getUpdateLog();
+ Timer.TLInst.start("runLeader#5");
+
if (!success) {
boolean hasRecentUpdates = false;
if (ulog != null) {
@@ -210,6 +234,8 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
}
}
}
+ Timer.TLInst.end("runLeader#5");
+
// solrcloud_debug
if (log.isDebugEnabled()) {
@@ -235,6 +261,7 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
}
+
if (!isClosed) {
try {
if (replicaType == Replica.Type.TLOG) {
@@ -258,11 +285,16 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
, "without being up-to-date with the previous leader", coreNodeName);
zkController.getShardTerms(collection, shardId).setTermEqualsToLeader(coreNodeName);
}
+ Timer.TLInst.start("runLeader#6");
super.runLeaderProcess(weAreReplacement, 0);
+ Timer.TLInst.end("runLeader#6");
+
try (SolrCore core = cc.getCore(coreName)) {
if (core != null) {
+ Timer.TLInst.start("runLeader#7");
core.getCoreDescriptor().getCloudDescriptor().setLeader(true);
publishActiveIfRegisteredAndNotActive(core);
+ Timer.TLInst.end("runLeader#7");
} else {
return;
}
@@ -272,7 +304,9 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
}
// we made it as leader - send any recovery requests we need to
+ Timer.TLInst.start("runLeader#8");
syncStrategy.requestRecoveries();
+ Timer.TLInst.end("runLeader#8");
} catch (SessionExpiredException e) {
throw new SolrException(ErrorCode.SERVER_ERROR,
@@ -303,6 +337,8 @@ final class ShardLeaderElectionContext extends ShardLeaderElectionContextBase {
} else {
cancelElection();
}
+
+
} finally {
MDCLoggingContext.clear();
}
diff --git a/solr/core/src/java/org/apache/solr/cloud/ShardLeaderElectionContextBase.java b/solr/core/src/java/org/apache/solr/cloud/ShardLeaderElectionContextBase.java
index 5afacf5d098..dd16c32a21c 100644
--- a/solr/core/src/java/org/apache/solr/cloud/ShardLeaderElectionContextBase.java
+++ b/solr/core/src/java/org/apache/solr/cloud/ShardLeaderElectionContextBase.java
@@ -24,6 +24,7 @@ import java.util.ArrayList;
import org.apache.solr.cloud.overseer.OverseerAction;
import org.apache.solr.common.SolrException;
+import org.apache.solr.common.Timer;
import org.apache.solr.common.SolrException.ErrorCode;
import org.apache.solr.common.cloud.DocCollection;
import org.apache.solr.common.cloud.PerReplicaStates;
@@ -122,6 +123,7 @@ class ShardLeaderElectionContextBase extends ElectionContext {
void runLeaderProcess(boolean weAreReplacement, int pauseBeforeStartMs)
throws KeeperException, InterruptedException, IOException {
// register as leader - if an ephemeral is already there, wait to see if it goes away
+ Timer.TLInst.start("superRunLeader#0");
String parent = ZkMaintenanceUtils.getZkParent(leaderPath);
try {
@@ -162,6 +164,10 @@ class ShardLeaderElectionContextBase extends ElectionContext {
throw new SolrException(ErrorCode.SERVER_ERROR, "Could not register as the leader because creating the ephemeral registration node in ZooKeeper failed", t);
}
+ Timer.TLInst.end("superRunLeader#0");
+
+ Timer.TLInst.start("superRunLeader#1");
+ // TODOFORNOBLE, don't need for PRS
assert shardId != null;
boolean isAlreadyLeader = false;
if (zkStateReader.getClusterState() != null &&
@@ -173,6 +179,9 @@ class ShardLeaderElectionContextBase extends ElectionContext {
isAlreadyLeader = true;
}
}
+
+ Timer.TLInst.end("superRunLeader#1");
+
if (!isAlreadyLeader) {
String nodeName = leaderProps.getStr(ZkStateReader.NODE_NAME_PROP);
ZkNodeProps m = ZkNodeProps.fromKeyVals(Overseer.QUEUE_OPERATION, OverseerAction.LEADER.toLower(),
@@ -186,11 +195,19 @@ class ShardLeaderElectionContextBase extends ElectionContext {
assert zkController.getOverseer() != null;
DocCollection coll = zkStateReader.getCollection(this.collection);
if (coll == null || coll.getStateFormat() < 2 || ZkController.sendToOverseer(coll, id)) {
+ Timer.TLInst.start("superRunLeader#1");
+
zkController.getOverseer().offerStateUpdate(Utils.toJSON(m));
+ Timer.TLInst.end("superRunLeader#1");
+
} else {
+ Timer.TLInst.start("superRunLeader#2");
+
PerReplicaStates prs = PerReplicaStates.fetch(coll.getZNode(), zkClient, coll.getPerReplicaStates());
PerReplicaStatesOps.flipLeader(zkStateReader.getClusterState().getCollection(collection).getSlice(shardId).getReplicaNames(), id, prs)
.persist(coll.getZNode(), zkStateReader.getZkClient());
+ Timer.TLInst.end("superRunLeader#2");
+
}
}
}
diff --git a/solr/core/src/java/org/apache/solr/cloud/ZkController.java b/solr/core/src/java/org/apache/solr/cloud/ZkController.java
index 503f09da204..016c6862cfd 100644
--- a/solr/core/src/java/org/apache/solr/cloud/ZkController.java
+++ b/solr/core/src/java/org/apache/solr/cloud/ZkController.java
@@ -1224,6 +1224,8 @@ public class ZkController implements Closeable {
boolean afterExpiration, boolean skipRecovery) throws Exception {
MDCLoggingContext.setCoreDescriptor(cc, desc);
try {
+ Timer.TLInst.start("register()_1");
+
// pre register has published our down state
final String baseUrl = getBaseUrl();
final CloudDescriptor cloudDesc = desc.getCloudDescriptor();
@@ -1244,6 +1246,8 @@ public class ZkController implements Closeable {
throw new SolrException(ErrorCode.SERVER_ERROR, "Error registering SolrCore, replica is removed from clusterstate");
}
+ Timer.TLInst.end("register()_1");
+ Timer.TLInst.start("register()_2");
if (replica.getType() != Type.PULL) {
getCollectionTerms(collection).register(cloudDesc.getShardId(), coreZkNodeName);
@@ -1254,6 +1258,9 @@ public class ZkController implements Closeable {
log.debug("Register replica - core:{} address:{} collection:{} shard:{}",
coreName, baseUrl, collection, shardId);
+ Timer.TLInst.end("register()_2");
+ Timer.TLInst.start("register()_3");
+
try {
// If we're a preferred leader, insert ourselves at the head of the queue
boolean joinAtHead = replica.getBool(SliceMutator.PREFERRED_LEADER_PROP, false);
@@ -1264,7 +1271,7 @@ public class ZkController implements Closeable {
log.warn("Replica {} was designated as preferred leader but it's type is {}, It won't join election", coreZkNodeName, Type.PULL);
}
log.debug("Replica {} skipping election because it's type is {}", coreZkNodeName, Type.PULL);
- startReplicationFromLeader(coreName, false);
+ //startReplicationFromLeader(coreName, false);
}
} catch (InterruptedException e) {
// Restore the interrupted status
@@ -1273,6 +1280,10 @@ public class ZkController implements Closeable {
} catch (KeeperException | IOException e) {
throw new ZooKeeperException(SolrException.ErrorCode.SERVER_ERROR, "", e);
}
+
+ Timer.TLInst.end("register()_3");
+ Timer.TLInst.start("register()_4");
+
// in this case, we want to wait for the leader as long as the leader might
// wait for a vote, at least - but also long enough that a large cluster has
@@ -1284,6 +1295,9 @@ public class ZkController implements Closeable {
boolean isLeader = leaderUrl.equals(ourUrl);
assert !(isLeader && replica.getType() == Type.PULL) : "Pull replica became leader!";
+ Timer.TLInst.end("register()_4");
+ Timer.TLInst.start("register()_5");
+
try (SolrCore core = cc.getCore(desc.getName())) {
// recover from local transaction log and wait for it to complete before
@@ -1347,6 +1361,9 @@ public class ZkController implements Closeable {
// the watcher is added to a set so multiple calls of this method will left only one watcher
zkStateReader.registerDocCollectionWatcher(cloudDesc.getCollectionName(),
new UnloadCoreOnDeletedWatcher(coreZkNodeName, shardId, desc.getName()));
+
+ Timer.TLInst.end("register()_5");
+
return shardId;
} finally {
MDCLoggingContext.clear();
@@ -1490,6 +1507,9 @@ public class ZkController implements Closeable {
private void joinElection(CoreDescriptor cd, boolean afterExpiration, boolean joinAtHead)
throws InterruptedException, KeeperException, IOException {
// look for old context - if we find it, cancel it
+
+ Timer.TLInst.start("joinElection()_1");
+
String collection = cd.getCloudDescriptor().getCollectionName();
final String coreNodeName = cd.getCloudDescriptor().getCoreNodeName();
@@ -1501,6 +1521,9 @@ public class ZkController implements Closeable {
prevContext.cancelElection();
}
+ Timer.TLInst.end("joinElection()_1");
+ Timer.TLInst.start("joinElection()_2");
+
String shardId = cd.getCloudDescriptor().getShardId();
Map<String, Object> props = new HashMap<>();
@@ -1517,9 +1540,22 @@ public class ZkController implements Closeable {
ElectionContext context = new ShardLeaderElectionContext(leaderElector, shardId,
collection, coreNodeName, ourProps, this, cc);
+ Timer.TLInst.end("joinElection()_2");
+ Timer.TLInst.start("joinElection()_3");
+
leaderElector.setup(context);
+
+ Timer.TLInst.end("joinElection()_3");
+ Timer.TLInst.start("joinElection()_4");
+
electionContexts.put(contextKey, context);
+ Timer.TLInst.end("joinElection()_4");
+ Timer.TLInst.start("joinElection()_5");
+
leaderElector.joinElection(context, false, joinAtHead);
+
+ Timer.TLInst.end("joinElection()_5");
+
}
diff --git a/solr/core/src/java/org/apache/solr/core/CoreContainer.java b/solr/core/src/java/org/apache/solr/core/CoreContainer.java
index 3711cac85b9..08111c8e2f3 100644
--- a/solr/core/src/java/org/apache/solr/core/CoreContainer.java
+++ b/solr/core/src/java/org/apache/solr/core/CoreContainer.java
@@ -1258,7 +1258,9 @@ public class CoreContainer {
assert core.getName().equals(cd.getName()) : "core name " + core.getName() + " != cd " + cd.getName();
+ Timer.TLInst.start("solrCores.putCore()");
SolrCore old = solrCores.putCore(cd, core);
+ Timer.TLInst.end("solrCores.putCore()");
coreInitFailures.remove(cd.getName());
@@ -1267,7 +1269,9 @@ public class CoreContainer {
log.debug("registering core: {}", cd.getName());
}
if (registerInZk) {
+ Timer.TLInst.start("zkSys.registerInZk()");
zkSys.registerInZk(core, false, skipRecovery);
+ Timer.TLInst.end("zkSys.registerInZk()");
}
return null;
} else {
@@ -1276,7 +1280,9 @@ public class CoreContainer {
}
old.close();
if (registerInZk) {
+ Timer.TLInst.start("zkSys.registerInZk2()");
zkSys.registerInZk(core, false, skipRecovery);
+ Timer.TLInst.end("zkSys.registerInZk2()");
}
return old;
}