Mysql Slow 쿼리 Slack으로 알람 보내기

dragonappear·2022년 7월 5일
aws
1

AWS

목록 보기
3/6

출처

제목: "PostgreSQL RDS Slow 쿼리 Slack으로 알람 보내기"
작성자: tistory.com(jojoldu)
작성자 수정일: 2021년5월8일
링크: https://jojoldu.tistory.com/570
작성일: 2022년7월5일

글 작성 계기

  • RDS 역시 서버이다. 요청이 들어오면 요청을 처리하고 응답을 한다. RDS에서 늦게 응답을 하면 클라이언트인 로직은 클라이언트에게 응답을 늦게할 수 밖에 없다.
  • 정상적으로 요청(쿼리)을 보냈는데 RDS에서 응답이 늦게 온다면 또 그걸 내가 모르고 있다면? 억울하지 않은가?
  • 억울한? 상황을 해결하고자 향로님의 글을 보고 작성하게 되었다.

시작 전

서비스를 운영하다보면 여러가지 이유로 서버 장애가 발생한다.
그 중 가장 빈도수가 높은 원인은 DB의 슬로우쿼리이다.

어떤 쿼리가 언제, 얼마나 긴시간동안 수행되었는지에 대해 알람을 받거나 모니터링이 되어야 서비스에 이슈가 될만한 쿼리들을 지속적으로 탐지하고 개선이 가능하기 때문이다.

이번 시간에는 AWS RDS MySQL에서 슬로우 쿼리에 대한 로그를 남기고 이에 대해 슬랙 알람을 보내도록 설정하는 방법을 진행해보자.

전체적인 구조는 다음과 같다.

한 번 이렇게 구성하고 나면 이후에 CloudWatch에 적재된 슬로우 쿼리를 ElasticSearch 로 보내어 대시보드를 통한 슬로우쿼리 모니터링 시스템도 쉽게 구축할 수 있게 된다.

이건 다음 시간에 알아보자.

1. Slow Log 남기기

제일 먼저 할 것은 현재 RDS MySQL에 슬로우 쿼리 로그를 남기는 것이다.

1-1 파라미터 그룹 설정

사용하는 RDS의 파라미터 그룹에 접속해서 아래 2개 파라미터 변경을 해주면 된다.

  • log_statement

    • 총 4개의 상태값을 가질 수 있음
    • none , ddl , mod , all
    • DML( SELECT,UPDATE,DELETE,INSERT 등)에 대한 로그만 남기고 싶다면 mod를 선택

  • log_min_duration_statement

    • 지정된 시간 이상 쿼리가 수행되면 로그를 남긴다.
    • 단위는 ms (즉, 1000로 지정할 경우 1초)
    • 1000으로 할 경우 1초이상 수행된 쿼리들은 모두 로그로 남게된다.

mysql의 파라미터 그룹인 경우

이렇게 하고 나서 최종 저장을 하면 DB의 재시작과 함께 적용된다.

주의
RDS의 파라미터를 변경하게 되면 적용하기 위해서 자동으로 DB가 재시작된다. HA가 되어있지 않고, 단일 DB만 사용하고 있다면, 재부팅되는동안 서비스 전체가 정지된다. 주의가 필요하다

DB의 재시작이 끝나면 아래처럼 구성->게시된 로그-> Postgresql 항목으로 들어가서 로그를 볼 수 있다.

확인이 되었으면 실제 로그가 남는지 확인해보자.

1-2 슬로우 쿼리 테스트

해당 RDS에 접속하여서 아래와 같이 슬로우 쿼리를 실행해보자

postgresql: SELECT pg_sleep(2);
mysql: do sleep(5);

지정된 초만큼 sleep을 수행한다.

수행하고 나면

  • 구성->게시된 로그->Postgresql
  • 혹은 Cloudwatch의 로그그룹에 들어가서 볼 수 있다.

이번 시간에는 슬로우쿼리를 조건을 1초로 두고, 1초 이상은 모두 로그를 남기도록 하였다.

상황에 따라 1초보다 더 높은값을 둬도 되나, 1초 이상이면 충분히 슬로우 쿼리로 판단된다

그래서 1초 이상의 쿼리를 다 남긴뒤, 상황에 따라 Lambda에서 if 문을 통해 별도의 슬랙 알람발송 조건(5초 이상인 경우) 등을 두는게 낫다고 본다.

이렇게 로그를 남겨야 이후에 ELK나 기타 다른 모니터링 도구에서 상세 분석이 가능해진다.

쿼리 로그가 남는 것이 확인되었다면, 이제 Lambda 함수를 만들어보자

2. Lambda

이번에 만들 Lambda 함수는 CLoudwatch에서 실시간으로 보내주는 로그를 파싱해서 슬랙으로 보내주는 역할을 한다.

실제로는 Cloudwatch 연동까지 해야 기능이 작동하지만, 그 전에 미리 Lambda를 만들어놓고, Cloudwatch 설정을 진행할 예정이다.

2-1 Lambda 함수 생성

먼저 아래와 같이 간단하게 Lambda 함수를 생성한다.

함수 코드는 간단하게 Cloudwatch에서 넘어오는 데이터만 확인하기 위해 아래와 같이 작성한다.

var zlib = require('zlib');
exports.handler = function(input, context) {
    var payload = Buffer.from(input.awslogs.data, 'base64');
    zlib.gunzip(payload, function(e, result) {
        if (e) { 
            context.fail(e);
        } else {
            result = JSON.parse(result.toString('ascii'));
            console.log("Event Data:", JSON.stringify(result, null, 2));
            context.succeed();
        }
    });
};
  • zlib,Buffer.com(input.awslogs.data,'base.64'
    • Cloudwatch의 구독 기능을 통해 전송 되는 로그는 1)Base64로 인코딩되고 2)gzip형식으로 압축되어 있다.
    • 그래서 이걸 풀어서 볼 때는 역순으로 1)gzip 압축을 풀고 2) Base64로 디코딩을 해야만 한다.

나머지 코드는 풀어진 JSON 데이터를 그대로 Console에 출력하는 것 뿐이다.

이 코드가 작동하는지 검증하기 위해 테스트를 수행해보자.

수행해보면 Cloudwatch에서 로그를 어떤 JSON 형태로 전달해주는지 확인해볼 수 있다.

START RequestId: cb4cd8ce-b9bf-4df7-bcf3-1674db634bf6 Version: $LATEST
2022-07-06T01:39:09.344Z	cb4cd8ce-b9bf-4df7-bcf3-1674db634bf6	INFO	Event Data: {
  "messageType": "DATA_MESSAGE",
  "owner": "123456789123",
  "logGroup": "testLogGroup",
  "logStream": "testLogStream",
  "subscriptionFilters": [
    "testFilter"
  ],
  "logEvents": [
    {
      "id": "eventId1",
      "timestamp": 1440442987000,
      "message": "[ERROR] First test message"
    },
    {
      "id": "eventId2",
      "timestamp": 1440442987001,
      "message": "[ERROR] Second test message"
    }
  ]
}
END RequestId: cb4cd8ce-b9bf-4df7-bcf3-1674db634bf6
REPORT RequestId: cb4cd8ce-b9bf-4df7-bcf3-1674db634bf6	Duration: 64.26 ms	Billed Duration: 65 ms	Memory Size: 128 MB	Max Memory Used: 57 MB	Init Duration: 151.54 ms

그럼 이제 이렇게 넘어오는 데이터를 PostgreSQL(필자는 MySQL 로그) 형태로 변경해서 빠른 테스트와 Lambda 함수 코드를 작성해보자.

2-2 MySQL 테스트 로그 생성

Lambda에서 기본으로 제공하는 CliudWatch 테스트 데이터는 PostgreSQL 로그 데이터가 아니다

그래서 PostgreSQL의 쿼리 형태로 테스트 데이터를 변경해주어야 한다.

RDS PostgreSQL의 쿼리로그는 아래와 같은 형태로 전달된다.

PostgreSQL

2021-05-07 08:28:23 UTC:127.0.0.1(56644):test@test:[7221]:LOG:  duration: 10045.607 ms  execute <unnamed>: SELECT pg_sleep(10)

Mysql

# Time: 2022-07-05T07:09:40.801098Z # User@Host: admin[admin] @ [10.0.2.240] Id: 20050 # Query_time: 5.000209 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 1 use moccozy; SET timestamp=1657004975; do sleep(5);

로그가 육안으로 보기에는 좋으나, 파싱해서 사용하기에는 불편하다

하지만, 아쉽게도 RDS PostgreSQL에서는 이 로그 포맷을 변경할 수는 없다.

PostgreSQL을 설치해서 쓴다면 변경 가능하나, 관리형 서비스인 RDS에서는 해당 설정에 대해서는 변경을 못하도록 막아두었다.

여튼 위 로그 데이터를 테스트 데이터에 넣어서 Gzip압축을 해야한다

압축전 JSON 형태는 다음과 같다.

{
  "messageType": "DATA_MESSAGE",
  "owner": "123456789123",
  "logGroup": "testLogGroup",
  "logStream": "testLogStream",
  "subscriptionFilters": [
    "testFilter"
  ],
  "logEvents": [
    {
      "id": "eventId1",
      "timestamp": 1440442987000,
      "message": "# Time: 2022-07-05T07:09:40.801098Z # User@Host: admin[admin] @ [10.0.2.240] Id: 20050 # Query_time: 5.000209 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 1 use moccozy; SET timestamp=1657004975; do sleep(5);"
    }
  ]
}

기존 메시지 포맷에서 logEvents.[].message에만 PostgreSQL 로그를 넣은 형태이다.

이 JSON을 온라인 gzip 압축 사이트에서 압축하면 테스트 데이터를 얻을 수 있다.

만약 이 과정이 귀찮다면(혹은 추가 가공없이 그대로 쓰고 싶다면) 아래 JSON을 복사해서 그대로 테스트 데이터로 써도 된다

{
  "awslogs": {
    "data": "H4sIAAAAAAAACkVP22rDMAz9FeOnFtIiu86lZoyFLguDjD0keyqhZI0IgdyInV0o/fcp2cqQEDo6hyPpwls0pqgw+x6Qa/4YZuHpJUrTMI64w/vPDkcaC7lTrucHe2po3PRVPPbTQIxFY5MbXJjUjli0/9QfdriZ3s15rAdb991T3VgcDdfHRfYLeb4YRB/Y2Zm68LokH5zxcynIwtZ0ri1a2iyUAqXkPvABwLm9QXIJUmzA3YDPINCScsfesoMW0t8ChVi5nqfUWs+LH+aij76UItfJa6wZK6exmE/UTAAod+uRUWsYwy88TxbZ3dR1RYvlvWZplESHjA3VyTSIw0rAml/z6w+YOKmEVQEAAA=="
  }
}

변경된 테스트 데이터도 잘 노출되는지 확인해보자

Lambda 콘솔에서도 결과를 바로 볼 수도 있지만, Cloudwatch에서 Lambda 로그를 보고 싶으면 아래과 같이 확인할 수 있다.

CloudWatch -> 로그 -> 로그그룹 -> aws/lambda/으로 이동해서 볼 수도 있다.

만약 로그 그룹이 없음 오류가 발생할 경우
https://aws.amazon.com/ko/premiumsupport/knowledge-center/lambda-cloudwatch-log-streams-error/

로그를 확인해보면 다음과 같은 데이터를 볼 수 있다.

이제 테스트 데이터도 생성되었으니, 바로 이 데이터를 통해 슬랙 발송 함수를 만들어보자

2-3 Lambda 함수 코드 작성

Labmda 함수 전체코드는 다음과 같다

const https = require('https');
const zlib = require('zlib');
const SLOW_TIME_LIMIT = 3; // 3초이상일 경우 슬랙 발송
const SLACK_URL = '슬랙 Webhook URL';

exports.handler = (input, context) => {
    var payload = Buffer.from(input.awslogs.data, 'base64');
    zlib.gunzip(payload, async(e, result) => {
        
        if (e) { 
            context.fail(e);
        } 
        
        const resultAscii = result.toString('ascii');
        
        let resultJson;

        try {
            resultJson = JSON.parse(resultAscii);
        } catch (e) {
            console.log(`[알람발송실패] JSON.parse(result.toString('ascii')) Fail, resultAscii= ${resultAscii}`);
            context.fail(e);
            return;
        }
        
        console.log(`result json = ${resultAscii}`);
        
        for(let i=0; i<resultJson.logEvents.length; i++) {
            const logJson = toJson(resultJson.logEvents[i], resultJson.logStream);
            console.log(`logJson=${JSON.stringify(logJson)}`);
        
            try {
                const message = slackMessage(logJson);
                
                if(logJson.queryTime > SLOW_TIME_LIMIT) {
                    await exports.postSlack(message, SLACK_URL);
                }    
            } catch (e) {
                console.log(`slack message fail= ${JSON.stringify(logJson)}`);
                return;
            }

        }
    });
};

function toJson(logEvent, logLocation) {
    const message = logEvent.message;
    
    const currentTime = toYyyymmddhhmmss(logEvent.timestamp);
    const dateTimeRegex = new RegExp('(\\d{4})-(\\d{2})-(\\d{2}) (\\d{2}):(\\d{2}):(\\d{2}) UTC:');
    const matchArray = message.match(dateTimeRegex);
    const removedUtcMessage = message.replace(matchArray[0], '');
    const messages = removedUtcMessage.split(':');
    const timeSplit = messages.length>6? messages[5].trim().split(' '): [];
    const queryTime = timeSplit.length>1? (Number(timeSplit[0]) / 1000).toFixed(3): 0;
    const querySplit = message.split('\<unnamed\>\:');

    return {
        "currentTime": currentTime,
        "logLocation": logLocation,
        "userIp": messages[0].trim(),
        "user": messages[1].trim(),
        "pid": messages[2].trim().replace('[', '').replace(']', ''),
        "queryTime": queryTime,
        "query": querySplit[querySplit.length-1].trim()
    }
}

// 타임존 UTC -> KST
function toYyyymmddhhmmss(timestamp) {

    if(!timestamp){
        return '';
    }

    function pad2(n) { return n < 10 ? '0' + n : n }

    var kstDate = new Date(timestamp + 32400000);
    return kstDate.getFullYear().toString()
        + '-'+ pad2(kstDate.getMonth() + 1)
        + '-'+ pad2(kstDate.getDate())
        + ' '+ pad2(kstDate.getHours())
        + ':'+ pad2(kstDate.getMinutes())
        + ':'+ pad2(kstDate.getSeconds());
}

function slackMessage(messageJson) {
    const title = `[${SLOW_TIME_LIMIT}초이상 실행된 쿼리]`;
    const message = `언제: ${messageJson.currentTime}\n로그위치:${messageJson.logLocation}\n계정: ${messageJson.user}\n계정IP: ${messageJson.userIp}\npid: ${messageJson.pid}\nQueryTime: ${messageJson.queryTime}초\n쿼리: ${messageJson.query}`;
    
    return {
        attachments: [
            {
                color: '#2eb886',
                title: `${title}`,
                fields: [
                    {
                        value: message,
                        short: false
                    }
                ]
            }
        ]
    };
}

exports.postSlack = async (message, slackUrl) => {
    return await request(exports.options(slackUrl), message);
}

exports.options = (slackUrl) => {
    const {host, pathname} = new URL(slackUrl);
    return {
        hostname: host,
        path: pathname,
        method: 'POST',
        headers: {
            'Content-Type': 'application/json'
        },
    };
}

function request(options, data) {

    return new Promise((resolve, reject) => {
        const req = https.request(options, (res) => {
            res.setEncoding('utf8');
            let responseBody = '';

            res.on('data', (chunk) => {
                responseBody += chunk;
            });

            res.on('end', () => {
                resolve(responseBody);
            });
        });

        req.on('error', (err) => {
            console.error(err);
            reject(err);
        });

        req.write(JSON.stringify(data));
        req.end();
    });
}

각각의 function들은 다음과 같은 역할을 한다.

  • toJson

    • CloudWatch에서 넘겨준 Log 데이터를 가공하기 쉽도록 JSON으로 파싱하는 역할을 한다.
    • PostgreSQL 로그가 한줄의 text 로 나열된 형태라서 : 를 구분자로 두어 불필요한 데이터는 버리고 필요한 데이터만 가공한다.

  • toYyyymmddhhmmss

    • UTC 시간 데이터를 식별가능한 KST로 전환한다.

  • slackMessage

    • toJson을 통해 받은 JSON 데이터를 Slack 노출용 메시지로 변환한다.

  • postSlack

    • request function 을 통해 Slack으로 메시지를 발송한다.

  • options

    • https 모듈에서 인식 가능한 HTTP Options를 만들어준다.

  • request

    • callback만 지원하는 https 모듈을 async/await를 사용할 수 있도록 Promise 객체를 만들어준다.

코드 중간중간 function 중에는 exports 되어 있는 것들이 있다. 이들은 테스트 코드로 해당 function만 테스트하기 위해 exports를 한 것이라 기능 자체는 일반 function과 차이가 없다.

위 코드는 PostgreSQL에서 Slow Query에 대한 파싱이고, 아래는 MySQL에 대해 파싱하도록 수정하였다.

정규식 잘몰라서 그냥 무식하게했다..

function toJson(logEvent, logLocation) {
    const message = logEvent.message;
    const splitMessages = message.split("#");
    const userInfos = splitMessages[2].split(" ");
    const queryInfos = splitMessages[3];
    const queryTime = queryInfos.split(" ")[2];
    const currentTime = toYyyymmddhhmmss(logEvent.timestamp);
    
    return {
        "currentTime": currentTime,
        "logLocation": logLocation,
        "userIp": userInfos[5],
        "user": userInfos[2],
        "pid": userInfos[8],
        "queryTime": queryTime,
        "query": queryInfos
    }
}

3. CloudWatch & Lambda 연동

Cloudwatch와 Lambda의 연동은 쉽다

이미 구독기능을 AWS에서 지원하기 때문이다.

먼저 RDS Postgre의 로그 그룹으로 이동해서 로그그룹 선택 -> 작업 -> 구독필터 -> Lambda 구독 필터 생성을 차례로 선택한다.

구독 필터 생성 화면에 들어가면, 2-1에서 만든 Lambda 함수를 대상에 등록한다.

아래로 내려가보면 로그 형식이 나오는데. 여기서 로그 형식은 기타로 선택한다.

구독 필터 패턴의 경우 필요한 형태에 따라 넣어주면 된다.

정규표현식이 아직 미지원 되어서 여기서 클라우드워치 로그 전용 패턴을 사용해야 한다.

"LOG" "select" "duration"로 등록하여 select절만 사용하도록 했다.

구독 필터 이름이 없는 경우 생성이 불가능하니 꼭 식별가능한 이름으로 입력한다.

기존의 데이터에 대한 패턴 테스트까지 끝났다면 스트리밍 시작 버튼을 클릭하여 구독을 활성화시킨다.

그럼 아래와 같이 로그그룹의 구독 필터에 1개의 구독이 추가된 것을 볼 수 있다.

모든 설정이 끝났다!

이제 전체 테스트를 한번 해보자!

DB 툴로 강제로 스로우 쿼리를 발생시켜보자.

do sleep(5);

그러면 아래와 같이 알람이 온다.

보완해야할 부분

Mysql 로그 정규식으로 파싱

profile
dragonappear
이전 포스트

CloudWatch 이상 지표 Slack으로 알람으로 보내기(feat: SNS,Lambda)

다음 포스트

RDS 이벤트 Slack으로 알람 받기

0개의 댓글