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.

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

[BE] Feature/#422 성능 측정을 위한 로깅 구현 #434

Merged
merged 9 commits into from
Sep 19, 2023
Original file line number Diff line number Diff line change
@@ -0,0 +1,24 @@
package com.mapbefine.mapbefine.common.config;

import com.mapbefine.mapbefine.common.filter.QueryInspector;
import org.hibernate.cfg.AvailableSettings;
import org.springframework.boot.autoconfigure.orm.jpa.HibernatePropertiesCustomizer;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class HibernateConfig {

private final QueryInspector queryInspector;

public HibernateConfig(QueryInspector queryInspector) {
this.queryInspector = queryInspector;
}

@Bean
public HibernatePropertiesCustomizer hibernatePropertiesCustomizer() {
return hibernateProperties ->
hibernateProperties.put(AvailableSettings.STATEMENT_INSPECTOR, queryInspector);
}
Comment on lines +18 to +22
Copy link
Collaborator Author

Choose a reason for hiding this comment

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

Hibernate에 쿼리 수 측정을 위한 QueryInspector를 등록하는 코드입니다.

Copy link
Collaborator

Choose a reason for hiding this comment

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

설명 굳굳~!


}
Original file line number Diff line number Diff line change
@@ -0,0 +1,45 @@
package com.mapbefine.mapbefine.common.filter;

import jakarta.servlet.FilterChain;
import jakarta.servlet.ServletException;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import java.io.IOException;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;

@Component
public class LatencyLoggingFilter extends OncePerRequestFilter {

private static final Logger log = LoggerFactory.getLogger(LatencyLoggingFilter.class);

private final LatencyRecorder latencyRecorder;
private final QueryInspector queryInspector;

public LatencyLoggingFilter(LatencyRecorder latencyRecorder, QueryInspector queryInspector) {
this.latencyRecorder = latencyRecorder;
this.queryInspector = queryInspector;
}

@Override
protected void doFilterInternal(
HttpServletRequest request,
HttpServletResponse response,
FilterChain filterChain
) throws ServletException, IOException {
latencyRecorder.start();

filterChain.doFilter(request, response);

double latencyForSeconds = latencyRecorder.getLatencyForSeconds();
int queryCount = queryInspector.getQueryCount();
String requestURI = request.getRequestURI();

log.info("Latency : {}s, Query count : {}, Request URI : {}", latencyForSeconds, queryCount, requestURI);
MDC.clear();
Copy link
Collaborator Author

Choose a reason for hiding this comment

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

임무를 마치고 복귀하는 쓰레드는 자신의 로컬 정보(?)를 삭제하지 않기 때문에 로깅 정보를 clear 해주어야 합니다.

Copy link
Collaborator

Choose a reason for hiding this comment

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

굳굳~!

}

}
Original file line number Diff line number Diff line change
@@ -0,0 +1,23 @@
package com.mapbefine.mapbefine.common.filter;

import org.springframework.stereotype.Component;

@Component
public class LatencyRecorder {

private final ThreadLocal<Long> threadLocal = new ThreadLocal<>();

public void start() {
threadLocal.set(System.currentTimeMillis());
}

public double getLatencyForSeconds() {
long start = threadLocal.get();
long end = System.currentTimeMillis();

threadLocal.remove();
Copy link
Collaborator Author

Choose a reason for hiding this comment

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

쓰레드 풀로 돌아가기 전에 remove를 통해, threadLocal에 저장된 값을 삭제해줍니다.


return (end - start) / 1000d;
}

}
Original file line number Diff line number Diff line change
@@ -0,0 +1,20 @@
package com.mapbefine.mapbefine.common.filter;

import org.springframework.stereotype.Component;
import org.springframework.web.context.annotation.RequestScope;

@Component
@RequestScope
Copy link
Collaborator Author

Choose a reason for hiding this comment

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

해당 Bean의 스코프를 위와 같이 설정함으로써, 생명 주기를 각 요청으로 설정하였습니다.

public class QueryCounter {

private int count = 0;

public void increase() {
count++;
}

public int getCount() {
return count;
}

}
Original file line number Diff line number Diff line change
@@ -0,0 +1,33 @@
package com.mapbefine.mapbefine.common.filter;

import org.hibernate.resource.jdbc.spi.StatementInspector;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;

@Component
public class QueryInspector implements StatementInspector {

private final QueryCounter queryCounter;

public QueryInspector(QueryCounter queryCounter) {
this.queryCounter = queryCounter;
}

@Override
public String inspect(String sql) {
if (isInRequestScope()) {
queryCounter.increase();
}

return sql;
}
Comment on lines +16 to +23
Copy link
Collaborator Author

Choose a reason for hiding this comment

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

StatementInspector에서 쿼리를 실행하기 전에, insepct 메서드를 호출합니다.

이때, 쿼리 카운트를 증가시킴으로써 쿼리 횟수를 확인할 수 있습니다.


private boolean isInRequestScope() {
return RequestContextHolder.getRequestAttributes() != null;
}

public int getQueryCount() {
return queryCounter.getCount();
}

}
Original file line number Diff line number Diff line change
@@ -0,0 +1,48 @@
package com.mapbefine.mapbefine.common.filter;

import static org.assertj.core.api.Assertions.assertThat;

import org.junit.jupiter.api.DisplayName;
import org.junit.jupiter.api.Test;

class LatencyRecorderTest {

private final LatencyRecorder latencyRecorder = new LatencyRecorder();

@Test
@DisplayName("실행 시간을 초단위로 측정할 수 있다.")
void getLatencyForSeconds() throws InterruptedException {
//given
latencyRecorder.start();

//5초
Thread.sleep(5000);

//when
double latencyForSeconds = latencyRecorder.getLatencyForSeconds();

//then
assertThat(latencyForSeconds).isGreaterThanOrEqualTo(5)
.isLessThanOrEqualTo(6);
}

@Test
@DisplayName("다른 쓰레드에 영향을 받지 않는다.")
void getLatencyForSecondsThreadSafe() throws InterruptedException {
//given
Thread thread = new Thread(latencyRecorder::start);
thread.start();
Thread.sleep(3000);

latencyRecorder.start();
Thread.sleep(3000);

Comment on lines +33 to +39
Copy link
Collaborator

Choose a reason for hiding this comment

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

저 이 부분 이해가 안가보렷...

이렇게 하면 첫번째 thread.sleep 과 두번쨰 thread.sleep 은 다른 thread 에서 실행되는 것인가요?

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

모든 Thread에서 실행되는걸로 알아요..

테스트 의도는 새로 생성한 쓰레드에서는 6초를 기다렸고, 필드에 생성한 쓰레드는 3초만 기다렸다...
쓰레드 간의 독립성을 ,. 보여주고싶었어요

Copy link
Collaborator

Choose a reason for hiding this comment

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

이해완!

알러뷰

//when
double latencyForSeconds = latencyRecorder.getLatencyForSeconds();

//then
assertThat(latencyForSeconds).isGreaterThanOrEqualTo(3)
.isLessThanOrEqualTo(4);
}

}
Original file line number Diff line number Diff line change
@@ -0,0 +1,24 @@
package com.mapbefine.mapbefine.common.filter;

import static org.assertj.core.api.Assertions.assertThat;

import org.junit.jupiter.api.DisplayName;
import org.junit.jupiter.api.Test;

class QueryCounterTest {

@Test
@DisplayName("값을 증가시킬 수 있다.")
void increase_Success() {
//given
QueryCounter queryCounter = new QueryCounter();
assertThat(queryCounter.getCount()).isZero();
Copy link
Collaborator

Choose a reason for hiding this comment

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

isZero 간지나네요


//when
queryCounter.increase();

//then
assertThat(queryCounter.getCount()).isOne();
Copy link
Collaborator

Choose a reason for hiding this comment

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

isOne 도 간지나네요

}

}
Loading