Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 12 commits into from
Nov 6, 2023
Merged

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

Show file tree
Hide file tree
Changes from 11 commits
Commits
Show all changes
12 commits
Select commit Hold shift + click to select a range
073c479
feat(api): support recording slow query log
SunnyBoy-WYH Oct 15, 2023
4bfd688
feat(api): support recording slow query log
SunnyBoy-WYH Oct 16, 2023
e1e5777
feat(api): support recording slow query log
SunnyBoy-WYH Oct 16, 2023
7a7bd88
feat(api): support recording slow query log
SunnyBoy-WYH Oct 16, 2023
d3d91b1
feat(api): support recording slow query log
SunnyBoy-WYH Oct 16, 2023
6826944
chore(api): code style for cr
SunnyBoy-WYH Oct 20, 2023
ae62019
chore(api): code style for cr
SunnyBoy-WYH Oct 20, 2023
cd6b4f1
Merge branch 'master' into slow-query-log
imbajin Oct 22, 2023
2b3c0ab
chore(api): code style for cr
SunnyBoy-WYH Oct 22, 2023
30134c3
Merge branch 'master' into slow-query-log
SunnyBoy-WYH Oct 22, 2023
8bdc89b
Merge remote-tracking branch 'origin/slow-query-log' into slow-query-log
SunnyBoy-WYH Oct 22, 2023
6d3be26
chore(api): code style for cr
SunnyBoy-WYH Oct 23, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
52 changes: 50 additions & 2 deletions hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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;


Expand All @@ -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
Expand All @@ -62,13 +79,24 @@ public void filter(ContainerRequestContext requestContext, ContainerResponseCont

// get responseTime
Object requestTime = requestContext.getProperty(REQUEST_TIME);
if(requestTime!=null){
if(requestTime != null){
SunnyBoy-WYH marked this conversation as resolved.
Show resolved Hide resolved
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);
SunnyBoy-WYH marked this conversation as resolved.
Show resolved Hide resolved
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Holding the timeThreshold in a private variable and changing its type to long would be better, reducing the cost of unboxing and hash searching.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

thanks ， but i dont know “Holding the timeThreshold in a private variable ” means what？ thanks again

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just like this:

public class AccessLogFilter implements ContainerResponseFilter {
     private long timeThreshold =configProvider.get().get(ServerOptions.SLOW_QUERY_LOG_TIME_THRESHOLD);

.....
}

Of course, you need to check for null.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just like this:

public class AccessLogFilter implements ContainerResponseFilter {
     private long timeThreshold =configProvider.get().get(ServerOptions.SLOW_QUERY_LOG_TIME_THRESHOLD);

.....
}

Of course, you need to check for null.

we cant get timeThreshold as private var from configProvider, because configProvider managed by @context; it will case NPE.


// 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));
}
}
}

Expand All @@ -79,4 +107,24 @@ 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
if (path.startsWith(GRAPHS) && method.equals(HttpMethod.GET)) {
return true;
}
// CypherAPI
if (path.startsWith(GRAPHS) && path.endsWith(CYPHER)) {
return true;
}
// Job GremlinAPI
if (path.startsWith(GRAPHS) && path.endsWith(GREMLIN)) {
return true;
}
SunnyBoy-WYH marked this conversation as resolved.
Show resolved Hide resolved
// Raw GremlinAPI
return path.startsWith(GREMLIN);
}
}
24 changes: 24 additions & 0 deletions hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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);
}
}
9 changes: 9 additions & 0 deletions hugegraph-api/src/main/java/org/apache/hugegraph/config/ServerOptions.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
);
}
43 changes: 43 additions & 0 deletions hugegraph-api/src/main/java/org/apache/hugegraph/metrics/SlowQueryLog.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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;
}
}
27 changes: 27 additions & 0 deletions hugegraph-dist/src/assembly/static/conf/log4j2.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -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>
3 changes: 3 additions & 0 deletions hugegraph-dist/src/assembly/static/conf/rest-server.properties
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
28 changes: 28 additions & 0 deletions hugegraph-dist/src/main/resources/log4j2.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -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>
28 changes: 28 additions & 0 deletions hugegraph-test/src/main/resources/log4j2.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand Down Expand Up @@ -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>
Loading