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:56 UTC
[lucene-solr] branch jira/solr15138-4 created (now 2efc600218c)
This is an automated email from the ASF dual-hosted git repository.
ishan pushed a change to branch jira/solr15138-4
in repository https://gitbox.apache.org/repos/asf/lucene-solr.git
at 2efc600218c More instrumentation, identified some TODOFORNOBLE to resolve
This branch includes the following new commits:
new 2efc600218c More instrumentation, identified some TODOFORNOBLE to resolve
The 1 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails. The revisions
listed as "add" were already present in the repository and have only
been added to this reference.
[lucene-solr] 01/01: More instrumentation, identified some TODOFORNOBLE to resolve
Posted by is...@apache.org.
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;
}