Skip to content

Commit 69e6b46

Browse files
SunnyBoy-WYHimbajin
SunnyBoy-WYH
and
imbajin
authored
feat(api): support recording slow query log (#2327)
* chore(api): code style for cr --------- Co-authored-by: imbajin <[email protected]>
1 parent 4d5f419 commit 69e6b46

File tree

8 files changed

+206
-2
lines changed

8 files changed

+206
-2
lines changed

‎hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java‎

Lines changed: 44 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@
1717

1818
package org.apache.hugegraph.api.filter;
1919

20+
import static org.apache.hugegraph.api.filter.PathFilter.REQUEST_PARAMS_JSON;
2021
import static org.apache.hugegraph.api.filter.PathFilter.REQUEST_TIME;
2122
import static org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_FAILED_COUNTER;
2223
import static org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_RESPONSE_TIME_HISTOGRAM;
@@ -25,12 +26,20 @@
2526

2627
import java.io.IOException;
2728

29+
import org.apache.hugegraph.config.HugeConfig;
30+
import org.apache.hugegraph.config.ServerOptions;
2831
import org.apache.hugegraph.metrics.MetricsUtil;
32+
import org.apache.hugegraph.metrics.SlowQueryLog;
33+
import org.apache.hugegraph.util.JsonUtil;
34+
import org.apache.hugegraph.util.Log;
35+
import org.slf4j.Logger;
2936

3037
import jakarta.inject.Singleton;
38+
import jakarta.ws.rs.HttpMethod;
3139
import jakarta.ws.rs.container.ContainerRequestContext;
3240
import jakarta.ws.rs.container.ContainerResponseContext;
3341
import jakarta.ws.rs.container.ContainerResponseFilter;
42+
import jakarta.ws.rs.core.Context;
3443
import jakarta.ws.rs.ext.Provider;
3544

3645

@@ -39,6 +48,14 @@
3948
public class AccessLogFilter implements ContainerResponseFilter {
4049

4150
private static final String DELIMETER = "/";
51+
private static final String GRAPHS = "graphs";
52+
private static final String GREMLIN = "gremlin";
53+
private static final String CYPHER = "cypher";
54+
55+
private static final Logger LOG = Log.logger(AccessLogFilter.class);
56+
57+
@Context
58+
private jakarta.inject.Provider<HugeConfig> configProvider;
4259

4360
/**
4461
* Use filter to log request info
@@ -62,13 +79,24 @@ public void filter(ContainerRequestContext requestContext, ContainerResponseCont
6279

6380
// get responseTime
6481
Object requestTime = requestContext.getProperty(REQUEST_TIME);
65-
if(requestTime!=null){
82+
if(requestTime != null){
6683
long now = System.currentTimeMillis();
67-
long responseTime = (now - (long)requestTime);
84+
long start = (Long) requestTime;
85+
long responseTime = now - start;
6886

6987
MetricsUtil.registerHistogram(
7088
join(metricsName, METRICS_PATH_RESPONSE_TIME_HISTOGRAM))
7189
.update(responseTime);
90+
91+
HugeConfig config = configProvider.get();
92+
long timeThreshold = config.get(ServerOptions.SLOW_QUERY_LOG_TIME_THRESHOLD);
93+
94+
// record slow query log
95+
if (timeThreshold > 0 && isSlowQueryLogWhiteAPI(requestContext) && responseTime > timeThreshold) {
96+
SlowQueryLog log = new SlowQueryLog(responseTime, start, (String) requestContext.getProperty(REQUEST_PARAMS_JSON),
97+
method, timeThreshold, path);
98+
LOG.info("Slow query: {}", JsonUtil.toJson(log));
99+
}
72100
}
73101
}
74102

@@ -79,4 +107,18 @@ private String join(String path1, String path2) {
79107
private boolean statusOk(int status){
80108
return status == 200 || status == 201 || status == 202;
81109
}
110+
111+
public static boolean isSlowQueryLogWhiteAPI(ContainerRequestContext context) {
112+
String path = context.getUriInfo().getPath();
113+
String method = context.getRequest().getMethod();
114+
115+
// GraphsAPI/CypherAPI/Job GremlinAPI
116+
if (path.startsWith(GRAPHS)) {
117+
if (method.equals(HttpMethod.GET) || path.endsWith(CYPHER) || path.endsWith(GREMLIN) ){
118+
return true;
119+
}
120+
}
121+
// Raw GremlinAPI
122+
return path.startsWith(GREMLIN);
123+
}
82124
}

‎hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java‎

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,12 +17,20 @@
1717

1818
package org.apache.hugegraph.api.filter;
1919

20+
import static org.apache.hugegraph.api.API.CHARSET;
21+
2022
import java.io.IOException;
23+
import java.io.InputStream;
24+
25+
import org.apache.commons.io.Charsets;
26+
import org.apache.commons.io.IOUtils;
2127

2228
import jakarta.inject.Singleton;
29+
import jakarta.ws.rs.HttpMethod;
2330
import jakarta.ws.rs.container.ContainerRequestContext;
2431
import jakarta.ws.rs.container.ContainerRequestFilter;
2532
import jakarta.ws.rs.container.PreMatching;
33+
import jakarta.ws.rs.core.MultivaluedMap;
2634
import jakarta.ws.rs.ext.Provider;
2735

2836
@Provider
@@ -31,10 +39,26 @@
3139
public class PathFilter implements ContainerRequestFilter {
3240

3341
public static final String REQUEST_TIME = "request_time";
42+
public static final String REQUEST_PARAMS_JSON = "request_params_json";
3443

3544
@Override
3645
public void filter(ContainerRequestContext context)
3746
throws IOException {
3847
context.setProperty(REQUEST_TIME, System.currentTimeMillis());
48+
49+
// record the request json
50+
String method = context.getMethod();
51+
String requestParamsJson = "";
52+
if (method.equals(HttpMethod.POST)) {
53+
requestParamsJson = IOUtils.toString(context.getEntityStream(), Charsets.toCharset(CHARSET));
54+
// replace input stream because we have already read it
55+
InputStream in = IOUtils.toInputStream(requestParamsJson, Charsets.toCharset(CHARSET));
56+
context.setEntityStream(in);
57+
} else if(method.equals(HttpMethod.GET)){
58+
MultivaluedMap<String, String> pathParameters = context.getUriInfo().getPathParameters();
59+
requestParamsJson = pathParameters.toString();
60+
}
61+
62+
context.setProperty(REQUEST_PARAMS_JSON, requestParamsJson);
3963
}
4064
}

‎hugegraph-api/src/main/java/org/apache/hugegraph/config/ServerOptions.java‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -304,4 +304,13 @@ public static synchronized ServerOptions instance() {
304304
null,
305305
"jad"
306306
);
307+
308+
public static final ConfigOption<Long> SLOW_QUERY_LOG_TIME_THRESHOLD =
309+
new ConfigOption<>(
310+
"log.slow_query_threshold",
311+
"The threshold time(ms) of logging slow query, " +
312+
"0 means logging slow query is disabled.",
313+
nonNegativeInt(),
314+
1000L
315+
);
307316
}

‎hugegraph-api/src/main/java/org/apache/hugegraph/metrics/SlowQueryLog.java‎

Lines changed: 43 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,43 @@
1+
/*
2+
* Licensed to the Apache Software Foundation (ASF) under one or more
3+
* contributor license agreements. See the NOTICE file distributed with this
4+
* work for additional information regarding copyright ownership. The ASF
5+
* licenses this file to You under the Apache License, Version 2.0 (the
6+
* "License"); you may not use this file except in compliance with the License.
7+
* You may obtain a copy of the License at
8+
*
9+
* http://www.apache.org/licenses/LICENSE-2.0
10+
*
11+
* Unless required by applicable law or agreed to in writing, software
12+
* distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
13+
* WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
14+
* License for the specific language governing permissions and limitations
15+
* under the License.
16+
*/
17+
package org.apache.hugegraph.metrics;
18+
19+
20+
public class SlowQueryLog {
21+
22+
public Long executeTime;
23+
24+
public Long startTime;
25+
26+
public String rawQuery;
27+
28+
public String method;
29+
30+
public Long threshold;
31+
32+
public String path;
33+
34+
public SlowQueryLog(Long executeTime, Long startTime, String rawQuery, String method, Long threshold,
35+
String path) {
36+
this.executeTime = executeTime;
37+
this.startTime = startTime;
38+
this.rawQuery = rawQuery;
39+
this.method = method;
40+
this.threshold = threshold;
41+
this.path = path;
42+
}
43+
}

‎hugegraph-dist/src/assembly/static/conf/log4j2.xml‎

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -76,6 +76,30 @@
7676
</Delete>
7777
</DefaultRolloverStrategy>
7878
</RollingRandomAccessFile>
79+
80+
<!-- Slow query log config -->
81+
<RollingRandomAccessFile name="slowQueryLog" fileName="${LOG_PATH}/slow_query.log"
82+
filePattern="${LOG_PATH}/$${date:yyyy-MM}/slow_query_log-%d{yyyy-MM-dd}-%i.log"
83+
immediateFlush="false">
84+
<ThresholdFilter level="TRACE" onMatch="ACCEPT" onMismatch="DENY"/>
85+
<PatternLayout pattern="%-d{yyyy-MM-dd HH:mm:ss} [%t] [%p] %c{1.} - %m%n"/>
86+
<!-- Trigger after exceeding 1day or 50MB -->
87+
<Policies>
88+
<SizeBasedTriggeringPolicy size="50MB"/>
89+
<TimeBasedTriggeringPolicy interval="1" modulate="true" />
90+
</Policies>
91+
<!-- Keep 5 files per day & auto delete after over 2GB or 100 files -->
92+
<DefaultRolloverStrategy max="5">
93+
<Delete basePath="${LOG_PATH}" maxDepth="2">
94+
<IfFileName glob="*/*.log"/>
95+
<!-- Limit log amount & size -->
96+
<IfAny>
97+
<IfAccumulatedFileSize exceeds="2GB" />
98+
<IfAccumulatedFileCount exceeds="100" />
99+
</IfAny>
100+
</Delete>
101+
</DefaultRolloverStrategy>
102+
</RollingRandomAccessFile>
79103
</appenders>
80104

81105
<loggers>
@@ -113,5 +137,8 @@
113137
<AsyncLogger name="org.apache.hugegraph.api.filter.AuthenticationFilter" level="INFO" additivity="false">
114138
<appender-ref ref="audit"/>
115139
</AsyncLogger>
140+
<AsyncLogger name="org.apache.hugegraph.api.filter.AccessLogFilter" level="INFO" additivity="false">
141+
<appender-ref ref="slowQueryLog"/>
142+
</AsyncLogger>
116143
</loggers>
117144
</configuration>

‎hugegraph-dist/src/assembly/static/conf/rest-server.properties‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -48,3 +48,6 @@ rpc.server_port=8091
4848
# lightweight load balancing (beta)
4949
server.id=server-1
5050
server.role=master
51+
52+
# slow query log
53+
log.slow_query_threshold=1000

‎hugegraph-dist/src/main/resources/log4j2.xml‎

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -76,6 +76,30 @@
7676
</Delete>
7777
</DefaultRolloverStrategy>
7878
</RollingRandomAccessFile>
79+
80+
<!-- Slow query log config -->
81+
<RollingRandomAccessFile name="slowQueryLog" fileName="${LOG_PATH}/slow_query.log"
82+
filePattern="${LOG_PATH}/$${date:yyyy-MM}/slow_query_log-%d{yyyy-MM-dd}-%i.log"
83+
immediateFlush="false">
84+
<ThresholdFilter level="TRACE" onMatch="ACCEPT" onMismatch="DENY"/>
85+
<PatternLayout pattern="%-d{yyyy-MM-dd HH:mm:ss} [%t] [%p] %c{1.} - %m%n"/>
86+
<!-- Trigger after exceeding 1day or 50MB -->
87+
<Policies>
88+
<SizeBasedTriggeringPolicy size="50MB"/>
89+
<TimeBasedTriggeringPolicy interval="1" modulate="true" />
90+
</Policies>
91+
<!-- Keep 5 files per day & auto delete after over 2GB or 100 files -->
92+
<DefaultRolloverStrategy max="5">
93+
<Delete basePath="${LOG_PATH}" maxDepth="2">
94+
<IfFileName glob="*/*.log"/>
95+
<!-- Limit log amount & size -->
96+
<IfAny>
97+
<IfAccumulatedFileSize exceeds="2GB" />
98+
<IfAccumulatedFileCount exceeds="100" />
99+
</IfAny>
100+
</Delete>
101+
</DefaultRolloverStrategy>
102+
</RollingRandomAccessFile>
79103
</appenders>
80104

81105
<loggers>
@@ -124,5 +148,9 @@
124148
<appender-ref ref="console"/>
125149
<appender-ref ref="audit"/>
126150
</AsyncLogger>
151+
<AsyncLogger name="org.apache.hugegraph.api.filter.AccessLogFilter" level="INFO" additivity="false">
152+
<appender-ref ref="console"/>
153+
<appender-ref ref="slowQueryLog"/>
154+
</AsyncLogger>
127155
</loggers>
128156
</configuration>

‎hugegraph-test/src/main/resources/log4j2.xml‎

Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -76,6 +76,30 @@
7676
</Delete>
7777
</DefaultRolloverStrategy>
7878
</RollingRandomAccessFile>
79+
80+
<!-- Slow query log config -->
81+
<RollingRandomAccessFile name="slowQueryLog" fileName="${LOG_PATH}/slow_query.log"
82+
filePattern="${LOG_PATH}/$${date:yyyy-MM}/slow_query_log-%d{yyyy-MM-dd}-%i.log"
83+
immediateFlush="false">
84+
<ThresholdFilter level="TRACE" onMatch="ACCEPT" onMismatch="DENY"/>
85+
<PatternLayout pattern="%-d{yyyy-MM-dd HH:mm:ss} [%t] [%p] %c{1.} - %m%n"/>
86+
<!-- Trigger after exceeding 1day or 50MB -->
87+
<Policies>
88+
<SizeBasedTriggeringPolicy size="50MB"/>
89+
<TimeBasedTriggeringPolicy interval="1" modulate="true" />
90+
</Policies>
91+
<!-- Keep 5 files per day & auto delete after over 2GB or 100 files -->
92+
<DefaultRolloverStrategy max="5">
93+
<Delete basePath="${LOG_PATH}" maxDepth="2">
94+
<IfFileName glob="*/*.log"/>
95+
<!-- Limit log amount & size -->
96+
<IfAny>
97+
<IfAccumulatedFileSize exceeds="2GB" />
98+
<IfAccumulatedFileCount exceeds="100" />
99+
</IfAny>
100+
</Delete>
101+
</DefaultRolloverStrategy>
102+
</RollingRandomAccessFile>
79103
</appenders>
80104

81105
<loggers>
@@ -124,5 +148,9 @@
124148
<appender-ref ref="console"/>
125149
<appender-ref ref="audit"/>
126150
</AsyncLogger>
151+
<AsyncLogger name="org.apache.hugegraph.api.filter.AccessLogFilter" level="INFO" additivity="false">
152+
<appender-ref ref="console"/>
153+
<appender-ref ref="slowQueryLog"/>
154+
</AsyncLogger>
127155
</loggers>
128156
</configuration>

0 commit comments

Comments
 (0)