This is an automated email from the ASF dual-hosted git repository. jin pushed a commit to branch pd-store in repository https://gitbox.apache.org/repos/asf/incubator-hugegraph.git
commit 896d943538693c26a37f332626db7eb31c2ca55b 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 ++++++++-------- .../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-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java b/hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java index ba9c98118..3b529cf0a 100644 --- a/hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java +++ b/hugegraph-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 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-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 index 3414d6831..e1e449ef2 100644 --- 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 @@ 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-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 index e8b999fb5..a8bbe5a5f 100644 --- 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 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-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java b/hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/metrics/SlowQueryLog.java similarity index 56% copy from hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java copy to hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/metrics/SlowQueryLog.java index 3414d6831..cb3f1c712 100644 --- 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/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-server/hugegraph-dist/src/assembly/static/conf/log4j2.xml b/hugegraph-server/hugegraph-dist/src/assembly/static/conf/log4j2.xml index 985ab78b2..db58e8911 100644 --- 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 index f6444f84f..23f78c582 100644 --- 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 index bdd391e58..5d8081629 100644 --- 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 index e830c6248..284f53487 100644 --- 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>
