[24HANE] 서비스 레이턴시 개선기

date

Mar 27, 2023

slug

24hane-latency-improve-1

author

status

Public

문제 상황

현재 24HANE의 백앤드 프로젝트는 웹, Android, iOS 외 서드파티 앱에서까지 API를 끌어다 사용하는 서비스가 되었습니다. 별도로 통계를 내진 않았지만 사용자가 점차 증가하는 것으로 판단되며 HTTP API 호출 횟수가 늘어날 것으로 판단됩니다.

그래서 24HANE 웹/앱 서비스에 접속하면 누적 시간을 표시하는 컴포넌트에 딜레이가 걸리는 것이 체감이 됩니다.

실제로 개발자 도구를 통해 레이턴시를 확인해 본 결과 시간 계산 API는 기본적으로 1초 이상을 소요하며, 누적 시간을 가져오는 API는 6초 가까이 소요됩니다.

24HANE 서비스를 사용하는 카뎃분들이 많은 만큼, 더 좋은 사용자 경험을 위해 레이턴시를 개선해야 합니다.

부하 테스트

문제를 해결하기에 앞서, 현재 성능에 대한 정량적인 데이터를 기반으로 분석하기 위해 부하 테스트를 해보기로 했습니다.

부하 테스트 툴은 여러 종류가 있습니다.

JMeter

nGrinder

vegeta

JMeter는 지원하는 기능도 많고, 개발된지 오래되었기 때문에 그만큼 안정성도 있다고 합니다. 하지만 초기 설정이 복잡한 단점이 있습니다. nGrinder도 마찬가지로 설정 요소들이 많이 들어가는 것으로 알고 있습니다. ab는 단순하고 사용이 편한 장점이 있지만 HTTP 1.0만을 지원하는 단점이 있습니다.

쉘에서 가볍게 사용할 수 있지만, 적당히 지원하는 기능도 많은 vegeta를 사용하기로 했습니다.

vegeta를 사용한 부하 테스트

vegeta는 파이프를 이용해 부하 테스트할 명령을 지정할 수 있고, 결과를 저장하고, 리포트를 볼 수 있습니다.


echo "GET https://~~" | vegeta attack -duration=1s | vegeta report

공격 인자는 다음과 같습니다.

duration : 테스트할 시간 (기본값 : 0 - 무한)

name : 테스트 이름

rate : 초당 요청 (기본값 : 50)

위 명령은 초당 50건의 GET 요청을 보내며, 실행 결과는 다음과 같습니다.


Requests      [total, rate, throughput]         50, 51.01, 42.16
Duration      [total, attack, wait]             1.186s, 980.224ms, 205.84ms
Latencies     [min, mean, 50, 90, 95, 99, max]  205.111ms, 542.245ms, 537.316ms, 951.799ms, 1.018s, 1.057s, 1.057s
Bytes In      [total, mean]                     100, 2.00
Bytes Out     [total, mean]                     0, 0.00
Success       [ratio]                           100.00%
Status Codes  [code:count]                      200:50
Error Set:

Request

total : 총 테스트 횟수

rate : 초당 실행한 테스트

throughput : 초당 처리률

Latencies

min, mean, max : 최소, 중간, 최대 레이턴시

50, 90, 95, 99 : p50, p90, p95, p99 → 백분위수를 의미하며 각 가장 느린 50, 90, 95, 99 %의 평균 지연 시간을 의미함

테스트할 API

24HANE 서비스에 접근할 때 주로 사용하는 API가 사용자 체감상 영향이 제일 크므로 이를 위주로 테스트합니다.

v2/tag-log/accumulationTimes : 로그인한 유저의 일별, 월별, 지난 6개월 누적 시간 정보를 가지고 옵니다.

v2/tag-log/getAllTagPerDay?year=2023&month=3&day=25 : 2023년 3월 25일의 모든 태그 기록을 가지고 옵니다.

/v2/tag-log/maininfo : 현재 로그인한 유저의 기본 정보와 마지막으로 태그한 로그, 클러스터의 체류 인원을 가지고 옵니다.

위 3가지 API의 사용 빈도가 가장 높으므로, 위 3가지에 부하 테스트를 합니다.

부하 테스트 인자

42서울엔 카뎃이 최대 1500명이 있습니다. 1500명이 모두 한번에 접근하는 경우도 고려해야 하지만 현재 위 API들은 레이턴시가 1초정도 걸리므로 초당 1500명으로 지정하는 것은 현재로서는 무의미하다 판단되어 1, 20, 50으로 지정하기로 하였습니다.

부하 테스트 기간은 1초로 잡았습니다.

다음 명령을 이용하여, 테스트를 진행하였습니다.


# JSON 타입의 테스트 케이스 생성
jq -ncM '{method: "GET", url: "https://api-dev.24hoursarenotenough.42seoul.kr/v2/tag-log/accumulationTimes", header: {"Authorization": ["Bearer TOKEN"]}}' > accumulationTimes.v2.tc

# rate 1, 20, 50 테스트 수행 및 결과 저장
cat accumulationTimes.v2.tc | vegeta attack -format=json -rate=1 -duration=1s -name="accumulationTimesV2 (rate=1, default)" | tee v1.1.accumulationTimesV2.bin | vegeta report
cat accumulationTimes.v2.tc | vegeta attack -format=json -rate=20 -duration=1s -name="accumulationTimesV2 (rate=20, default)" | tee v1.20.accumulationTimesV2.bin | vegeta report
cat accumulationTimes.v2.tc | vegeta attack -format=json -rate=50 -duration=1s -name="accumulationTimesV2 (rate=50, default)" | tee v1.50.accumulationTimesV2.bin | vegeta report

# 1, 20, 50 테스트 결과를 html 리포트로 생성
vegeta plot -title="accumulationTimesV2 (default)" v1.1.accumulationTimesV2.bin v1.20.accumulationTimesV2.bin v1.50.accumulationTimesV2.bin > v1.accumulationTimesV2.html

테스트 결과

accumulationTimes

Latencies [min, mean, 50, 90, 95, 99, max] 6.234s, 6.234s, 6.234s, 6.234s, 6.234s, 6.234s, 6.234s @rate = 1

Latencies [min, mean, 50, 90, 95, 99, max] 30s, 30.001s, 30.001s, 30.001s, 30.002s, 30.003s, 30.003s @rate = 20

Latencies [min, mean, 50, 90, 95, 99, max] 30s, 30.001s, 30s, 30.001s, 30.001s, 30.002s, 30.002s @rate = 50

요청이 1건 있을 때, 레이턴시가 약 6초정도 걸립니다. 요청이 20, 50건인 경우 타임아웃으로 인해 처리되지 않습니다.

getAllTagPerDay

Latencies [min, mean, 50, 90, 95, 99, max] 11.589s, 11.589s, 11.589s, 11.589s, 11.589s, 11.589s, 11.589s @rate = 1

Latencies [min, mean, 50, 90, 95, 99, max] 15.957s, 20.004s, 21.169s, 22.529s, 22.735s, 22.863s, 22.863s @rate = 20

Latencies [min, mean, 50, 90, 95, 99, max] 30s, 30.001s, 30.001s, 30.001s, 30.001s, 30.001s, 30.001s @rate = 50

요청이 1건 있을 때, 레이턴시가 약 12초 걸립니다. 요청이 20건인 경우는 15 ~ 20초 걸렸으며 타임아웃 처리된 요청은 없었습니다. 요청이 50건인 경우 모든 케이스가 타임아웃이 걸렸습니다.

maininfo

Latencies [min, mean, 50, 90, 95, 99, max] 7.94s, 7.94s, 7.94s, 7.94s, 7.94s, 7.94s, 7.94s @rate = 1

Latencies [min, mean, 50, 90, 95, 99, max] 6.805s, 10.008s, 8.528s, 13.47s, 13.748s, 13.96s, 13.96s @rate = 20

Latencies [min, mean, 50, 90, 95, 99, max] 30s, 30.001s, 30.001s, 30.001s, 30.001s, 30.004s, 30.004s @rate = 50

요청이 1건 있을 때, 레이턴시가 약 8초 걸립니다. 요청이 20건인 경우는 7 ~ 14초 걸렸으며 타임아웃 처리된 요청은 없었습니다. 요청이 50건인 경우 모든 케이스가 타임아웃이 걸렸습니다.

결과 분석

accumulationTimes 은 1건일 때를 제외하고 모든 요청이 타임아웃 처리되었습니다. 아마 요청 하나당 6초 가량 걸릴 때 6 * 20 / 6 * 50 초만큼 걸리기 때문에 타임아웃이 발생한 것으로 추측됩니다.

getAllTagPerDay 와 maininfo 는 accumulationTimes 와 다르게 요청 하나당 레이턴시가 긴데도 불구하고 요청이 20건인 경우 타임아웃이 걸리지 않은 이유는 accumulationTimes API는 여러 정보를 가져오기 때문에 서버 내부에서 순차적으로 처리하다 타임아웃이 걸린 것으로 추측합니다.

원인 추측

현재 프로젝트는 최소 기능 구현으로 보완해야 할 문제를 남겨두고 구현한 부분이 많습니다.

인덱스 미적용

DB 테이블 중 유저의 태그 기록을 저장하는 테이블이 있습니다. 하루에 약 몇천건 정도 누적되는데, 프로젝트 초기엔 데이터 량이 크지 않아 별 문제 없을 것이라 판단했지만 현재는 2백만이 넘는 데이터가 쌓였습니다.
24HANE는 태그 기록 테이블을 조회하여 시간을 산정합니다. 태그 기록 테이블의 데이터를 조회할 때 다음 조건이 걸립니다.

태그한 카드
태그한 시간

(논리적으로 접근하면) 먼저 태그 기록중 특정 카드만 찾아냅니다. 이후 특정 카드의 태그 기록에서 특정 시간만 조회합니다.
인덱스를 걸지 않을 경우 몇백만건이 담긴 테이블을 FULL SCAN하게 됩니다. 이런 경우 인덱스를 태그 시간 과 태그 카드 에 걸어야 합니다.

시간 산정 로직에서 수많은 RDB 쿼리 요청

특정 유저의 체류 시간을 산정할 때 다음 테이블에 반드시 접근합니다.

입출입 쌍 테이블
카드 발급 테이블
태그 기록 테이블

이외에도 필요한 경우 다른 테이블에도 접근합니다.

백앤드 서버에 적용된 과도한 전처리 연산

현재 중복 제거 등을 백앤드 서버에서 처리합니다. 싱글스레드 서버에서 적절한 처리 방법이 아닙니다.

개선 1. 경계 로그 문제

가상 로그

24HANE는 경계값에 걸쳐져 있는 로그에 대해 가상 로그 라는 것을 삽입해 해결합니다.

예를 들면, 3월 25일 오후 10시에 입실하여 3월 26일 오전 11시에 퇴실했을 때 이 사람의 26일 체류시간은 3월 26일 오전 00시부터 3월 26일 오전 11시가 됩니다.

여기서 3월 26일 오전 00시 가 가상 로그가 됩니다.

가상 로그 만드는 로직

그럼 만약에, TAG_LOG 테이블에 3월 26일의 기록을 가져오기 위해 태그 로그를 가져오게 되면 SQL의 조건은 다음과 같이 될 것입니다.

WHERE TAG_AT BETWEEN "3월 26일 오전 0시" AND "3월 26일 오전 12시"

이렇게 조건을 설정한 경우, 3월 26일 오전 11시 퇴실 로그 하나만 가져오게 됩니다.

24HANE는 이런 일을 막기 위해 무조건 로그의 처음과 끝에 로그를 하나씩 더 가져오는데, 이렇게 처리할 경우 TAG_LOG 테이블에 요청을 항상 세번 날리게 됩니다.

개선

가져온 로그의 첫 로그가 OUT 일 경우, 이전 날에 IN 로그가 있을 것이기 때문에 가져온 로그의 첫 로그보다 더 과거의 로그를 가져오도록 조건을 변경하였습니다.

그리고 가져온 로그의 마지막 로그가 IN 인 경우, 다음 날에 OUT 로그가 있을 것이기 때문에 이 또한 마찬가지로 동작하게 합니다.

유의해야 할 점

이렇게 할 경우, 처음 로그를 가져왔을 때 만약 로그가 비어있을 수도 있습니다. 이런 경우 실제로 출입을 하지 않았을수도 있지만, 24시간 넘게 클러스터에 체류했을 경우 문제가 됩니다.

따라서 로그가 아예 비어있다면, 해당 날짜의 더 이전 로그를 가져와야 합니다.

개선 1 적용 후 테스트

accumulationTimes

Latencies [min, mean, 50, 90, 95, 99, max] 4.352s, 4.352s, 4.352s, 4.352s, 4.352s, 4.352s, 4.352s @rate = 1

Latencies [min, mean, 50, 90, 95, 99, max] 26.506s, 28.506s, 29.066s, 30s, 30.001s, 30.001s, 30.001s @rate = 20

Latencies [min, mean, 50, 90, 95, 99, max] 30s, 30.001s, 30.001s, 30.001s, 30.001s, 30.001s, 30.001s @rate = 50

요청이 1건 있을 때, 레이턴시가 약 4초정도 걸립니다. 요청이 20건인 경우 요청의 일부가 타임아웃으로 처리되지 않으며 50건인 경우 모두 타임아웃으로 인해 처리되지 않습니다.

getAllTagPerDay

Latencies [min, mean, 50, 90, 95, 99, max] 1.722s, 1.722s, 1.722s, 1.722s, 1.722s, 1.722s, 1.722s @rate = 1

Latencies [min, mean, 50, 90, 95, 99, max] 4.308s, 6.379s, 6.289s, 8.181s, 8.456s, 8.706s, 8.706s @rate = 20

Latencies [min, mean, 50, 90, 95, 99, max] 12.397s, 16.994s, 13.477s, 22.468s, 22.752s, 23.068s, 23.068s @rate = 50

요청이 1건 있을 때, 레이턴시가 약 1초 걸립니다. 20, 50건의 요청에 대해서도 처리할 수 있음을 볼 수 있습니다.

maininfo

Latencies [min, mean, 50, 90, 95, 99, max] 2.113s, 2.113s, 2.113s, 2.113s, 2.113s, 2.113s, 2.113s @rate = 1

Latencies [min, mean, 50, 90, 95, 99, max] 4.93s, 7.149s, 8.08s, 8.674s, 8.693s, 8.696s, 8.696s @rate = 20

Latencies [min, mean, 50, 90, 95, 99, max] 10.447s, 13.177s, 11.225s, 16.418s, 16.45s, 16.49s, 16.49s @rate = 50

요청이 1건 있을 때, 레이턴시가 약 2초 걸립니다. 20, 50건의 요청에 대해서도 처리할 수 있음을 볼 수 있습니다.

개선 2. 인덱스 적용

추가로, 인덱스를 적용해 레이턴시를 줄여 보도록 합니다.

인덱스란?

인덱스는 DB 테이블에의 특정 컬럼에 대해 빠르게 검색하기 위해 사용하는 트리 기반의 데이터 구조입니다. 인덱스가 걸려 있는 컬럼에 대해 값을 검색하면, RDB는 이진 탐색과 같은 방법으로 조회하기 때문에 특정 값을 빠르게 검색합니다.

예를 들면, 테이블 내에 몇백만건의 데이터가 있다고 할 때, 인덱스가 걸린 컬럼을 기준으로 값을 찾으면 몇백만건의 row를 전부 조회하는 것이 아니라, 몇건에서 몇십 건만 조회하게 됩니다.

인덱스 적용 시 고려해야 할 사항

1. 인덱스의 단점

인덱스는 테이블 외에 별도로 존재하는 자료구조입니다. 따라서 RDB 공간을 추가로 소모하며, 테이블 내 데이터에 대해 생성, 조회, 삭제를 수행할 때마다 인덱스를 업데이트해야 하기 때문에 느려실 수 있습니다.

2. 여러 컬럼에 적용 (결합 인덱스)

만약 테이블에 id, 사용자 이름, 나이 컬럼이 들어있고, 다음과 같이 들어있다고 합시다. id는 중복이 불가능하며, 사용자 이름과 나이가 중복을 허용한다 합시다.

1, joopark , 29

2, joopark , 34

3, inshin , 20

이런 식으로 데이터가 들어있을때, 사용자 이름을 기반(WHERE 사용자 이름 = joopark)으로 조회한다면 사용자 이름에 인덱스를 걸면 조회 속도가 빨라집니다.

하지만, 역효과가 날 수 있는 조회 사례가 있습니다. WHERE 사용자 이름 = joopark AND 나이 > 10 와 같이 인덱스가 걸려있지 않은 컬럼과 함께 조회하면, 인덱싱을 하여 검색된 데이터를 기반으로 원본 테이블에 접근하기 때문에 속도가 느려집니다.

그래서 보통 위와 같은 경우는 사용자 이름과 나이를 묶은 인덱스를 걸어야 합니다. 이를 결합 인덱스라고 하며, 내부적으로 B-Tree 내에 사용자 이름과 나이를 함께 순서대로 정렬하여 저장히기 때문에, 속도 향상을 기대할 수 있습니다.

TAG_LOG 테이블

현재 TAG_LOG 테이블의 DDL입니다.


create table TAG_LOG
(
    IDX       int auto_increment comment '태그 기록 고유 번호'
        primary key,
    CARD_ID   varchar(45) not null comment '태그가 발생한 카드의 번호',
    TAG_AT    datetime    not null comment '태그가 발생한 시점',
    DEVICE_ID int         not null comment '태그가 발생한 기기'
)
    comment '카드 태그 기록';

24HANE의 핵심 로직은 위 테이블을 태그가 발생한 카드의 번호 를 기준으로, 태그가 발생한 시점 을 조회하는 것입니다. TAG_LOG에 접근하는 쿼리는 모두 동일합니다.

그래서 TAG_AT, CARD_ID에 인덱스를 적용해야 하기 때문에 결합 인덱스를 걸어야 합니다. 먼저 CARD_ID를 통해 특정 사용자를 추려내고, 태그한 시간으로 카드 태그 기록을 가져오기 때문에 인덱스를 다음과 같이 걸어야 합니다.


CREATE INDEX TAG_LOG_CARD_WITH_TAG_AT ON TAG_LOG(CARD_ID, TAG_AT);

결합 인덱스는 컬럼의 순서가 중요합니다. 위와 같이 선언하면 먼저 CARD_ID 순으로 정렬한 다음, TAG_AT로 정렬하기 때문에, 이 인덱스는 위와 같은 조회 쿼리에서만 성능에 이점을 나타냅니다.

개선 2 적용 후 테스트

accumulationTimes

Latencies [min, mean, 50, 90, 95, 99, max] 1.802s, 1.802s, 1.802s, 1.802s, 1.802s, 1.802s, 1.802s @rate = 1

Latencies [min, mean, 50, 90, 95, 99, max] 4.618s, 6.447s, 6.29s, 8.062s, 8.43s, 8.778s, 8.778s @rate = 20

Latencies [min, mean, 50, 90, 95, 99, max] 8.403s, 13.396s, 12.416s, 17.763s, 17.916s, 18.111s, 18.111s @rate = 50

레이턴시가 유의미한 수치로 줄어든 것을 확인할 수 있습니다. 기존엔 타임아웃이 발생하던 rate에 대해서도 정상동작을 합니다.

getAllTagPerDay

Latencies [min, mean, 50, 90, 95, 99, max] 805.135ms, 805.135ms, 805.135ms, 805.135ms, 805.135ms, 805.135ms, 805.135ms @rate = 1

Latencies [min, mean, 50, 90, 95, 99, max] 438.321ms, 853.126ms, 853.76ms, 1.205s, 1.28s, 1.338s, 1.338s @rate = 20

Latencies [min, mean, 50, 90, 95, 99, max] 232.44ms, 631.082ms, 653.543ms, 948.848ms, 975.806ms, 1.053s, 1.053s @rate = 50

마찬가지로 레이턴시가 확연히 줄어든 것을 확인할 수 있습니다. 요청이 늘어날때 더 두드러지는 효과를 보입니다.

maininfo

Latencies [min, mean, 50, 90, 95, 99, max] 920.967ms, 920.967ms, 920.967ms, 920.967ms, 920.967ms, 920.967ms, 920.967ms @rate = 1

Latencies [min, mean, 50, 90, 95, 99, max] 872.427ms, 1.306s, 1.318s, 1.486s, 1.548s, 1.585s, 1.585s @rate = 20

Latencies [min, mean, 50, 90, 95, 99, max] 1.735s, 2.359s, 2.366s, 2.573s, 2.604s, 2.719s, 2.719s @rate = 50

마찬가지로 레이턴시가 확연히 줄어든 것을 확인할 수 있습니다. 역시 요청이 늘어날때 더 두드러지는 효과를 보입니다.

사용자 관점에서 개선 전과 개선 후 비교

개선 전

개선 후

설명

브라우저 상에서 개선 전과 후를 비교해보았습니다.

accumulationTimes : 5.90s → 832ms (5068% 감소)

getAllTagPerDay : 1.6s → 0.777ms (823% 감소)

maininfo : 1.6s → 0.577ms (1023% 감소)

아직 개선해야 할 부분들이 조금 있지만, 인덱스 적용과 로직 최적화로 체감이 될 정도의 성능 개선을 이루었습니다.