This is an automated email from the ASF dual-hosted git repository. janhoy pushed a commit to tag history/branches/lucene-solr/jira/solr-12730 in repository https://gitbox.apache.org/repos/asf/solr.git
commit efb73a39b03b3f4ac2fa139d4e0816a35c5d8b8d Author: Andrzej Bialecki <[email protected]> AuthorDate: Mon Oct 29 20:06:31 2018 +0100 SOLR-12730: add more debug logging. --- .../solr/cloud/autoscaling/IndexSizeTrigger.java | 19 +++++++++++++--- .../src/java/org/apache/solr/core/SolrCore.java | 26 ++++++++++++++++++++++ .../apache/solr/handler/admin/MetricsHandler.java | 8 +++++++ .../org/apache/solr/update/SolrIndexSplitter.java | 4 ++-- .../cloud/autoscaling/IndexSizeTriggerTest.java | 19 ++++++++++++++-- 5 files changed, 69 insertions(+), 7 deletions(-) diff --git a/solr/core/src/java/org/apache/solr/cloud/autoscaling/IndexSizeTrigger.java b/solr/core/src/java/org/apache/solr/cloud/autoscaling/IndexSizeTrigger.java index 533ec53..e41297e 100644 --- a/solr/core/src/java/org/apache/solr/cloud/autoscaling/IndexSizeTrigger.java +++ b/solr/core/src/java/org/apache/solr/cloud/autoscaling/IndexSizeTrigger.java @@ -252,7 +252,7 @@ public class IndexSizeTrigger extends TriggerBase { DocCollection docCollection = clusterState.getCollection(coll); shards.forEach((sh, replicas) -> { - // check only the leader of a replica in active shard + // check only the leader replica in an active shard Slice s = docCollection.getSlice(sh); if (s.getState() != Slice.State.ACTIVE) { return; @@ -262,6 +262,10 @@ public class IndexSizeTrigger extends TriggerBase { if (r == null) { return; } + // not on this node + if (!r.getNodeName().equals(node)) { + return; + } // find ReplicaInfo ReplicaInfo info = null; for (ReplicaInfo ri : replicas) { @@ -282,6 +286,7 @@ public class IndexSizeTrigger extends TriggerBase { String registry = SolrCoreMetricManager.createRegistryName(true, coll, sh, replicaName, null); String tag = "metrics:" + registry + ":INDEX.sizeInBytes"; metricTags.put(tag, info); + metricTags.put("metrics:" + registry + ":INDEX.sizeDetails", info); tag = "metrics:" + registry + ":SEARCHER.searcher.numDocs"; metricTags.put(tag, info); }); @@ -297,14 +302,14 @@ public class IndexSizeTrigger extends TriggerBase { } else { // verify that it's a Number if (!(size instanceof Number)) { - log.warn("invalid size value - not a number: '" + size + "' is " + size.getClass().getName()); + log.warn("invalid size value for tag " + tag + " - not a number: '" + size + "' is " + size.getClass().getName()); return; } ReplicaInfo currentInfo = currentSizes.computeIfAbsent(info.getCore(), k -> (ReplicaInfo)info.clone()); if (tag.contains("INDEX")) { currentInfo.getVariables().put(BYTES_SIZE_PROP, ((Number) size).longValue()); - } else { + } else if (tag.contains("SEARCHER")) { currentInfo.getVariables().put(DOCS_SIZE_PROP, ((Number) size).longValue()); } } @@ -458,6 +463,14 @@ public class IndexSizeTrigger extends TriggerBase { if (ops.isEmpty()) { return; } + try { + ClusterState cs = cloudManager.getClusterStateProvider().getClusterState(); + cs.forEachCollection(coll -> { + log.debug("##== Collection: {}", coll); + }); + } catch (IOException e) { + throw new RuntimeException("oops: ", e); + } if (processor.process(new IndexSizeEvent(getName(), eventTime.get(), ops, aboveSize, belowSize))) { // update last event times aboveSize.forEach((coll, replicas) -> { diff --git a/solr/core/src/java/org/apache/solr/core/SolrCore.java b/solr/core/src/java/org/apache/solr/core/SolrCore.java index 6e13039..abc4af6 100644 --- a/solr/core/src/java/org/apache/solr/core/SolrCore.java +++ b/solr/core/src/java/org/apache/solr/core/SolrCore.java @@ -443,6 +443,31 @@ public final class SolrCore implements SolrInfoBean, SolrMetricProducer, Closeab return size; } + String getIndexSizeDetails() { + Directory dir; + StringBuilder sb = new StringBuilder(); + try { + if (directoryFactory.exists(getIndexDir())) { + dir = directoryFactory.get(getIndexDir(), DirContext.DEFAULT, solrConfig.indexConfig.lockType); + try { + String[] files = dir.listAll(); + Arrays.sort(files); + for (String file : files) { + sb.append('\n'); + sb.append(file); + sb.append('\t'); + sb.append(String.valueOf(dir.fileLength(file))); + } + } finally { + directoryFactory.release(dir); + } + } + } catch (IOException e) { + SolrException.log(log, "IO error while trying to get the details of the Directory", e); + } + return sb.toString(); + } + @Override public String getName() { return name; @@ -1161,6 +1186,7 @@ public final class SolrCore implements SolrInfoBean, SolrMetricProducer, Closeab manager.registerGauge(this, registry, () -> resourceLoader.getInstancePath().toString(), getMetricTag(), true, "instanceDir", Category.CORE.toString()); manager.registerGauge(this, registry, () -> isClosed() ? "(closed)" : getIndexDir(), getMetricTag(), true, "indexDir", Category.CORE.toString()); manager.registerGauge(this, registry, () -> isClosed() ? 0 : getIndexSize(), getMetricTag(), true, "sizeInBytes", Category.INDEX.toString()); + manager.registerGauge(this, registry, () -> isClosed() ? "" : getIndexSizeDetails(), getMetricTag(), true, "sizeDetails", Category.INDEX.toString()); manager.registerGauge(this, registry, () -> isClosed() ? "(closed)" : NumberUtils.readableSize(getIndexSize()), getMetricTag(), true, "size", Category.INDEX.toString()); if (coreContainer != null) { manager.registerGauge(this, registry, () -> coreContainer.getNamesForCore(this), getMetricTag(), true, "aliases", Category.CORE.toString()); diff --git a/solr/core/src/java/org/apache/solr/handler/admin/MetricsHandler.java b/solr/core/src/java/org/apache/solr/handler/admin/MetricsHandler.java index 752e021..9b9f948 100644 --- a/solr/core/src/java/org/apache/solr/handler/admin/MetricsHandler.java +++ b/solr/core/src/java/org/apache/solr/handler/admin/MetricsHandler.java @@ -17,6 +17,7 @@ package org.apache.solr.handler.admin; +import java.lang.invoke.MethodHandles; import java.util.ArrayList; import java.util.Collections; import java.util.EnumSet; @@ -41,6 +42,7 @@ import org.apache.solr.common.params.SolrParams; import org.apache.solr.common.util.NamedList; import org.apache.solr.common.util.SimpleOrderedMap; import org.apache.solr.common.util.StrUtils; +import org.apache.solr.common.util.Utils; import org.apache.solr.core.CoreContainer; import org.apache.solr.handler.RequestHandlerBase; import org.apache.solr.metrics.SolrMetricManager; @@ -49,11 +51,15 @@ import org.apache.solr.response.SolrQueryResponse; import org.apache.solr.security.AuthorizationContext; import org.apache.solr.security.PermissionNameProvider; import org.apache.solr.util.stats.MetricUtils; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; /** * Request handler to return metrics */ public class MetricsHandler extends RequestHandlerBase implements PermissionNameProvider { + private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); + final SolrMetricManager metricManager; public static final String COMPACT_PARAM = "compact"; @@ -99,6 +105,8 @@ public class MetricsHandler extends RequestHandlerBase implements PermissionName } handleRequest(req.getParams(), (k, v) -> rsp.add(k, v)); + log.debug("##== Req: {}", req); + log.debug("##== Rsp: {}", Utils.toJSONString(rsp.getValues())); } public void handleRequest(SolrParams params, BiConsumer<String, Object> consumer) throws Exception { diff --git a/solr/core/src/java/org/apache/solr/update/SolrIndexSplitter.java b/solr/core/src/java/org/apache/solr/update/SolrIndexSplitter.java index 334a29d..6ed0b1f 100644 --- a/solr/core/src/java/org/apache/solr/update/SolrIndexSplitter.java +++ b/solr/core/src/java/org/apache/solr/update/SolrIndexSplitter.java @@ -174,7 +174,7 @@ public class SolrIndexSplitter { log.error("Original error closing IndexWriter:", e); throw new SolrException(SolrException.ErrorCode.SERVER_ERROR, "Error reopening IndexWriter after failed close", e1); } - throw new SolrException(SolrException.ErrorCode.SERVER_ERROR, "Error closing current IndexWriter, aborting offline split...", e); + throw new SolrException(SolrException.ErrorCode.SERVER_ERROR, "Error closing current IndexWriter, aborting 'link' split...", e); } } boolean success = false; @@ -195,7 +195,7 @@ public class SolrIndexSplitter { t = timings.sub("parentApplyBufferedUpdates"); ulog.applyBufferedUpdates(); t.stop(); - log.info("Splitting in 'offline' mode " + (success? "finished" : "FAILED") + + log.info("Splitting in 'link' mode " + (success? "finished" : "FAILED") + ": re-opened parent IndexWriter."); } } diff --git a/solr/core/src/test/org/apache/solr/cloud/autoscaling/IndexSizeTriggerTest.java b/solr/core/src/test/org/apache/solr/cloud/autoscaling/IndexSizeTriggerTest.java index c933c0a..934ec20 100644 --- a/solr/core/src/test/org/apache/solr/cloud/autoscaling/IndexSizeTriggerTest.java +++ b/solr/core/src/test/org/apache/solr/cloud/autoscaling/IndexSizeTriggerTest.java @@ -67,7 +67,7 @@ import static org.apache.solr.common.cloud.ZkStateReader.SOLR_AUTOSCALING_CONF_P /** * */ -@LogLevel("org.apache.solr.cloud.autoscaling=DEBUG") +@LogLevel("org.apache.solr.cloud.autoscaling=DEBUG;org.apache.solr.handler.admin.MetricsHandler=DEBUG") public class IndexSizeTriggerTest extends SolrCloudTestCase { private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass()); @@ -90,6 +90,7 @@ public class IndexSizeTriggerTest extends SolrCloudTestCase { @BeforeClass public static void setupCluster() throws Exception { + System.setProperty("solr.directoryFactory", "solr.StandardDirectoryFactory"); configureCluster(2) .addConfig("conf", configset("cloud-minimal")) .configure(); @@ -503,7 +504,8 @@ public class IndexSizeTriggerTest extends SolrCloudTestCase { int aboveBytes = maxSize * 9 / 10; - long waitForSeconds = 3 + random().nextInt(5); + // need to wait for recovery after splitting + long waitForSeconds = 10 + random().nextInt(5); // the trigger is initially disabled so that we have time to add listeners // and have them capture all events once the trigger is enabled @@ -562,6 +564,7 @@ public class IndexSizeTriggerTest extends SolrCloudTestCase { "'name' : 'index_size_trigger4'" + "}" + "}"; + log.info("-- resuming trigger"); req = createAutoScalingRequest(SolrRequest.METHOD.POST, resumeTriggerCommand); response = solrClient.request(req); assertEquals(response.get("result").toString(), "success"); @@ -570,6 +573,7 @@ public class IndexSizeTriggerTest extends SolrCloudTestCase { boolean await = finished.await(90000 / SPEED, TimeUnit.MILLISECONDS); assertTrue("did not finish processing in time", await); + log.info("-- suspending trigger"); // suspend the trigger to avoid generating more events String suspendTriggerCommand = "{" + "'suspend-trigger' : {" + @@ -624,6 +628,7 @@ public class IndexSizeTriggerTest extends SolrCloudTestCase { finished = new CountDownLatch(1); + log.info("-- deleting documents"); for (int j = 0; j < 10; j++) { UpdateRequest ureq = new UpdateRequest(); ureq.setParam("collection", collectionName); @@ -632,6 +637,7 @@ public class IndexSizeTriggerTest extends SolrCloudTestCase { } solrClient.request(ureq); } + cloudManager.getTimeSource().sleep(5000); // make sure the actual index size is reduced by deletions, otherwise we may still violate aboveBytes UpdateRequest ur = new UpdateRequest(); ur.setParam(UpdateParams.COMMIT, "true"); @@ -640,14 +646,17 @@ public class IndexSizeTriggerTest extends SolrCloudTestCase { ur.setParam(UpdateParams.MAX_OPTIMIZE_SEGMENTS, "1"); ur.setParam(UpdateParams.WAIT_SEARCHER, "true"); ur.setParam(UpdateParams.OPEN_SEARCHER, "true"); + log.info("-- requesting optimize / expungeDeletes / commit"); solrClient.request(ur, collectionName); // wait for the segments to merge to reduce the index size cloudManager.getTimeSource().sleep(50000); + log.info("-- requesting commit"); solrClient.commit(collectionName, true, true); // resume the trigger + log.info("-- resuming trigger"); req = createAutoScalingRequest(SolrRequest.METHOD.POST, resumeTriggerCommand); response = solrClient.request(req); assertEquals(response.get("result").toString(), "success"); @@ -656,6 +665,12 @@ public class IndexSizeTriggerTest extends SolrCloudTestCase { await = finished.await(90000 / SPEED, TimeUnit.MILLISECONDS); assertTrue("did not finish processing in time", await); + log.info("-- suspending trigger"); + req = createAutoScalingRequest(SolrRequest.METHOD.POST, suspendTriggerCommand); + response = solrClient.request(req); + assertEquals(response.get("result").toString(), "success"); + System.exit(-1); + assertEquals(1, listenerEvents.size()); events = listenerEvents.get("capturing4"); assertNotNull("'capturing4' events not found", events);
