feat(api): support recording slow query log (#2327)

* chore(api): code style for cr --------- Co-authored-by: imbajin <jin@apache.org>
apache · Nov 10, 2023 · 896d943 · 896d943
1 parent 73bf660
commit 896d943
Show file tree

Hide file tree

Showing 8 changed files with 206 additions and 2 deletions.
diff --git a/...h-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java b/...h-server/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 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 @@
 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 void filter(ContainerRequestContext requestContext, ContainerResponseCont
 
         // 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 @@ private String join(String path1, String path2) {
     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-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java b/hugegraph-server/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 @@
 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-server/hugegraph-api/src/main/java/org/apache/hugegraph/config/ServerOptions.java b/hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/config/ServerOptions.java
@@ -304,4 +304,13 @@ public static synchronized ServerOptions instance() {
             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-server/hugegraph-api/src/main/java/org/apache/hugegraph/metrics/SlowQueryLog.java b/hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/metrics/SlowQueryLog.java
@@ -0,0 +1,43 @@
+/*
+ * 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.hugegraph.metrics;
+
+
+public class SlowQueryLog {
+
+    public Long executeTime;
+
+    public Long startTime;
+
+    public String rawQuery;
+
+    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-server/hugegraph-dist/src/assembly/static/conf/log4j2.xml b/hugegraph-server/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-server/hugegraph-dist/src/assembly/static/conf/rest-server.properties b/hugegraph-server/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-server/hugegraph-dist/src/main/resources/log4j2.xml b/hugegraph-server/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-server/hugegraph-test/src/main/resources/log4j2.xml b/hugegraph-server/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>