This is an automated email from the ASF dual-hosted git repository.
jin pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-hugegraph.git
The following commit(s) were added to refs/heads/master by this push:
new 69e6b461a feat(api): support recording slow query log (#2327)
69e6b461a is described below
commit 69e6b461add1051831dd6cc0c36a5e249a3b3176
Author: SunnyBoy-WYH <[email protected]>
AuthorDate: Mon Nov 6 14:34:12 2023 +0800
feat(api): support recording slow query log (#2327)
* chore(api): code style for cr
---------
Co-authored-by: imbajin <[email protected]>
---
.../hugegraph/api/filter/AccessLogFilter.java | 46 +++++++++++++++++++++-
.../apache/hugegraph/api/filter/PathFilter.java | 24 +++++++++++
.../org/apache/hugegraph/config/ServerOptions.java | 9 +++++
.../PathFilter.java => metrics/SlowQueryLog.java} | 35 ++++++++--------
hugegraph-dist/src/assembly/static/conf/log4j2.xml | 27 +++++++++++++
.../assembly/static/conf/rest-server.properties | 3 ++
hugegraph-dist/src/main/resources/log4j2.xml | 28 +++++++++++++
hugegraph-test/src/main/resources/log4j2.xml | 28 +++++++++++++
8 files changed, 182 insertions(+), 18 deletions(-)
diff --git
a/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java
b/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java
index ba9c98118..3b529cf0a 100644
---
a/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java
+++
b/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java
@@ -17,6 +17,7 @@
package org.apache.hugegraph.api.filter;
+import static org.apache.hugegraph.api.filter.PathFilter.REQUEST_PARAMS_JSON;
import static org.apache.hugegraph.api.filter.PathFilter.REQUEST_TIME;
import static
org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_FAILED_COUNTER;
import static
org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_RESPONSE_TIME_HISTOGRAM;
@@ -25,12 +26,20 @@ import static
org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_TOTAL_COUNTE
import java.io.IOException;
+import org.apache.hugegraph.config.HugeConfig;
+import org.apache.hugegraph.config.ServerOptions;
import org.apache.hugegraph.metrics.MetricsUtil;
+import org.apache.hugegraph.metrics.SlowQueryLog;
+import org.apache.hugegraph.util.JsonUtil;
+import org.apache.hugegraph.util.Log;
+import org.slf4j.Logger;
import jakarta.inject.Singleton;
+import jakarta.ws.rs.HttpMethod;
import jakarta.ws.rs.container.ContainerRequestContext;
import jakarta.ws.rs.container.ContainerResponseContext;
import jakarta.ws.rs.container.ContainerResponseFilter;
+import jakarta.ws.rs.core.Context;
import jakarta.ws.rs.ext.Provider;
@@ -39,6 +48,14 @@ import jakarta.ws.rs.ext.Provider;
public class AccessLogFilter implements ContainerResponseFilter {
private static final String DELIMETER = "/";
+ private static final String GRAPHS = "graphs";
+ private static final String GREMLIN = "gremlin";
+ private static final String CYPHER = "cypher";
+
+ private static final Logger LOG = Log.logger(AccessLogFilter.class);
+
+ @Context
+ private jakarta.inject.Provider<HugeConfig> configProvider;
/**
* Use filter to log request info
@@ -62,13 +79,24 @@ public class AccessLogFilter implements
ContainerResponseFilter {
// get responseTime
Object requestTime = requestContext.getProperty(REQUEST_TIME);
- if(requestTime!=null){
+ if(requestTime != null){
long now = System.currentTimeMillis();
- long responseTime = (now - (long)requestTime);
+ long start = (Long) requestTime;
+ long responseTime = now - start;
MetricsUtil.registerHistogram(
join(metricsName,
METRICS_PATH_RESPONSE_TIME_HISTOGRAM))
.update(responseTime);
+
+ HugeConfig config = configProvider.get();
+ long timeThreshold =
config.get(ServerOptions.SLOW_QUERY_LOG_TIME_THRESHOLD);
+
+ // record slow query log
+ if (timeThreshold > 0 && isSlowQueryLogWhiteAPI(requestContext) &&
responseTime > timeThreshold) {
+ SlowQueryLog log = new SlowQueryLog(responseTime, start,
(String) requestContext.getProperty(REQUEST_PARAMS_JSON),
+ method, timeThreshold,
path);
+ LOG.info("Slow query: {}", JsonUtil.toJson(log));
+ }
}
}
@@ -79,4 +107,18 @@ public class AccessLogFilter implements
ContainerResponseFilter {
private boolean statusOk(int status){
return status == 200 || status == 201 || status == 202;
}
+
+ public static boolean isSlowQueryLogWhiteAPI(ContainerRequestContext
context) {
+ String path = context.getUriInfo().getPath();
+ String method = context.getRequest().getMethod();
+
+ // GraphsAPI/CypherAPI/Job GremlinAPI
+ if (path.startsWith(GRAPHS)) {
+ if (method.equals(HttpMethod.GET) || path.endsWith(CYPHER) ||
path.endsWith(GREMLIN) ){
+ return true;
+ }
+ }
+ // Raw GremlinAPI
+ return path.startsWith(GREMLIN);
+ }
}
diff --git
a/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java
b/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java
index 3414d6831..e1e449ef2 100644
---
a/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java
+++
b/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java
@@ -17,12 +17,20 @@
package org.apache.hugegraph.api.filter;
+import static org.apache.hugegraph.api.API.CHARSET;
+
import java.io.IOException;
+import java.io.InputStream;
+
+import org.apache.commons.io.Charsets;
+import org.apache.commons.io.IOUtils;
import jakarta.inject.Singleton;
+import jakarta.ws.rs.HttpMethod;
import jakarta.ws.rs.container.ContainerRequestContext;
import jakarta.ws.rs.container.ContainerRequestFilter;
import jakarta.ws.rs.container.PreMatching;
+import jakarta.ws.rs.core.MultivaluedMap;
import jakarta.ws.rs.ext.Provider;
@Provider
@@ -31,10 +39,26 @@ import jakarta.ws.rs.ext.Provider;
public class PathFilter implements ContainerRequestFilter {
public static final String REQUEST_TIME = "request_time";
+ public static final String REQUEST_PARAMS_JSON = "request_params_json";
@Override
public void filter(ContainerRequestContext context)
throws IOException {
context.setProperty(REQUEST_TIME, System.currentTimeMillis());
+
+ // record the request json
+ String method = context.getMethod();
+ String requestParamsJson = "";
+ if (method.equals(HttpMethod.POST)) {
+ requestParamsJson = IOUtils.toString(context.getEntityStream(),
Charsets.toCharset(CHARSET));
+ // replace input stream because we have already read it
+ InputStream in = IOUtils.toInputStream(requestParamsJson,
Charsets.toCharset(CHARSET));
+ context.setEntityStream(in);
+ } else if(method.equals(HttpMethod.GET)){
+ MultivaluedMap<String, String> pathParameters =
context.getUriInfo().getPathParameters();
+ requestParamsJson = pathParameters.toString();
+ }
+
+ context.setProperty(REQUEST_PARAMS_JSON, requestParamsJson);
}
}
diff --git
a/hugegraph-api/src/main/java/org/apache/hugegraph/config/ServerOptions.java
b/hugegraph-api/src/main/java/org/apache/hugegraph/config/ServerOptions.java
index e8b999fb5..a8bbe5a5f 100644
--- a/hugegraph-api/src/main/java/org/apache/hugegraph/config/ServerOptions.java
+++ b/hugegraph-api/src/main/java/org/apache/hugegraph/config/ServerOptions.java
@@ -304,4 +304,13 @@ public class ServerOptions extends OptionHolder {
null,
"jad"
);
+
+ public static final ConfigOption<Long> SLOW_QUERY_LOG_TIME_THRESHOLD =
+ new ConfigOption<>(
+ "log.slow_query_threshold",
+ "The threshold time(ms) of logging slow query, " +
+ "0 means logging slow query is disabled.",
+ nonNegativeInt(),
+ 1000L
+ );
}
diff --git
a/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java
b/hugegraph-api/src/main/java/org/apache/hugegraph/metrics/SlowQueryLog.java
similarity index 56%
copy from
hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java
copy to
hugegraph-api/src/main/java/org/apache/hugegraph/metrics/SlowQueryLog.java
index 3414d6831..cb3f1c712 100644
---
a/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java
+++ b/hugegraph-api/src/main/java/org/apache/hugegraph/metrics/SlowQueryLog.java
@@ -14,27 +14,30 @@
* License for the specific language governing permissions and limitations
* under the License.
*/
+package org.apache.hugegraph.metrics;
-package org.apache.hugegraph.api.filter;
-import java.io.IOException;
+public class SlowQueryLog {
-import jakarta.inject.Singleton;
-import jakarta.ws.rs.container.ContainerRequestContext;
-import jakarta.ws.rs.container.ContainerRequestFilter;
-import jakarta.ws.rs.container.PreMatching;
-import jakarta.ws.rs.ext.Provider;
+ public Long executeTime;
-@Provider
-@Singleton
-@PreMatching
-public class PathFilter implements ContainerRequestFilter {
+ public Long startTime;
- public static final String REQUEST_TIME = "request_time";
+ public String rawQuery;
- @Override
- public void filter(ContainerRequestContext context)
- throws IOException {
- context.setProperty(REQUEST_TIME, System.currentTimeMillis());
+ public String method;
+
+ public Long threshold;
+
+ public String path;
+
+ public SlowQueryLog(Long executeTime, Long startTime, String rawQuery,
String method, Long threshold,
+ String path) {
+ this.executeTime = executeTime;
+ this.startTime = startTime;
+ this.rawQuery = rawQuery;
+ this.method = method;
+ this.threshold = threshold;
+ this.path = path;
}
}
diff --git a/hugegraph-dist/src/assembly/static/conf/log4j2.xml
b/hugegraph-dist/src/assembly/static/conf/log4j2.xml
index 985ab78b2..db58e8911 100644
--- a/hugegraph-dist/src/assembly/static/conf/log4j2.xml
+++ b/hugegraph-dist/src/assembly/static/conf/log4j2.xml
@@ -76,6 +76,30 @@
</Delete>
</DefaultRolloverStrategy>
</RollingRandomAccessFile>
+
+ <!-- Slow query log config -->
+ <RollingRandomAccessFile name="slowQueryLog"
fileName="${LOG_PATH}/slow_query.log"
+
filePattern="${LOG_PATH}/$${date:yyyy-MM}/slow_query_log-%d{yyyy-MM-dd}-%i.log"
+ immediateFlush="false">
+ <ThresholdFilter level="TRACE" onMatch="ACCEPT" onMismatch="DENY"/>
+ <PatternLayout pattern="%-d{yyyy-MM-dd HH:mm:ss} [%t] [%p] %c{1.}
- %m%n"/>
+ <!-- Trigger after exceeding 1day or 50MB -->
+ <Policies>
+ <SizeBasedTriggeringPolicy size="50MB"/>
+ <TimeBasedTriggeringPolicy interval="1" modulate="true" />
+ </Policies>
+ <!-- Keep 5 files per day & auto delete after over 2GB or 100
files -->
+ <DefaultRolloverStrategy max="5">
+ <Delete basePath="${LOG_PATH}" maxDepth="2">
+ <IfFileName glob="*/*.log"/>
+ <!-- Limit log amount & size -->
+ <IfAny>
+ <IfAccumulatedFileSize exceeds="2GB" />
+ <IfAccumulatedFileCount exceeds="100" />
+ </IfAny>
+ </Delete>
+ </DefaultRolloverStrategy>
+ </RollingRandomAccessFile>
</appenders>
<loggers>
@@ -113,5 +137,8 @@
<AsyncLogger
name="org.apache.hugegraph.api.filter.AuthenticationFilter" level="INFO"
additivity="false">
<appender-ref ref="audit"/>
</AsyncLogger>
+ <AsyncLogger name="org.apache.hugegraph.api.filter.AccessLogFilter"
level="INFO" additivity="false">
+ <appender-ref ref="slowQueryLog"/>
+ </AsyncLogger>
</loggers>
</configuration>
diff --git a/hugegraph-dist/src/assembly/static/conf/rest-server.properties
b/hugegraph-dist/src/assembly/static/conf/rest-server.properties
index f6444f84f..23f78c582 100644
--- a/hugegraph-dist/src/assembly/static/conf/rest-server.properties
+++ b/hugegraph-dist/src/assembly/static/conf/rest-server.properties
@@ -48,3 +48,6 @@ rpc.server_port=8091
# lightweight load balancing (beta)
server.id=server-1
server.role=master
+
+# slow query log
+log.slow_query_threshold=1000
diff --git a/hugegraph-dist/src/main/resources/log4j2.xml
b/hugegraph-dist/src/main/resources/log4j2.xml
index bdd391e58..5d8081629 100644
--- a/hugegraph-dist/src/main/resources/log4j2.xml
+++ b/hugegraph-dist/src/main/resources/log4j2.xml
@@ -76,6 +76,30 @@
</Delete>
</DefaultRolloverStrategy>
</RollingRandomAccessFile>
+
+ <!-- Slow query log config -->
+ <RollingRandomAccessFile name="slowQueryLog"
fileName="${LOG_PATH}/slow_query.log"
+
filePattern="${LOG_PATH}/$${date:yyyy-MM}/slow_query_log-%d{yyyy-MM-dd}-%i.log"
+ immediateFlush="false">
+ <ThresholdFilter level="TRACE" onMatch="ACCEPT" onMismatch="DENY"/>
+ <PatternLayout pattern="%-d{yyyy-MM-dd HH:mm:ss} [%t] [%p] %c{1.}
- %m%n"/>
+ <!-- Trigger after exceeding 1day or 50MB -->
+ <Policies>
+ <SizeBasedTriggeringPolicy size="50MB"/>
+ <TimeBasedTriggeringPolicy interval="1" modulate="true" />
+ </Policies>
+ <!-- Keep 5 files per day & auto delete after over 2GB or 100
files -->
+ <DefaultRolloverStrategy max="5">
+ <Delete basePath="${LOG_PATH}" maxDepth="2">
+ <IfFileName glob="*/*.log"/>
+ <!-- Limit log amount & size -->
+ <IfAny>
+ <IfAccumulatedFileSize exceeds="2GB" />
+ <IfAccumulatedFileCount exceeds="100" />
+ </IfAny>
+ </Delete>
+ </DefaultRolloverStrategy>
+ </RollingRandomAccessFile>
</appenders>
<loggers>
@@ -124,5 +148,9 @@
<appender-ref ref="console"/>
<appender-ref ref="audit"/>
</AsyncLogger>
+ <AsyncLogger name="org.apache.hugegraph.api.filter.AccessLogFilter"
level="INFO" additivity="false">
+ <appender-ref ref="console"/>
+ <appender-ref ref="slowQueryLog"/>
+ </AsyncLogger>
</loggers>
</configuration>
diff --git a/hugegraph-test/src/main/resources/log4j2.xml
b/hugegraph-test/src/main/resources/log4j2.xml
index e830c6248..284f53487 100644
--- a/hugegraph-test/src/main/resources/log4j2.xml
+++ b/hugegraph-test/src/main/resources/log4j2.xml
@@ -76,6 +76,30 @@
</Delete>
</DefaultRolloverStrategy>
</RollingRandomAccessFile>
+
+ <!-- Slow query log config -->
+ <RollingRandomAccessFile name="slowQueryLog"
fileName="${LOG_PATH}/slow_query.log"
+
filePattern="${LOG_PATH}/$${date:yyyy-MM}/slow_query_log-%d{yyyy-MM-dd}-%i.log"
+ immediateFlush="false">
+ <ThresholdFilter level="TRACE" onMatch="ACCEPT" onMismatch="DENY"/>
+ <PatternLayout pattern="%-d{yyyy-MM-dd HH:mm:ss} [%t] [%p] %c{1.}
- %m%n"/>
+ <!-- Trigger after exceeding 1day or 50MB -->
+ <Policies>
+ <SizeBasedTriggeringPolicy size="50MB"/>
+ <TimeBasedTriggeringPolicy interval="1" modulate="true" />
+ </Policies>
+ <!-- Keep 5 files per day & auto delete after over 2GB or 100
files -->
+ <DefaultRolloverStrategy max="5">
+ <Delete basePath="${LOG_PATH}" maxDepth="2">
+ <IfFileName glob="*/*.log"/>
+ <!-- Limit log amount & size -->
+ <IfAny>
+ <IfAccumulatedFileSize exceeds="2GB" />
+ <IfAccumulatedFileCount exceeds="100" />
+ </IfAny>
+ </Delete>
+ </DefaultRolloverStrategy>
+ </RollingRandomAccessFile>
</appenders>
<loggers>
@@ -124,5 +148,9 @@
<appender-ref ref="console"/>
<appender-ref ref="audit"/>
</AsyncLogger>
+ <AsyncLogger name="org.apache.hugegraph.api.filter.AccessLogFilter"
level="INFO" additivity="false">
+ <appender-ref ref="console"/>
+ <appender-ref ref="slowQueryLog"/>
+ </AsyncLogger>
</loggers>
</configuration>
