Skip to content

Commit

Permalink
fix(api): refactor/downgrade record logic for slow log (apache#2347)
Browse files Browse the repository at this point in the history 
* fix(api): refactor/downgrade record logic for slow log

add some TODOs & assign @SunnyBoy-WYH to address it

* fix typo

* enhance the perf
  • Loading branch information
@imbajin @VGalaxies
imbajin authored and VGalaxies committed Jan 12, 2024
1 parent 9a80183 commit a52cd9b
Show file tree
Hide file tree
Showing 3 changed files with 71 additions and 69 deletions.
82 changes: 40 additions & 42 deletions ...h-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,20 +17,18 @@

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;
import static org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_SUCCESS_COUNTER;
import static org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_TOTAL_COUNTER;

import java.io.IOException;
import java.net.URI;

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;

Expand All @@ -42,32 +40,52 @@
import jakarta.ws.rs.core.Context;
import jakarta.ws.rs.ext.Provider;


// TODO: should add test for this class
@Provider
@Singleton
public class AccessLogFilter implements ContainerResponseFilter {

private static final String DELIMETER = "/";
private static final Logger LOG = Log.logger(AccessLogFilter.class);

private static final String DELIMITER = "/";
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;

public static boolean needRecordLog(ContainerRequestContext context) {
// TODO: add test for 'path' result ('/gremlin' or 'gremlin')
String path = context.getUriInfo().getPath();

// GraphsAPI/CypherAPI/Job GremlinAPI
if (path.startsWith(GRAPHS)) {
if (HttpMethod.GET.equals(context.getMethod()) || path.endsWith(CYPHER)) {
return true;
}
}
// Direct GremlinAPI
return path.endsWith(GREMLIN);
}

private String join(String path1, String path2) {
return String.join(DELIMITER, path1, path2);
}

/**
* Use filter to log request info
*
* @param requestContext requestContext
* @param responseContext responseContext
*/
@Override
public void filter(ContainerRequestContext requestContext, ContainerResponseContext responseContext) throws IOException {
public void filter(ContainerRequestContext requestContext,
ContainerResponseContext responseContext) throws IOException {
// Grab corresponding request / response info from context;
String method = requestContext.getRequest().getMethod();
String path = requestContext.getUriInfo().getPath();
URI uri = requestContext.getUriInfo().getRequestUri();
String path = uri.getRawPath();
String method = requestContext.getMethod();
String metricsName = join(path, method);

MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_TOTAL_COUNTER)).inc();
Expand All @@ -77,48 +95,28 @@ public void filter(ContainerRequestContext requestContext, ContainerResponseCont
MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_FAILED_COUNTER)).inc();
}

// get responseTime
Object requestTime = requestContext.getProperty(REQUEST_TIME);
if(requestTime != null){
if (requestTime != null) {
long now = System.currentTimeMillis();
long start = (Long) requestTime;
long responseTime = now - start;
long executeTime = now - start;

MetricsUtil.registerHistogram(
join(metricsName, METRICS_PATH_RESPONSE_TIME_HISTOGRAM))
.update(responseTime);
MetricsUtil.registerHistogram(join(metricsName, METRICS_PATH_RESPONSE_TIME_HISTOGRAM))
.update(executeTime);

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));
// Record slow query if meet needs, watch out the perf
if (timeThreshold > 0 && executeTime > timeThreshold &&
needRecordLog(requestContext)) {
// TODO: set RequestBody null, handle it later & should record "client IP"
LOG.info("[Slow Query] execTime={}ms, body={}, method={}, path={}, query={}",
executeTime, null, method, path, uri.getQuery());
}
}
}

private String join(String path1, String path2) {
return String.join(DELIMETER, path1, 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);
private boolean statusOk(int status) {
return status >= 200 && status < 300;
}
}
24 changes: 9 additions & 15 deletions hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,20 +17,12 @@

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 @@ -42,23 +34,25 @@ public class PathFilter implements ContainerRequestFilter {
public static final String REQUEST_PARAMS_JSON = "request_params_json";

@Override
public void filter(ContainerRequestContext context)
throws IOException {
public void filter(ContainerRequestContext context) throws IOException {
context.setProperty(REQUEST_TIME, System.currentTimeMillis());

// record the request json
// TODO: temporarily comment it to fix loader bug, handle it later
/*// record the request json
String method = context.getMethod();
String requestParamsJson = "";
if (method.equals(HttpMethod.POST)) {
requestParamsJson = IOUtils.toString(context.getEntityStream(), Charsets.toCharset(CHARSET));
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();
} else if (method.equals(HttpMethod.GET)) {
MultivaluedMap<String, String> pathParameters = context.getUriInfo()
.getPathParameters();
requestParamsJson = pathParameters.toString();
}
context.setProperty(REQUEST_PARAMS_JSON, requestParamsJson);
context.setProperty(REQUEST_PARAMS_JSON, requestParamsJson);*/
}
}
34 changes: 22 additions & 12 deletions hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/metrics/SlowQueryLog.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -16,28 +16,38 @@
*/
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;
public long executeTime;

public long startTime;

public long thresholdTime;

public SlowQueryLog(String rawQuery, String method, String path,
long executeTime, long startTime, long thresholdTime) {
this.rawQuery = rawQuery;
this.method = method;
this.threshold = threshold;
this.path = path;
this.executeTime = executeTime;
this.startTime = startTime;
this.thresholdTime = thresholdTime;
}

@Override
public String toString() {
return "SlowQueryLog{executeTime=" + executeTime +
", startTime=" + startTime +
", rawQuery='" + rawQuery + '\'' +
", method='" + method + '\'' +
", threshold=" + thresholdTime +
", path='" + path + '\'' +
'}';
}
}

0 comments on commit a52cd9b

Please sign in to comment.