Summary
JMeter
서비스의 성능을 분석하고 측정하기 위한 부하 테스트 도구
지난 게시글에선 Scouter를 통해 SOFO의 APM을 측정하고, 이를 UI로 확인해보았다. 이번 게시글에서는 특정 API의 성능을 개선한 뒤, 개선 전후의 성능 차이를 JMeter를 통해 테스트, Scouter를 통해 측정해 볼 것이다.
설치 및 실행
JMeter는 homebrew를 통해 설치할 수 있다.
1
brew install jmeter
이후 아래 명령어를 통해 실행할 수 있다.
1
open /opt/homebrew/bin/jmeter
JMeter에서 아래와 같은 요소들을 추가할 수있다.
- Thread Group : 요청을 보내는 스레드 그룹 생성
- Listener : 테스트 결과 도출
- Config element: 쿠키, 헤더, 캐시등의 값 사전 설정
- Assertion : 응답 결과의 성공 여부 조건 (이건 사용 안해봐서 잘 모르겠다)
나는 Thread Group에 HTTP Request를 추가한 후, Authorization 헤더 설정을 위해 HTTP Header Manager를 추가해주었다.
성능 측정
‘앨범 조회’ API의 성능을 측정해볼 예정이다.
앨범 조회 api가 반환하는 데이터는 앨범 정보, 앨범을 업로드한 아티스트 정보, 그리고 앨범에 포함된 트랙들의 정보이다.
그러나 앨범의 하위 데이터(앨범에 저장된 트랙) 조회에 있어 페이징을 적용하지 않았다는 문제가 있다. 만일 앨범 내에 트랙이 1000개 존재한다면, 그 1000개를 한 번에 다 조회해오는 것이다.
그래서 이번에 Scouter를 적용한 겸, 앨범 조회 api를 수정할 겸 JMeter를 사용하여 API 성능 측정을 해보기로 했다.
시나리오 설정
‘앨범 조회’ api 요청에 있어 점진적으로 사용자를 늘리는 시나리오를 작성했다.
- Threads number = 50
- Ramp-up period = 20s
- Loop Count = 20
위와 같이 20초 동안 사용자 수를 50명까지 늘려가며 각 스레드가 앨범 조회 요청을 20번 반복하도록 했다. (20초 동안 1000개의 요청이 들어오는 것이다.) 이렇게 하면 나름 안정적인 성능 테스트가 가능할것이라 생각했다.
(참고로 조회해오는 앨범에는 총 1000개의 트랙이 담겨있다.)
개선 전 성능 측정
우와….
위 시나리오로 앨범 조회 API를 요청하자 중간에 CPU 사용률이 100%에 도달하며 요청이 지연되는 구간이 존재하는 걸 확인할 수 있었다. 나름 안정적인 시나리오라고 생각했는데,,,
Scouter의 Summary는 다음과 같다…
CPU 부하가 너무 심한 거 같아 이번엔 Loop Count를 10으로 하여 요청수를 절반으로 줄여보았다.
비교적 안정적인 결과값을 확인할 수 있었다. 그럼에도 살짝 튀어오른 부분이 보이긴 한다.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
► txid = x4umqh4q2b9udq
► objName = /4f5660a0f9a6/tomcat1
► thread = http-nio-8080-exec-243
► endtime = 20250114 17:52:27.940
► elapsed = 247 ms
► service = /albums/{uuid}<GET>
► ipaddr=172.18.0.4, userid=0
► cpu=0 ms, kbytes=0
► sqlCount=3, sqlTime=6 ms
► userAgent=Apache-HttpClient/4.5.14 (Java/21.0.5)
► group=/albums
► profileCount=13
► profileSize=291
------------------------------------------------------------------------------------------
p# # TIME T-GAP CPU CONTENTS
------------------------------------------------------------------------------------------
[******] 17:52:27.693 0 0 start transaction
- [000000] 17:52:27.693 0 0 [driving thread] http-nio-8080-exec-243
- [000001] 17:52:27.695 2 0 param: 1b2a1c77-ad71-4990-8deb-a660dab68d06
- [000002] 17:52:27.695 0 0 OPEN-DBC jdbc:mysql://soundflyer-db:3306/soundflyer (com.zaxxer.hikari.HikariDataSource#getConnection) [0ms] -- OPEN-DBC jdbc:mysql://soundflyer-db:3306/soundflyer (com.zaxxer.hikari.HikariDataSource#getConnection)
- [000003] 17:52:27.695 0 0 setAutoCommit(false) [0ms] -- setAutoCommit(false)
- [000004] 17:52:27.695 0 0 PRE> select a1_0.id,a1_0.art_image,a1_0.artist_id,a1_0.created_at,a1_0.description,a1_0.is_deleted,a1_0.release_date,a1_0.title,a1_0.updated_at,a1_0.uuid from album a1_0 where (a1_0.is_deleted = @{1}) and a1_0.uuid=?
[0,'1b2a1c77-ad71-4990-8'] 1 ms
- [000005] 17:52:27.696 1 0 RESULT-SET-FETCH #1 0 ms
- [000006] 17:52:27.696 0 0 PRE> select t1_0.id,t1_0.album_id,t1_0.created_at,t1_0.duration,t1_0.is_deleted,t1_0.lyric,t1_0.song_url,t1_0.title,t1_0.updated_at,t1_0.uuid from track t1_0 where (t1_0.is_deleted = @{1}) and t1_0.album_id=?
[0,4] 3 ms
- [000007] 17:52:27.926 230 0 RESULT-SET-FETCH #1,002 227 ms
- [000008] 17:52:27.930 4 0 PRE> select a1_0.id,a1_0.artist_image,a1_0.created_at,a1_0.email,a1_0.is_deleted,a1_0.name,a1_0.provider,a1_0.role,a1_0.updated_at,a1_0.uuid from artist a1_0 where a1_0.id=? and (a1_0.is_deleted = @{1})
[0,2] 2 ms
- [000009] 17:52:27.932 2 0 RESULT-SET-FETCH #1 0 ms
- [000010] 17:52:27.932 0 0 COMMIT [0ms] -- COMMIT
- [000011] 17:52:27.933 1 0 setAutoCommit(true) [0ms] -- setAutoCommit(true)
- [000012] 17:52:27.939 6 0 CLOSE [0ms] -- CLOSE
[******] 17:52:27.940 1 0 end of transaction
------------------------------------------------------------------------------------------
발생한 트랜잭션 중 elapsed time이 최대인 트랜잭션의 로그를 확인해보았다. 총 247 ms가 소요되었다.
눈여겨봐야할 점은 247 ms중 대부분의 시간을 사용한 SQL문이다.
1
2
3
0 0 PRE> select t1_0.id,t1_0.album_id,t1_0.created_at,t1_0.duration,t1_0.is_deleted,t1_0.lyric,t1_0.song_url,t1_0.title,t1_0.updated_at,t1_0.uuid from track t1_0 where (t1_0.is_deleted = @{1}) and t1_0.album_id=?
[0,4] 3 ms
230 0 RESULT-SET-FETCH #1,002 227 ms
album_id가 4인 Track들을 조회해오는 SQL문과 그 결과가 반환되는 로그가 눈에 띈다.
총 247ms 중 결과 반환에만 230ms가 소요되었다.
이는 위에서 언급했듯 앨범 내에 존재하는 트랙 조회에 있어 페이징을 적용하지 않았기 때문에, 그만큼 많은 데이터를 반환하느라 시간이 더 많이 걸린 것으로 보인다.
JMeter 요약 결과는 다음과 같다
(Scouter에선 최대 elapsed time이 247ms인데 왜 JMeter에선 Max가 849로 뜨나 Gpt에게 물어봤더니… Scouter는 단순 서버 처리 시간만 계산하고 JMeter는 네트워크와 서버의 부하 상태를 반영해서 그렇다고 하네….)
개선 후 성능 측정
하위 데이터에 대해서도 페이징을 적용했다. 디폴트 paseSize는 10이다. 한 번에 조회해오는 양이 1000에서 10으로 줄었다고 보면 된다.
페이징을 적용 후, 최초 테스트와 동일한 시나리오를 적용해보기로 한다. 개선 전 테스트에서는 처리해야할 데이터가 너무 많은 이유로 CPU가 폭주하여 병목 현상이 발생했었다.
- Threads number = 50
- Ramp-up period = 20s
- Loop Count = 20
결과값은 아래와 같다.
당연하지만 이전과 같은 현상은 발생하지 않았다. 당연한게… 트랜잭션 1회당 1000개의 데이터를 조회하던 걸 10개로 줄였으니…. CPU도 폭주하지 않았다.
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
► txid = z3dckagjuqtbp0
► objName = /49c0be7c2ce5/tomcat1
► thread = http-nio-8080-exec-2
► endtime = 20250114 18:46:58.444
► elapsed = 23 ms
► service = /albums/{uuid}<GET>
► ipaddr=172.18.0.4, userid=0
► cpu=0 ms, kbytes=0
► sqlCount=1, sqlTime=2 ms
► userAgent=Apache-HttpClient/4.5.14 (Java/21.0.5)
► group=/albums
► profileCount=9
► profileSize=206
------------------------------------------------------------------------------------------
p# # TIME T-GAP CPU CONTENTS
------------------------------------------------------------------------------------------
[******] 18:46:58.421 0 0 start transaction
- [000000] 18:46:58.421 0 0 [driving thread] http-nio-8080-exec-2
- [000001] 18:46:58.423 2 0 param: 1b2a1c77-ad71-4990-8deb-a660dab68d06
- [000002] 18:46:58.423 0 0 param: 0
- [000003] 18:46:58.423 0 0 param: 10
- [000004] 18:46:58.423 0 0 OPEN-DBC jdbc:mysql://soundflyer-db:3306/soundflyer (com.zaxxer.hikari.HikariDataSource#getConnection) [0ms] -- OPEN-DBC jdbc:mysql://soundflyer-db:3306/soundflyer (com.zaxxer.hikari.HikariDataSource#getConnection)
- [000005] 18:46:58.423 0 0 setAutoCommit(false) [0ms] -- setAutoCommit(false)
- [000006] 18:46:58.423 0 0 PRE> select a1_0.id,a1_0.art_image,a1_0.artist_id,a1_0.created_at,a1_0.description,a1_0.is_deleted,a1_0.release_date,a1_0.title,a1_0.updated_at,a1_0.uuid from album a1_0 where (a1_0.is_deleted = @{1}) and a1_0.uuid=?
[0,'1b2a1c77-ad71-4990-8'] 2 ms
- [000007] 18:46:58.425 2 0 setAutoCommit(true) [0ms] -- setAutoCommit(true)
- [000008] 18:46:58.444 19 0 CLOSE [0ms] -- CLOSE
[******] 18:46:58.444 0 0 end of transaction
------------------------------------------------------------------------------------------
1000개의 요청 중 가장 오래 걸린 응답은 23ms로, 과거 500회의 요청에서 최대 247ms가 소요됐던 것을 생각하면 10배 이상 나아졌다.
과거 SQL 응답 반환에만 230ms를 소요했던 것에 비해, 이번엔 데이터베이스 종료에 19ms로 가장 많은 시간은 소요했다.
JMeter Summary는 위와 같다.
데이터 1000개를 조회해오던걸 10개만 조회해오면 당연히 성능이 좋아질텐데 너무 당연한 소리만 반복하는 거 같군…
하위 데이터에도 페이징을 적용하는걸 잊지 말자는 교훈을 얻었다.
이번 게시물은 성능 개선보단 Scouter를 사용한 모니터링에 초점을 맞춰서 보자 ^^;;
다음 게시물에선 부하 테스트 시나리오들을 공부한 후 성능이 떨어지는 api들을 찾아내보기로…