[LOG] 현업에서 느낀 Query LOG 에 들어가야 할 내용

⏰ 읽는 시간: 15분

 

들어가기 전

유지보수를 하는 개발자에게 로그는 생명이다🧐

 

라이브 서비스와 관련된 오류 및 결함이 접수되면,

가장 먼저 로그를 확인하고 로그를 토대로 이슈 구간을 확인하여 버그 원인을 추적해야 하기 때문이다

 

로그에 필요한 내용을 잘 기록하는 만큼 문제 해결 시간을 단축할 수 있지만

반대로 로그가 부족하다면.. 그만큼 에러 원인을 찾기까지의 시간이 소요되어 서비스에 대한 고객의 만족도가 떨어지게 된다.

 

로그의 종류는 여러가지지만!

아파치 로그, 커스텀 웹로그, 쿼리로그 등등..

 

오늘은 Query Log에 대한 이야기를 하고자 한다 :)

특히, 유지보수의 전쟁터인.. 현업에서의 경험을 바탕으로 쿼리 로그가 필요한 시점, 로그에 담아야할 내용 등을 정리해보려고 한다.

 

DB Log / Query Log

여기서 말하는 디비 로그란, 말 그대로 DB에서 실행된 SQL문에 대한 로그를 의미한다.

(우리 회사에서는 디비 로그, 쿼리 로그 용어를 섞어서 쓰는 편이다. 둘다 같은 뜻!)

 

언제 필요할까?

INSERT, SELECT, UPDATE, DELETE

 

당연히 쿼리가 실행되는 모든 순간이 로그로 남아야 한다.

라는 생각에 도달하기까지 병아리 시절의 나는 2가지의 물음표가 있었다.

1) 로그 용량이 너무 크지 않을까?
2) SELECT 로그도 꼭 필요한가?

 

 

1) 로그 용량이 너무 크지 않을까?

물론 쿼리 로그를 모두 보관하게 되면.. 그만큼 서버에서 메모리를 많이 잡아 먹는다.

 

그러나 유지보수를 위해서는 쿼리 로그는 꼭 필요하기 때문에

우리 회사는 서비스가 운영되는 리얼 서버에는 쿼리 로그를 함께 저장하지 않고, 데이터운영파트에서 따로 관리하고 있다.

 

 

신규 입사자분들이 99.99% 확률로 나에게 '리얼 DB 로그는 어떻게 봐요?'라고 질문 주시다보니

이제는 로그 확인 방법, 로그 추출 요청 가이드가 기계처럼 답변이 나오는.. 나의 모습 (😅)

 

서버 용량을 많이 차지한다고 해서 무조건 배제시키기보다는

효율적으로 관리할 수 있는 방법을 찾아 선택하는 것도 중요하다고 생각한다.

 

 

2) SELECT 로그까지 필요한가?

필요하다!! 무조건 필요하다

00/00일 14시 이벤트 진행 당시 DB부하가 발생하였습니다.
해당 시점에 발생된 슬로우 쿼리가 있는지 확인 부탁드립니다.

 

가끔 특정 DB에서 심하게 부하가 걸리는 경우가 있다.

보통 검색 기간 및 개수를 너무 크게 잡아 쿼리 실행 시간이 길어지는 경우..랄까

 

이렇게 부하를 유발하는 슬로우쿼리가 발생하기 때문에

그라파나에서 특정 시간대에 MySQL Questions 수치가 급격하게 높았던 것을 확인하고

느리다는 문의까지 겹쳤다면 해당 시간대에 발생한 슬로우쿼리를 찾아보는 편이다.

 

슬로우쿼리의 경우에는, 쿼리 수정을 통해 성능 향상까지 이루어질 수 있도록 개선이 필요하므로

유지보수 과정에서 꼭 확인이 되어야 한다.

 

어떤 내용을 담아야할까

회사를 다니면서 경험한 바로는 아래 6가지가 필요했다.

 

1. 쿼리 실행 일시
2. Acceess IP
3. Primary / Secondary 여부
4. 서비스 종류 (PC/Mobile/API/Admin/Scheduler 등)
5. 진입점
6. 실행 쿼리

 

1. 쿼리 실행 일시

쿼리 실행 시간은 너무 중요하고 당연한 단서..

기본 사항이라 별도의 설명은 생략하겠다.

 

 

2. 접속 IP

 

IP를 통해 쿼리 실행 주체가 누구인지 파악이 필요한 경우가 종종 있다.

 

예를 들어 아래와 같은 문의가 들어왔다고 해보자

금일 저희 업체에서는 진행한 작업이 없는데
10:30 이후로 Gold 그룹에 해당하는 회원의 혜택 할인 값이 변경되어 있습니다.

 

문제는.. 우리 쪽에서도 해당 업체의 회원 값을 수정한 적이 없다는 것이다.

 

서비스 이용자, 담당자 모두 "아무것도 안 했는데요."라는 입장일 경우에는

로그에 남은 UPDATE 쿼리의 실행 시간과 IP를 토대로 범인을 잡아낼 수 있다 🔍

 

[2023-01-01 10:30:00] [111.111.11.11] UPDATE memberGroup SET (...)=(...);

 

만약 이제 로그에 남은 `111.111.11.11`가 누구의 IP인지만 확인하면 상황은 쉽게 해결된다. 👍

 

 

3. Primary / Secondary 여부

 

Primary DB 만으로 서비스를 운영하기에 트래픽이 과하게 몰려 성능 이슈가 발생하는 업체는

성능 향상을 위해 Secondary DB를 추가로 더 붙이는 편이다.

[2023-07-26 04:07:28] [Master] UPDATE memberGroup SET (...)=(...);
[2023-07-26 04:07:30] [Slave] SELECT * FROM mall WHERE useFl='y';

 

 

실제로 Secondary DB도 잘 타고 있는지 확인하기 위해 Primary / Secondary 중 어느 DB에서 실행된 쿼리인지도 기록이 필요하다.

 

 

4. 서비스 종류

 

서비스 종류..? 라는 네이밍이 찰떡인지는 잘 모르겠지만 😅 특별한 단어가 생각나지 않음!

 

 

웹서비스의 경우, 유저 페이지 중에서도 PC, Mobile이 있고, 관리자 페이지도 있고 여러 종류가 있다.

따라서 어떤 페이지로 진입하여 실행된 쿼리인지도 함께 기록이 필요하다.

 

예를 들어 아래와 같은 문의가 들어왔다고 가정해보자

10:30 쯤에 관리자페이지에서 실수로 회원을 잘못 등록한 것 같은데, 저희 직원측에서는 확인이 어렵습니다.
혹시 확인 가능할까요?

 

그리고 로그를 열어본 결과 아래와 같이 기록이 되어 있다면..?

[2023-01-01 10:30:00] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:05] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:10] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:15] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:20] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:25] INSERT INTO member (...) VALUES (...);

 

이제 혼란에 빠지기 시작한다.

10:30 쯤에 여러 회원이 등록되었다면, 어떤 쿼리가 관리자 페이지에서 실행된 쿼리인지 확인하는 것은 난이도 상이다..

 

만약 아래와 같이 남았다면?

[2023-01-01 10:30:00] [PC] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:05] [MOBILE] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:10] [ADMIN] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:15] [API] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:20] [PC] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:25] [ADMIN] INSERT INTO member (...) VALUES (...);

 

2개의 로그에서 [ADMIN]이 보인다!

확인해야 할 범위가 확연하게 줄었다는 점에서 보다 빠른 데이터 확인과 양질의 답변이 나갈 수 있게 되었다 :)

안녕하세요. 요청하신 시간대를 기준으로 하여 1분 내외의 로그를 확인해보았을 때

[2023-01-01 10:30:10] [ADMIN] INSERT INTO member (...) VALUES (...);
[2023-01-01 10:30:25] [ADMIN] INSERT INTO member (...) VALUES (...);

관리자페이지에서 등록하신 총 2개의 로그가 확인됩니다.
로그 내 상세한 정보 참고하시어 적절한 조치 진행해주시길 부탁드립니다.

 

현재 포스팅에서는 위와 같이 간단한 예시로 설명했지만,

서비스를 구분하여 로그에 함께 기록하는 것은 정말 추적 시간 단축에 많은 도움을 준다.

 

 

5. 쿼리 실행 구간 및 진입점

 

예를 들어 로그에 아래와 같이 기록이 남았는데,

보안 상의 문제로 WHERE 절의 조건값이 바인딩 처리된 로그만 확인이 가능하다고 가정하자

[2023-01-01 10:30:10] SELECT * FROM order WHERE memberFl = ?;
[2023-01-01 10:30:15] SELECT * FROM order WHERE memberFl = ?;

 

주문 관련 테이블을 조회하는 동일한 쿼리가 실행되었지만

저 로그만으로 어떤 상황에서 실행된 쿼리인지 확인하기는 쉽지 않아.

 

만약 아래와 같이 추가된다면?

[2023-01-01 10:30:10] [(경로_생략)/Order|getMemberOrderList] SELECT * FROM order WHERE memberFl = ?;
[2023-01-01 10:30:15] [(경로_생략)/Order|getNonmemberOrderList] SELECT * FROM order WHERE memberFl = ?;

 

쿼리 실행된 진입점이 함께 기록됨으로써

1번 쿼리는 회원 주문을 조회하는 메서드에서 실행이 되었고,

2번 쿼리는 비회원 주문을 조회하는 메서드에서 실행된 쿼리임을 바로 확인할 수 있다.

 

쿼리를 실행한 메소드가 따로 로그에 남지 않았다면, 해당 쿼리를 호출하는 모든 메서드를 찾아야 하는 상황이었을 것이다.

시간 단축이 된다는 점에서 쿼리 실행 지점을 남기는 것은 정말 큰 장도움이 된다!

 

그러나.. 사실 쿼리 실행 메소드 경로만으로는 힌트가 부족한 상황이 많다

위에서 기록한 메서드는 '쿼리 호출 시점'이고, 실제로 어떤 페이지로 진입하여 쿼리가 호출되었는지는 확인이 어렵기 때문이다.

 

즉, 해당 메서드를 호출하는 곳이 많을 수록 더더욱 쿼리 실행에 대한 진입점 정보가 필요하다.

[2023-01-01 10:30:15] [(경로_생략)/Order|getNonmemberOrderList] [(경로_생략)\OrderController|run] SELECT * FROM order WHERE memberFl = ?;

 

cc. https://techblog.woowahan.com/13429/
유사한 이슈를 정리한 우형 기술 포스팅도 있다!

 

6. 실행 쿼리

실행한 쿼리는 당연히 남겨야죠 🤣

 

최종 정리

[2023-01-01 00:00:00] [(IP)] [(MASTER/SLAVE)] [(SERVICE_CATEGORY)] [(MATHOD_PATH)|(METHOD_NAME)] [(CONTROLLER_PATH)|(METHOD_NAME)]  */SELECT * FROM member *

[2023-07-26 04:07:28] [Master] [Front] [(경로_생략)\Member|selectMemberList] [(경로_생략)\Member\LoginController|run] SELECT * FROM member WHERE (...)=(...);

 

 

 

위에 언급한 필요한 요소들을 종합하여 완성된 쿼리 로그다. 사실 입사했을 때부터 위 형태로 갖춰져있지는 않았다.

나는 로그 포맷 다듬기 및 진입점 추가하기를 담당했다 😎

아직 위 형태에서 더 필요한 내용은 없었어서, 이정도로 정리하여 현업에서 사용 중이다.

 

 

이번 포스팅에서 다룬 쿼리 로그에 대한 이야기는 여기서 끝!