You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@solr.apache.org by ds...@apache.org on 2024/01/17 19:38:34 UTC
(solr) branch main updated: SOLR-16986: log cpuTime of requests (#2118)
This is an automated email from the ASF dual-hosted git repository.
dsmiley pushed a commit to branch main
in repository https://gitbox.apache.org/repos/asf/solr.git
The following commit(s) were added to refs/heads/main by this push:
new 16e4c239cc9 SOLR-16986: log cpuTime of requests (#2118)
16e4c239cc9 is described below
commit 16e4c239cc9a7bedd11733d8b80183f59ab9252f
Author: gbellaton <66...@users.noreply.github.com>
AuthorDate: Wed Jan 17 20:38:28 2024 +0100
SOLR-16986: log cpuTime of requests (#2118)
Log CPU time per request via solr.log.cputime
---
solr/CHANGES.txt | 2 +
.../apache/solr/handler/RequestHandlerBase.java | 23 ++++
.../solr/handler/component/SearchHandler.java | 33 +++++
.../src/java/org/apache/solr/util/ThreadStats.java | 94 ++++++++++++++
.../test/org/apache/solr/TestCpuTimeSearch.java | 137 +++++++++++++++++++++
5 files changed, 289 insertions(+)
diff --git a/solr/CHANGES.txt b/solr/CHANGES.txt
index b4b75870505..808ca7a4d73 100644
--- a/solr/CHANGES.txt
+++ b/solr/CHANGES.txt
@@ -82,6 +82,8 @@ New Features
* SOLR-17006: Collection creation & adding replicas: User-defined properties are persisted to state.json and
applied to new replicas, available for use as property substitution in configuration files. (Vincent Primault)
+* SOLR-16986: Log CPU time per request via solr.log.cputime (Gilles Bellaton, David Smiley)
+
* SOLR-16974: Circuit Breakers can now be configured globally (janhoy, Christine Poerschke)
* SOLR-16743: When using TLS, Solr can now auto-reload the keystore and truststore without the need to restart the process.
diff --git a/solr/core/src/java/org/apache/solr/handler/RequestHandlerBase.java b/solr/core/src/java/org/apache/solr/handler/RequestHandlerBase.java
index 2c53eb26625..086c3ca65e9 100644
--- a/solr/core/src/java/org/apache/solr/handler/RequestHandlerBase.java
+++ b/solr/core/src/java/org/apache/solr/handler/RequestHandlerBase.java
@@ -24,6 +24,7 @@ import com.codahale.metrics.Timer;
import java.lang.invoke.MethodHandles;
import java.util.Collection;
import java.util.Collections;
+import java.util.Optional;
import org.apache.solr.api.Api;
import org.apache.solr.api.ApiBag;
import org.apache.solr.api.ApiSupport;
@@ -48,6 +49,7 @@ import org.apache.solr.security.PermissionNameProvider;
import org.apache.solr.update.processor.DistributedUpdateProcessor;
import org.apache.solr.util.SolrPluginUtils;
import org.apache.solr.util.TestInjection;
+import org.apache.solr.util.ThreadStats;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@@ -74,6 +76,8 @@ public abstract class RequestHandlerBase
private PluginInfo pluginInfo;
+ protected boolean publishCpuTime = Boolean.getBoolean(ThreadStats.ENABLE_CPU_TIME);
+
@SuppressForbidden(reason = "Need currentTimeMillis, used only for stats output")
public RequestHandlerBase() {
handlerStart = System.currentTimeMillis();
@@ -212,6 +216,11 @@ public abstract class RequestHandlerBase
@Override
public void handleRequest(SolrQueryRequest req, SolrQueryResponse rsp) {
+ ThreadStats cpuStats = null;
+ if (publishCpuTime) {
+ cpuStats = new ThreadStats();
+ }
+
HandlerMetrics metrics = getMetricsForThisRequest(req);
metrics.requests.inc();
@@ -240,6 +249,20 @@ public abstract class RequestHandlerBase
} finally {
long elapsed = timer.stop();
metrics.totalTime.inc(elapsed);
+
+ if (cpuStats != null) {
+ Optional<Long> cpuTime = cpuStats.getCpuTimeMs();
+ if (cpuTime.isPresent()) {
+ // add CPU_TIME if not already added by SearchHandler
+ NamedList<Object> header = rsp.getResponseHeader();
+ if (header != null) {
+ if (header.get(ThreadStats.CPU_TIME) == null) {
+ header.add(ThreadStats.CPU_TIME, cpuTime.get());
+ }
+ }
+ rsp.addToLog(ThreadStats.LOCAL_CPU_TIME, cpuTime.get());
+ }
+ }
}
}
diff --git a/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java b/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java
index 5e64e5fbfea..92b8f090dfc 100644
--- a/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java
+++ b/solr/core/src/java/org/apache/solr/handler/component/SearchHandler.java
@@ -68,6 +68,7 @@ import org.apache.solr.security.AuthorizationContext;
import org.apache.solr.security.PermissionNameProvider;
import org.apache.solr.util.RTimerTree;
import org.apache.solr.util.SolrPluginUtils;
+import org.apache.solr.util.ThreadStats;
import org.apache.solr.util.circuitbreaker.CircuitBreaker;
import org.apache.solr.util.circuitbreaker.CircuitBreakerRegistry;
import org.apache.solr.util.plugin.PluginInfoInitialized;
@@ -514,6 +515,7 @@ public class SearchHandler extends RequestHandlerBase
rb.finished = new ArrayList<>();
int nextStage = 0;
+ long totalShardCpuTime = 0L;
do {
rb.stage = nextStage;
nextStage = ResponseBuilder.STAGE_DONE;
@@ -608,6 +610,11 @@ public class SearchHandler extends RequestHandlerBase
for (SearchComponent c : components) {
c.handleResponses(rb, srsp.getShardRequest());
}
+
+ // Compute total CpuTime used by all shards.
+ if (publishCpuTime) {
+ totalShardCpuTime += computeShardCpuTime(srsp.getShardRequest().responses);
+ }
}
}
@@ -617,6 +624,11 @@ public class SearchHandler extends RequestHandlerBase
// we are done when the next stage is MAX_VALUE
} while (nextStage != Integer.MAX_VALUE);
+
+ if (publishCpuTime) {
+ rsp.getResponseHeader().add(ThreadStats.CPU_TIME, totalShardCpuTime);
+ rsp.addToLog(ThreadStats.CPU_TIME, totalShardCpuTime);
+ }
}
// SOLR-5550: still provide shards.info if requested even for a short circuited distrib request
@@ -658,6 +670,27 @@ public class SearchHandler extends RequestHandlerBase
}
}
+ private long computeShardCpuTime(List<ShardResponse> responses) {
+ long totalShardCpuTime = 0;
+ for (ShardResponse response : responses) {
+ if ((response.getSolrResponse() != null)
+ && (response.getSolrResponse().getResponse() != null)
+ && (response.getSolrResponse().getResponse().get("responseHeader") != null)) {
+ @SuppressWarnings("unchecked")
+ SimpleOrderedMap<Object> header =
+ (SimpleOrderedMap<Object>)
+ response.getSolrResponse().getResponse().get(SolrQueryResponse.RESPONSE_HEADER_KEY);
+ if (header != null) {
+ Long shardCpuTime = (Long) header.get(ThreadStats.CPU_TIME);
+ if (shardCpuTime != null) {
+ totalShardCpuTime += shardCpuTime;
+ }
+ }
+ }
+ }
+ return totalShardCpuTime;
+ }
+
private static void throwSolrException(Throwable shardResponseException) throws SolrException {
if (shardResponseException instanceof SolrException) {
throw (SolrException) shardResponseException;
diff --git a/solr/core/src/java/org/apache/solr/util/ThreadStats.java b/solr/core/src/java/org/apache/solr/util/ThreadStats.java
new file mode 100644
index 00000000000..a0d6913c11e
--- /dev/null
+++ b/solr/core/src/java/org/apache/solr/util/ThreadStats.java
@@ -0,0 +1,94 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.solr.util;
+
+import java.lang.invoke.MethodHandles;
+import java.lang.management.ManagementFactory;
+import java.lang.management.ThreadMXBean;
+import java.util.Optional;
+import java.util.concurrent.TimeUnit;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+/**
+ * Allows tracking information about the current thread using the JVM's built-in management bean
+ * {@link java.lang.management.ThreadMXBean}.
+ *
+ * <p>Calling code should create an instance of this class when starting the operation, and then can
+ * get the {@link #getCpuTimeMs()} at any time thereafter.
+ */
+public class ThreadStats {
+ private static final long UNSUPPORTED = -1;
+ public static final String CPU_TIME = "cpuTime";
+ public static final String LOCAL_CPU_TIME = "localCpuTime";
+ public static final String ENABLE_CPU_TIME = "solr.log.cputime";
+
+ private static ThreadMXBean THREAD_MX_BEAN;
+ private static final Logger log = LoggerFactory.getLogger(MethodHandles.lookup().lookupClass());
+
+ static {
+ try {
+ ThreadMXBean threadBean = ManagementFactory.getThreadMXBean();
+ if (!threadBean.isThreadCpuTimeEnabled()) {
+ threadBean.setThreadCpuTimeEnabled(true);
+ }
+ THREAD_MX_BEAN = threadBean;
+ } catch (UnsupportedOperationException e) {
+ THREAD_MX_BEAN = null;
+ log.info("Operation Cpu Time is not supported.");
+ }
+ }
+
+ private final long threadId;
+ private final long startCpuTimeNanos;
+
+ /**
+ * Create an instance to track the current thread's usage of cpu and memory. The usage information
+ * can later be retrieved by any thread by calling {@link #getCpuTimeMs()}.
+ */
+ public ThreadStats() {
+ this.threadId = Thread.currentThread().getId();
+ if (THREAD_MX_BEAN != null) {
+ this.startCpuTimeNanos = THREAD_MX_BEAN.getThreadCpuTime(threadId);
+ } else {
+ this.startCpuTimeNanos = UNSUPPORTED;
+ }
+ }
+
+ /**
+ * Get the cpu usage information for the thread that created this {@link ThreadStats}. The
+ * information will track the thread's cpu since the creation of this {@link ThreadStats}
+ * instance, if the VM's cpu tracking is disabled, returned value counr be {@link #UNSUPPORTED}
+ */
+ public Optional<Long> getCpuTimeMs() {
+ if (THREAD_MX_BEAN != null) {
+ long cpuTimeMs =
+ this.startCpuTimeNanos != UNSUPPORTED
+ ? TimeUnit.NANOSECONDS.toMillis(
+ THREAD_MX_BEAN.getThreadCpuTime(threadId) - this.startCpuTimeNanos)
+ : UNSUPPORTED;
+ return Optional.of(cpuTimeMs);
+ } else {
+ return Optional.empty();
+ }
+ }
+
+ @Override
+ public String toString() {
+ return getCpuTimeMs().toString();
+ }
+}
diff --git a/solr/core/src/test/org/apache/solr/TestCpuTimeSearch.java b/solr/core/src/test/org/apache/solr/TestCpuTimeSearch.java
new file mode 100644
index 00000000000..9c963a1c27c
--- /dev/null
+++ b/solr/core/src/test/org/apache/solr/TestCpuTimeSearch.java
@@ -0,0 +1,137 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+package org.apache.solr;
+
+import java.io.IOException;
+import java.nio.file.Path;
+import java.util.List;
+import org.apache.lucene.tests.util.LuceneTestCase;
+import org.apache.solr.client.solrj.SolrClient;
+import org.apache.solr.client.solrj.SolrQuery;
+import org.apache.solr.client.solrj.SolrServerException;
+import org.apache.solr.client.solrj.response.QueryResponse;
+import org.apache.solr.common.SolrDocumentList;
+import org.apache.solr.common.SolrInputDocument;
+import org.apache.solr.common.params.ShardParams;
+import org.apache.solr.common.util.NamedList;
+import org.apache.solr.security.AllowListUrlChecker;
+import org.apache.solr.util.SolrJettyTestRule;
+import org.apache.solr.util.ThreadStats;
+import org.junit.AfterClass;
+import org.junit.BeforeClass;
+import org.junit.ClassRule;
+
+public class TestCpuTimeSearch extends SolrTestCaseJ4 {
+
+ @ClassRule public static final SolrJettyTestRule solrRule = new SolrJettyTestRule();
+
+ private static SolrClient clientCore1;
+ private static SolrClient clientCore2;
+ private static String shard1;
+ private static String shard2;
+
+ @BeforeClass
+ public static void setupSolr() throws Exception {
+ System.setProperty(ThreadStats.ENABLE_CPU_TIME, "true");
+ System.setProperty(AllowListUrlChecker.DISABLE_URL_ALLOW_LIST, "true");
+
+ Path configSet = createTempDir("configSet");
+ copyMinConf(configSet.toFile());
+ solrRule.startSolr(LuceneTestCase.createTempDir());
+
+ solrRule.newCollection("core1").withConfigSet(configSet.toString()).create();
+ solrRule.newCollection("core2").withConfigSet(configSet.toString()).create();
+ clientCore1 = solrRule.getSolrClient("core1");
+ clientCore2 = solrRule.getSolrClient("core2");
+
+ String urlCore1 = solrRule.getBaseUrl() + "/" + "core1";
+ String urlCore2 = solrRule.getBaseUrl() + "/" + "core2";
+ shard1 = urlCore1.replaceAll("https?://", "");
+ shard2 = urlCore2.replaceAll("https?://", "");
+
+ SolrInputDocument doc = new SolrInputDocument();
+ doc.setField("id", "1");
+ doc.setField("subject", "batman");
+ doc.setField("title", "foo bar");
+ clientCore1.add(doc);
+ clientCore1.commit();
+
+ doc.setField("id", "2");
+ doc.setField("subject", "superman");
+ clientCore2.add(doc);
+ clientCore2.commit();
+ }
+
+ @AfterClass
+ public static void cleanup() throws Exception {
+ if (null != clientCore1) {
+ clientCore1.close();
+ clientCore1 = null;
+ }
+ if (null != clientCore2) {
+ clientCore2.close();
+ clientCore2 = null;
+ }
+ }
+
+ public void testWithoutDistrib() throws SolrServerException, IOException {
+ SolrQuery query = new SolrQuery();
+ query.setQuery("subject:batman OR subject:superman");
+ query.addField("id");
+ query.addField("subject");
+
+ QueryResponse response = clientCore1.query(query);
+
+ SolrDocumentList results = response.getResults();
+ int size = results.size();
+ assertEquals("should have 1 result", 1, size);
+ NamedList<Object> header = response.getHeader();
+ List<Object> localCpuTimes = header.getAll(ThreadStats.LOCAL_CPU_TIME);
+ List<Object> cpuTimes = header.getAll(ThreadStats.CPU_TIME);
+ assertEquals("localCpuTime should not have values", 0, localCpuTimes.size());
+ assertEquals("cpuTime should only have one value", 1, cpuTimes.size());
+ long cpuTime = (long) cpuTimes.iterator().next();
+ assertTrue("cpuTime (" + cpuTime + ") should be positive", cpuTime >= 0);
+ }
+
+ public void testWithDistrib() throws SolrServerException, IOException {
+ SolrQuery query = new SolrQuery();
+ query.setQuery("subject:batman OR subject:superman");
+ query.addField("id");
+ query.addField("subject");
+ query.set("distrib", "true");
+ query.set("shards", shard1 + "," + shard2);
+ query.set(ShardParams.SHARDS_INFO, "true");
+ query.set("debug", "true");
+ query.set("stats", "true");
+ query.set("stats.field", "id");
+ query.set(ShardParams.SHARDS_TOLERANT, "true");
+
+ QueryResponse response = clientCore1.query(query);
+
+ SolrDocumentList results = response.getResults();
+ int size = results.size();
+ assertEquals("should have 2 results", 2, size);
+ NamedList<Object> header = response.getHeader();
+ List<Object> localCpuTimes = header.getAll(ThreadStats.LOCAL_CPU_TIME);
+ List<Object> cpuTimes = header.getAll(ThreadStats.CPU_TIME);
+ assertEquals("localCpuTime should not have values", 0, localCpuTimes.size());
+ assertEquals("cpuTime should only have one value", 1, cpuTimes.size());
+ long cpuTime = (long) cpuTimes.iterator().next();
+ assertTrue("cpuTime (" + cpuTime + ") should be positive", cpuTime >= 0);
+ }
+}