배포 서버를 대상으로 한 성능테스트 및 성능개선 (4) - 문제의 진짜 원인을 찾아서 (feat. 슬로우 쿼리 & BCrypt)

안녕하세요. 저번시간에는 문제의 원인일지 모르는 DB 커넥션과 커넥션 풀에 대해 이해하고, 커넥션 풀 크기를 조정한 뒤 2차로 다시 테스트를 수행해 보았습니다. 10개 였던 커넥션 풀 크기가 20개로 늘자 맨 처음 문제였던 getConnection 메소드 수행 시 대기 시간은 사라졌습니다. 다만, 커넥션 풀이 문제를 일으키는 진짜 원인이 아니었기에 또 다른 곳에서 문제가 발생하는 것을 확인할 수 있었습니다. 오늘은 문제의 원인이 될 만한 다른 부분을 분석해보고, 문제점이 발견되면 이를 개선하고 다시 성능 측정을 해봄으로써 실질적인 개선이 이루어졌는지 확인해보도록 하겠습니다.

 

문제가 발생하고 있는 지점을 좀 더 자세히 살펴봅시다.

저번 포스팅에 활용했던 사진을 다시 가져와 보았습니다. 여기서 확인했던 문제는 getConnection 메소드 대기시간 문제가 해결된 후에도 로그인을 수행하는 메소드의 시간 자체가 여전히 꽤나 오래걸리고 있다는 부분이었습니다.

여기서 대부분의 시간을 잡아먹고 있는 getUserLoginInfo는 로그인 요청으로 아이디와 패스워드를 입력받는 경우, 로그인을 수행을 완료하기 전 해당 정보가 서버 DB 내의 저장된 사용자 정보와 같은지 비교하기 위해 다음과 같은 역할을 수행합니다.

1. 요청 받은 아이디 값을 조건으로 활용해 DB에서 아이디, 패스워드 정보를 불러옵니다.
  1-1) 아무 값도 리턴되지 않은 경우에는 해당 사용자 아이디가 없다는 의미이므로 예외를 발생시킵니다. 

2. 값이 리턴된 경우에는 요청으로 들어온 비밀번호가 DB 상의 사용자 비밀번호와 일치하는 지 검증합니다.
  2-1) 불일치할 경우 비밀번호 입력이 잘못됬다는 의미이므로 예외를 발생시킵니다.
  2-2) 일치할 경우 아이디 비밀번호가 모두 일치한다는 의미이미로 다음 과정에 대한 수행을 진행합니다.

위의 과정을 수행하기 위해 작성한 코드는 이러합니다.

* getUserLoginInfo 메소드

@Transactional(readOnly = true)
public UserLoginData getUserLoginInfo(String userId, String password) {
    UserLoginData loginData = userMapper.getUserLoginDataById(userId)
                            .orElseThrow(() -> new InvalidUserInfoException("해당 사용자는 존재하지 않습니다. 아이디를 다시 확인해 주세요."));
    isValidPassword(password, loginData.getPassword());
    return loginData;
}

위의 로직을 담고있는 메소드입니다.

* isValidPassword 메소드

private void isValidPassword(String requestPassword, String userPassword) {
    if (!passwordEncoder.isMatch(requestPassword, userPassword)) {
        throw new InvalidUserInfoException("입력하신 비밀번호가 일치하지 않습니다. 다시 한 번 확인해주세요.");
    }
}

비밀번호 검증을 위한 메소드입니다. 해당 클래스 내부의 다른 곳에서도 사용되기 때문에, 메소드 추출을 활용해 따로 분리시켜 두었습니다.

* getUserLoginDataById 쿼리 

<select id="getUserLoginDataById"
            parameterType="String" resultMap="getUserLoginData">
 
    SELECT
        u.userId AS userId,
        u.password AS password,
        t.token AS token
    FROM users AS u
        LEFT OUTER JOIN tokens AS t on u.userId = t.userId
    WHERE u.userId = #{userId} AND isDeactivated = 'N';
</select>

로그인 요청을 보낸 사용자의 정보를 얻어오는 쿼리입니다. FCM(Firebase Cloud Messaging)에 알림요청 전송을 보내기 위해서 토큰용 테이블을 따로 두었고, 이를 외부 조인하는 형태로 수행되어, 토큰이 있으면 가져오고 없으면 null을 가져오는 식입니다. 조건으로는 해당 유저의 아이디와 해당 유저의 계정 활성화 여부가 주어져있습니다. 

 

문제 유발 요인이 될만한 부분을 차근차근 확인보도록 하겠습니다.

1) 쿼리 실행계획 확인하기

로그인 시 시간을 오래 잡아먹는 지점이 getUserLoginInfo이므로 가장 먼저 위 getUserLoginDataById 쿼리의 실행계획을 다시 살펴보기로 했습니다. 아이디를 조건으로 조인하는 간단한 쿼리이지만 혹시나 인덱스가 제대로 부여되어 있지 않다면 테이블 풀 스캔이 발생하여 테이블 내의 모든 row를 살펴봐야하므로 수행시간이 길어질 수 있습니다. 

EXPLAIN 키워드를 가지고 해당 쿼리의 실행계획을 살펴보니 이렇게 인덱스가 잘 활용되어 1개의 row만 탐색해 값을 빠르게 가져온다는 것을 확인할 수 있었습니다. 이미 양 테이블의 userId에 인덱스를 부여되어있기 때문입니다. 따라서, 인덱스는 문제의 원인이 아니라는 것을 알 수 있었습니다.

 

2) 슬로우 쿼리 분석하기

인덱스를 잘 활용하고 있기도 하고, 조인을 한 번 사용했지만 크게 복잡한 쿼리가 아닌 만큼 슬로우 쿼리가 발생할 확률은 낮다고 생각했습니다. 그래도 혹시나 하는 마음에 슬로우 쿼리가 발생하고 있는지에 대한 여부를 살펴보기로 했습니다.

그리하여 MySQL 서버로 접속해 슬로우 쿼리를 살펴보았는데, 아무것도 기록이 되어있지 않았습니다. 문제는 슬로우 쿼리가 발생하지 않아서가 아니라, 아뿔싸 슬로우 쿼리 기록 활성화가 되어있지 않았기 때문입니다. 그래서 일단 my.cnf에 아래의 설정을 추가하였습니다. (2초 이상 걸리는 쿼리를 기록하도록 지정해놓았습니다.

slow_query_log = 1
slow_query_log_file = /var/log/mysql/slow_queries.log
long_query_time = 1

(slow_query_log의 설정 값은 0 = off, 1 = on과 같습니다. 아래 slow_query_log_file 값을 통해 슬로우 쿼리가 저장되는 디렉토리를 지정해줄 수 있고, long_query_time 값을 변경하여 해당 초 이상 걸리는 쿼리가 기록되도록 만들 수 있습니다. 여기서는 1초 이상 걸리는 쿼리를 기록해두도록 설정했습니다.)

설정 값들을 추가했다면, MySQL 서버를 재시작 해주고, MySQL 콘솔에 접속하여 슬로우 쿼리를 기록하는 기능이 아래처럼 ON으로 표시되는지 확인해 줍니다. 

설정을 마치고 다시 테스트를 수행한 뒤, 슬로우 쿼리가 저장되는 디렉토리로 이동해 파일을 들여다 보았으나 다행히도(?) 슬로우 쿼리는 존재하지 않았습니다. 그 말은 문제의 원인은 쿼리가 아니라 다른 부분에 있다는 것을 의미합니다. 

 

쿼리가 아니라면 혹시 비밀번호 검증 부분이?

3) 3차 테스트 수행 - vUser: 10

getUserLoginInfo의 남은 부분은 비밀번호 검증이었습니다. 처음에는 의심하지 않았던 부분이지만 혹시나 하는 마음에 비밀번호 검증 메소드 위주로 테스트해보기로 했습니다. 부하를 많이 보낼 경우 DB 서버의 처리 속도가 결과에 영향을 줄 수 있다고 생각해서 부하를 최소화한 뒤 3차 테스트를 수행하였습니다. 시나리오 또한 로그인만 테스트하도록 변경했습니다.

 

3 - 1) htop으로 서버 자원 사용률 모니터링하기

htop - mysql

MySQL 서버의 지표를 살펴보니 예상대로 한산했습니다. 대략 1~2%의 CPU만이 사용되고 있었습니다.

htop - was

그러나 WAS 서버의 CPU 사용률을 보니 vUser가 10명밖에 안되는데도 엄청난 부하가 가해지고 있었습니다.

뭔가 좀 이상해서 pinpoint를 들여다 봤더니 실시간 응답속도 그래프가 다음과 같은 모양을 띄고 있었습니다.

 

3 - 2) pinpoint calltree 분석하기

응답속도가 지나치게 느린 부분에 대해서 각각 트랜잭션 Call Tree를 살펴보았습니다. 테스트 시작 직후에는 약 12000ms대의 응답속도를 보여주며, 일정시간 후에는 많이 빨라지긴 했지만 여전히 약 3000ms 대로 반드시 개선이 필요한 수준이었습니다.

이때까지도 제대로 된 문제의 원인을 알 수 없었지만, 한 가지는 분명하게 추정할 수 있게 되었습니다. 비밀번호 검증을 하는 부분에서 예상치 못한 많은 부하가 발생하고 있다는 것이었습니다. 그러다 계속해서 문제를 해결하기 위해 구글링을 하던 중 BCrypt의 암호화 방식에 대한 다음의 글을 발견하게 됩니다.

https://yunb2.tistory.com/8

[서버개발캠프] 인증 서버 - 로그인 성능 테스트 : nGrinder

 

때는 프로젝트 초창기,  막 시작을 한 시점에 보안을 위해 비밀번호를 암호화 하고자 여러 암호화 알고리즘을 찾아보던 때였습니다. 다양한 암호화 알고리즘 속에서 눈에 띄는 것이 BCrypt였습니다. 암호화 효율이 정리된 그래프를 살펴보니 원래부터 강력한 암호화를 위해 개발되었기 때문에 최고 수준의 암호화 성능을 자랑하고 있었습니다. 그러나 높은 수준의 암호화를 제공하는 대가로 발생하는 trade off는 크게 고려하지 못하고 BCrypt를 채용했기 때문에 이와 같은 문제가 발생하게 된 것입니다.

BCrypt는 강력한 암호화를 보장하기 위해서 랜덤 값인 salt를 부여하고 암호화를 진행하는데, 이때 설정한 암호화 강도에 따라 반복해서 해시함수를 돌리는 횟수가 결정이 됩니다. 4~31 사이로 strength를 결정할 수가 있으며 2^(strength) 번 만큼 수행하게 되는데, 문제는 기본값이 strength 10이라는 점입니다. 한 번 로그인을 수행할 때마다 2^10 = 1024번 씩 해시함수를 돌린 값을 일치하는지 체크해야 하므로 이에 대한 부하가 엄청났던 것입니다. 서버의 사양이 낮지 않다고 생각했었는데 BCrypt를 감당하기에는 충분하지 않아 성능테스트 시 부하가 10명임에도 문제가 발생하는 듯 보였습니다. 

 

3 - 3) BCrypt 암호화 strength 수정 후 재배포하기

BCrypt가 정말 문제의 원인이었는지 확인하기 위해서 암호화 시 해시함수에 대한 strength를 기본 값인 4로 수정하여 WAS 서버에 재배포 하였습니다. 미리 Jenkins에 CI & CD를 구축해놨기 때문에 github에 push만 하면 빌드 -> 테스트 -> 배포의 과정을 간단히 마무리 할 수 있었습니다.

1 2 3 4 5 6 7 8 9 10 11 12 13

@Component public class PasswordEncoderBcrypt implements PasswordEncoder {     @Override     public String encode(String rawPassword) {         return BCrypt.hashpw(rawPassword, BCrypt.gensalt(4));     }     @Override     public boolean isMatch(String rawPassword, String encodedPassword) {         return BCrypt.checkpw(rawPassword, encodedPassword);     } } Colored by Color Scripter

cs

 

4) 4차 테스트 - 수정된 코드를 가지고 이전과 동일한 조건인 vUser 10명으로 테스트하기

BCrypt strength 수정 후 WAS 서버 CPU 사용률

기존 응답속도 그래프

BCrypt strength를 낮춘 후 응답속도 그래프

앞 부분의 응답속도는 개선된 모습을 보였으나, 뒷 부분은 여전히 같은 형태를 띄고 있었기 때문에 하지만 여전히 뒷부분은 같은 양상을 띄고 있었기 때문에, BCrypt가 원인이었다는 것을 확신할 수가 없었습니다. 그래서 BCrypt가 적용되지 않은 평문 비밀번호의 경우에는 얼마나 확연한 차이가 있는지를 살펴보면 되겠다고 생각했고, BCrypt와 관련된 부분을 주석처리한 뒤 서버에 재배포 하였습니다. 

 

5) 5차 테스트 (비밀번호 암호화 없이 로그인 기능 테스트)

BCrpyt만 비활성화 시킨 뒤 좀 짧게 테스트를 재진행 하였습니다. 조건은 이전과 같이 vUser 10명 이었습니다. BCrypt가 있을 때의 TPS는 약 10~20정도 였던 것이 눈에 띄게 증가했음을 알 수 있습니다. 서버 내부에서 요청의 처리가 빨라져서 그런지 DB CPU 사용량도 증가하였습니다. 비록 사진은 찍지 않았지만 메인서버의 CPU 사용량은 90 ~ 100%, DB는 1% 대 였던 것이 10~20% 정도로 상승하였습니다.

상승한 TPS처럼, pinpoint의 응답속도 그래프 또한 안정적으로 변했으며, call tree에서도 getUserLoginInfo 메소드 수행 시 발생하던 지연이 사라졌습니다. 암호화를 처리하지 않는 만큼 CPU에 부하가 가지 않아서 그런듯 합니다.

 

하지만...

위의 TPS 그래프에서도 볼 수 있듯이 어느 시점에 이르면 TPS가 갑자기 급감하는 모습을 보입니다. 무언가 문제가 있다는 이야기인데, CPU 사용률의 추이를 분석해보니 다음과 같았습니다.

WAS 서버 CPU 사용률

WAS 서버 TPS

처음에는 100% 대를 유지했던 CPU 사용률이 어느 순간이 되면 뚝 떨어지기 시작합니다. 그리고 이에 맞춰 TPS도 함께 떨어졌습니다. 이쯤되면 그럴린 없겠지만 혹시 GCP의 문제인가 싶어서 네이버 클라우드에 남은 크레딧으로 같은 사양의 새로운 서버를 하나 더 만들고 해당 서버에 배포하여 테스트를 진행해보기로 결정했습니다.  

 

6차 테스트: vUser 10, Naver Cloud

안타깝게도 다른 부분에서 큰 변화는 없었고, 그나마 다행힌 점은 안정적인 응답속도도 유지되고 있다는 점이었습니다. 말도 안되는 가정이긴 했지만, 플랫폼 자체의 문제는 아니었음을 알 수 있었습니다.

 

7차 테스트 - vUser 3000

혹시나 서버 사양에 비해 부하가 너무 적어서 이러한 문제가 발생하고 있는건 아닐까 하는 생각이 들어서 한 에이전트에서 권장되는 최대 부하인 vUser 3000으로 10분간 테스트를 다시 진행해보기로 하였습니다.

nGrinder 테스트 설정

일정 시간이 지난 후 WAS 서버 CPU 사용률

일정시간이 지난 후 DB 서버의 CPU 사용률

테스트 결과

vUser가 증가한 만큼 처리하는 TPS도 증가하긴 했으나, 여전히 새롭게 발생한 문제는 지속되고 있는 모습을 보여주었습니다. 테스트 실행 직후에는 WAS 서버에 부하가 제대로 가해지면서 CPU 사용률을 100%로 유지하고, DB 서버에는 그다지 큰 부하가 가해지지 않는 양상이었으나, 일정 시간이 지나면 WAS 서버의 CPU 사용률을 떨어지되 DB 서버의 CPU 사용률이 올라가면서 TPS가 급감하는 모습이었습니다. 

 

암호화 알고리즘을 SHA-256으로 교체하기

BCrypt는 매우 강력한 암호화 알고리즘이지만, 서버의 여건 상 제대로 된 성능을 이끌어내기가 힘들다는 것을 확인하였습니다. BCrypt가 성능에 미치는 정도를 가늠해보기 위해서 BCrypt 자체를 아예 비활성화시키고 진행을 했지만, 평문을 DB에 그대로 저장하는 것은 보안상 큰 문제점이 있습니다. 따라서, 위의 TPS가 급감하는 문제는 제처두더라도 다른 암호화 알고리즘을 적용할 필요가 있었므로, 그 대안으로 SHA-256을 선택하였습니다.

public class PasswordEncoderSHA256 {

    public static final String ENCRYPTION_ALGORITHM = "SHA-256";

    public static String encode(String rawPassword) {
        String sha = "";

        try {
            MessageDigest sh = MessageDigest.getInstance(ENCRYPTION_ALGORITHM);
            sh.update(rawPassword.getBytes());
            byte[] byteData = sh.digest();
            StringBuilder sb = new StringBuilder();
            for (byte byteDatum : byteData) {
                sb.append(Integer.toString((byteDatum & 0xff) + 0x100, 16).substring(1));
            }
            sha = sb.toString();
        } catch (NoSuchAlgorithmException e) {
            throw new RuntimeException("적용하신 암호화 알고리즘이 존재하지 않습니다.", e);
        }

            return sha;
    }
}  

 

8차 테스트 - vUser 3000

이후 성능에 미치는 영향을 알아보기 위해 재배포 후 나머지는 이전과 동일한 조건하에서 다시 한 번 성능테스트를 진행하였습니다. 

그 결과 이전과 거의 비슷한 수준의 TPS를 나타났습니다. 다만 이전과 동일한 패턴이 계속 반복되어 제대로 된 성능을 측정하기 위해서는 이 부분을 꼭 해결할 필요가 있다는 것을 다시 한 번 깨닫게 되었습니다.

 

사실 성능테스트를 시작하기 전에는 이렇게 오랫동안 여러 문제로 시간을 끌게 될거라고는 상상하지 못했었습니다. 금방 원인을 찾고 개선까지 마무리 할 수 있을 것이라 생각했는데, 문제의 원인일지 모르는 부분을 하나 해결하고 나면 자꾸 다른 하나가 복병으로 등장하는 상황이 성능 테스트를 더욱 어렵게 만드는 듯 합니다. 특히나 지금까지 학습한 내용을 모두 종합해봐도 예측할 수 없는 부분이 계속 등장해서 더 그런 것 같습니다. 그래도 포기하지 않고 힘을 내서 계속 이어가도록 하겠습니다. 이번 포스팅은 많이 길어졌으니 여기서 마무리하고 다음 포스팅에서는 성능 테스트 시 나타난 다른 문제점에 대해 알아보고 이를 다시 개선하는 시간을 갖도록 하겠습니다. 

 

References

https://itstudyblog.tistory.com/384

 

프로젝트 링크

https://github.com/f-lab-edu/Hello-World

f-lab-edu/Hello-World

 

https://github.com/f-lab-edu/food-is-coming

f-lab-edu/Hello-World