[MySQL 운영 및 !자동화!] Undo 로그 길이 모니터링 및 장기 실행 트랜잭션의 쿼리 조회하기

MySQL을 운영하다보면 종종 Rollback History List Length 메트릭에 걸려있는 알람이 울립니다.

 

트랜잭션이 너무 오래 열려있어서 Length가 길어지는 현상인데요,

MySQL에서는 MVCC 를 통해 잠금없는 SELECT를 구현합니다.

MVCC 매커니즘은 Undo Log(=Rollback Segment)를 통해 구현되기 때문에 Undo Log를 임계치 이하로 관리하는 것이 매우 중요합니다. 임계치를 벗어나게 되면 read 레이턴시가 전반적으로 매우 하락해서 유저 경험 또한 매우 하락하게 되겠죠 -_-;

 

 

제가 경험했던 Undo Log가 길어지는 이유는 크게 세 가지 였습니다. 

1. 서비스 Batch가 장시간 실행되는 경우
2. 개발자가 개인 컴퓨터 환경에서 수동으로 트랜잭션을 열고 난 후에, 커밋이나 롤백하지 않고 시간이 오래 지난 경우
3. cdc 등의 서비스에서 테이블 데이터를 대량으로 긁어가는 경우 (주로 full load)

사실 한 가지라고 봐도 되겠네요. 문제는 모두 [너무 오래 열려있는 트랜잭션] 입니다.

'너무 오래'의 정의는 회사의 규모마다, 서비스의 성격마다, DBMS 호스트의 사양마다 다르겠지만 Read Latency에 영향이 생긴다면 조치를 취해야겠습니다. 모니터링 알람을 걸어놓으면 참 좋겠죠! (AWS Cloudwatch는 따로 메트릭을 제공하고 알람 연동도 쉽습니다. 다른 클라우드 회사는 모르겠네요.)

 

이번 글에서는 롱 트랜잭션에 속한 쿼리를 파악하는 방법을 살펴보고,

이 과정을 자동화해서 쿼리를 슬랙으로 받아보는 자동화를 구현해보겠습니다.

---

 

이제, 문제가 되는  알람은 식별했으니까 DBA가 조치를 취해야합니다.

 

사실 저는 실무에서 잘 대응하지 못했습니다. Undo Log를 어디서 봐야하는지.... 트랜잭션에 속한 쿼리를 어디서 보는건지.... show processlist에서는 보이지 않았기 때문에 더 대응하기 어려웠던 것 같습니다.

 

이제는 잘 대응할 수 있도록 글로 남겨보겠습니다. 호호호

 

MySQL 5.6 버전부터 information_schema의 INNODB_TRX 테이블을 통해 트랜잭션에 대한 정보를 더 자세히 제공해준다고 합니다.

SELECT trx.trx_id,
trx.trx_started,
trx.trx_mysql_thread_id
FROM INFORMATION_SCHEMA.INNODB_TRX trx
WHERE trx.trx_started < CURRENT_TIMESTAMP - INTERVAL 1 SECONDG

*************************** 1. row ***************************
trx_id: 3357
trx_started: 2014-08-08 12:10:23
trx_mysql_thread_id: 2170

row를 보면 트랜잭션ID, 시작시간, 스레드ID 를 뽑아올 수 있는 것으로 보입니다.

 

 

그리고, 방금 뽑아온 스레드ID를 이용해 performance_schema의 threads 테이블에서 더 자세한 정보를 뽑아낼 수 있습니다.

SELECT *
FROM performance_schema.threads
WHERE processlist_id = 2170G

*************************** 1. row ***************************
THREAD_ID: 2189
NAME: thread/sql/one_connection
TYPE: FOREGROUND
PROCESSLIST_ID: 2170
PROCESSLIST_USER: root
PROCESSLIST_HOST: NULL
PROCESSLIST_DB: test
PROCESSLIST_COMMAND: Sleep
PROCESSLIST_TIME: 2428
PROCESSLIST_STATE: NULL
PROCESSLIST_INFO: NULL
PARENT_THREAD_ID: NULL
ROLE: NULL
INSTRUMENTED: YES

꽤 많은 정보를 보여주긴 하지만, 여전히 트랜잭션에 대한 자세한 정보는 부족합니다.

 

이번엔

performance_schema의 events_statements_history 테이블을 스레드ID로 조회해봅시다.

해당 테이블에 특정 스레드가 어떤 event를 발생시켰는지 보여줍니다.

SELECT thread_id,
       EVENT_ID,
       END_EVENT_ID,
       EVENT_NAME,    
       SQL_TEXT
FROM events_statements_history
WHERE thread_id = 2189G

*************************** 1. row *************************** 
thread_id: 2189 
EVENT_ID: 11 
END_EVENT_ID: 33 
EVENT_NAME: statement/sql/show_databases 
SQL_TEXT: show databases 
*************************** 2. row *************************** 
thread_id: 2189 
EVENT_ID: 35 
END_EVENT_ID: 58 
EVENT_NAME: statement/sql/show_tables 
SQL_TEXT: show tables 
*************************** 3. row *************************** 
thread_id: 2189 
EVENT_ID: 60 
END_EVENT_ID: 71 
EVENT_NAME: statement/com/Field List 
SQL_TEXT: NULL 
*************************** 4. row *************************** 
thread_id: 2189 
EVENT_ID: 73 
END_EVENT_ID: 99 
EVENT_NAME: statement/sql/insert 
SQL_TEXT: insert into mytest values (7, "inigo") 
*************************** 5. row *************************** 
thread_id: 2189 
EVENT_ID: 101 
END_EVENT_ID: 132 
EVENT_NAME: statement/sql/select 
SQL_TEXT: select * from mytest

*************************** 6. row *************************** 
thread_id: 2189 
EVENT_ID: 134 
END_EVENT_ID: 144 
EVENT_NAME: statement/sql/begin 
SQL_TEXT: start transaction 

*************************** 7. row *************************** 
thread_id: 2189 
EVENT_ID: 146 
END_EVENT_ID: 176 
EVENT_NAME: statement/sql/select 
SQL_TEXT: select * from mytest 
*************************** 8. row *************************** 
thread_id: 2189 
EVENT_ID: 178 
END_EVENT_ID: 201 
EVENT_NAME: statement/sql/insert 
SQL_TEXT: insert into mytest values (5, "stephen") 
*************************** 9. row *************************** 
thread_id: 2189 
EVENT_ID: 203 
END_EVENT_ID: 225 
EVENT_NAME: statement/sql/insert 
SQL_TEXT: insert into mytest values (6, "dave") 
*************************** 10. row *************************** 
thread_id: 2189 
EVENT_ID: 227 
END_EVENT_ID: 259 
EVENT_NAME: statement/sql/select 
SQL_TEXT: select * from mytest

이제 슬슬 원하는 정보들이 보이는 것 같습니다. 

실제 INSERT 문에 어떤 값들이 들어가는지도 보이고, SELECT 문이 어떤 조건으로 실행되는지도 보입니다.

 

 

다만 events_statements_history 테이블을 트랜잭션 ID가 아니라 스레드ID로 조회했기 때문에 스레드가 날린 모든 명령어가 구분없이 섞여있습니다.

그럼 이제 위 결과에서 트랜잭션 시작점을 찾아봐야합니다.

*************************** 6. row *************************** 
thread_id: 2189 
EVENT_ID: 134 
END_EVENT_ID: 144 
EVENT_NAME: statement/sql/begin 
SQL_TEXT: start transaction

EVENT_ID가 134인 row에서 트랜잭션 시작점을 찾았습니다. 

조회한 결과로 SQL_TEXT에 commit으로 표시되는 row가 없으니 아직 활성상태의 transaction인 것도 유추해볼 수 있습니다.

 

 

그런데 매 번 이렇게 눈으로 트랜잭션의 시작과 끝을 찾을 수는 없겠죠! (찾으려면 찾을 수는 있지만 그건 좀 ;;)

지금까지 활용한 MySQL information_schema와 performance_schema의 여러 테이블을 조인해서 가독성 좋게 만들어봅시다!

SELECT ps.id 'PROCESS ID',
       ps.user,
       ps.host,
       esh.event_name 'EVENT NAME',
       esh.sql_text 'SQL',
       esh.digest_text
FROM information_schema.innodb_trx trx
JOIN information_schema.processlist ps ON trx.trx_mysql_thread_id = ps.id
JOIN performance_schema.threads th ON th.processlist_id = trx.trx_mysql_thread_id 
AND trx.trx_mysql_thread_id = 258 -- PROCESSLIST ID 기재
JOIN performance_schema.events_statements_history esh ON esh.thread_id = th.thread_id
WHERE esh.EVENT_ID >= (
    SELECT MAX(EVENT_ID)
    FROM performance_schema.events_statements_history
    WHERE EVENT_NAME = 'statement/sql/begin' -- 트랜잭션 시작점 찾기
)
ORDER BY esh.EVENT_ID;

+------------+-------+--------------------+----------------------+------+----------------------------------------------+
| PROCESS ID | user  | host               | EVENT NAME           | SQL  | digest_text                                  |
+------------+-------+--------------------+----------------------+------+----------------------------------------------+
|        258 | admin | 14.35.54.105:50338 | statement/sql/begin  | NULL | START TRANSACTION                            |
|        258 | admin | 14.35.54.105:50338 | statement/sql/select | NULL | SELECT * FROM `sysbench` . `sbtest1` LIMIT ? |
+------------+-------+--------------------+----------------------+------+----------------------------------------------+

좀 괜찮죠? 이걸 토대로 개발팀과 커뮤니케이션하면 됩니다.

 

processlist id는 어디서 가져오면 좋을까요?

보통 Undo Log는 아래 명령으로 조회합니다.

SHOW ENGINE INNODB STATUS;

------------
TRANSACTIONS
------------
Trx id counter 3368
Purge done for trx's n:o < 3365 undo n:o < 0 state: running but idle
History list length 10
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 2169, OS thread handle 0x12bf06000, query id 4734 localhost root init
show engine innodb status
---TRANSACTION 3363, ACTIVE 1924 sec
1 lock struct(s), heap size 360, 0 row lock(s), undo log entries 1
MySQL thread id 2170, OS thread handle 0x12be1e000, query id 4726 localhost root cleaning up
Trx read view will not see trx with id >= 3364, sees < 3364

중간쯤 보다보면 'History list length 10' 문자를 확인할 수 있습니다.

밑에서 2번째 줄을 보면 스레드ID 도 친절하게 나와있습니다. (thread id랑 processlist id랑 되게 헷갈리게 되어있습니다..)

 

 

그런데 SHOW ENGINE INNODB STATUS는 write를 포함하지 않은 트랜잭션의 active 상태는 추적해주지 않는 것 같습니다(확실치 않으나 실험해본 결과는 그렇네요..)

그래서, READ만 포함되어있는 트랜잭션의 PROCESSLIST ID는 따로 쿼리를 날려서 추측하는 방법이 있을 것 같습니다.

SELECT * FROM PERFORMANCE_SCHEMA.THREADS
WHERE processlist_id IS NOT NULL AND TYPE='FOREGROUND' AND PROCESSLIST_USER!='rdsadmin' AND PROCESSLIST_USER!='event_scheduler' 
ORDER BY PROCESSLIST_TIME DESC limit 1;

+-----------+---------------------------+------------+----------------+------------------+------------------+----------------+---------------------+------------------+-------------------+------------------+------------------+------+--------------+---------+-----------------+--------------+----------------+------------------+-------------------+-----------------------+--------------+------------------+
| THREAD_ID | NAME                      | TYPE       | PROCESSLIST_ID | PROCESSLIST_USER | PROCESSLIST_HOST | PROCESSLIST_DB | PROCESSLIST_COMMAND | PROCESSLIST_TIME | PROCESSLIST_STATE | PROCESSLIST_INFO | PARENT_THREAD_ID | ROLE | INSTRUMENTED | HISTORY | CONNECTION_TYPE | THREAD_OS_ID | RESOURCE_GROUP | EXECUTION_ENGINE | CONTROLLED_MEMORY | MAX_CONTROLLED_MEMORY | TOTAL_MEMORY | MAX_TOTAL_MEMORY |
+-----------+---------------------------+------------+----------------+------------------+------------------+----------------+---------------------+------------------+-------------------+------------------+------------------+------+--------------+---------+-----------------+--------------+----------------+------------------+-------------------+-----------------------+--------------+------------------+
|       666 | thread/sql/one_connection | FOREGROUND |            530 | admin            | 220.120.162.204  | NULL           | Sleep               |              466 | NULL              | NULL             |             NULL | NULL | YES          | YES     | SSL/TLS         |         1000 | USR_default    | PRIMARY          |                 0 |                 93528 |        69014 |           162758 |
+-----------+---------------------------+------------+----------------+------------------+------------------+----------------+---------------------+------------------+-------------------+------------------+------------------+------+--------------+---------+-----------------+--------------+----------------+------------------+-------------------+-----------------------+--------------+------------------+

가져온 PROCESSLIST ID를 토대로 쿼리를 날리면 되겠습니다 호호호.

이제, 가이드를 했다면 kill을 하든,,, 기다리든,,, 개선하든,,, 어떻게든 하면 됩니다.

 

---

 

이제 쿼리를 파악하는 방법은 다 배워봤습니다.

그런데 이 모든 과정을 매 번 수동으로 작업하긴 귀찮죠 ㅎ_ㅎ

AWS CloudWatch는 기본적으로 지연시간을 갖고있어서, 직접 DB에 찔러 가져오는 것 보다 대응이 늦어지게 됩니다. 그리고 쿼리를 보여주지도 않고요.

이제 자동화를 해봅시다.

Java + SpringBoot 를 기반으로 스케줄러 기반의 자동화 스크립트를 짜보겠습니다.

 

기반 환경은 MSA환경에서의 AWS RDS를 대상으로 합니다.

운영하는 클러스터가 수십대 이상일 것으로 예상하고 구현해봅시다.

대강의 흐름은 이렇습니다.

1. X 초마다 모든 클러스터에 속한 인스턴스들의 History List의 길이와 PROCESSLIST ID를 조회 (LongTransactionDetector 클래스, @Scheduled로 검사)
2. 길이 조회 메서드는 MysqlClient 클래스의 findHistoryListLength 메서드
3. History List의 길이가 Y 이상이면 MysqlClient로 processlist id 조회 + 조회된 id로 쿼리 조회
4. 조회된 쿼리 + hll + databaseName을 슬랙으로 전송 (SlackClient 클래스)

 

대충의 흐름입니다. 코드를 봅시다!!!

@Slf4j
@RequiredArgsConstructor
@Component
public class LongTransactionDetector {

    private final long HISTORY_LIST_LENGTH_THRESHOLD = 1000L;
    private final long TRANSACTION_SEARCH_DELAY = 15000L;

    private final MysqlClient mysqlClient;
    private final SlackClient slackClient;

    @Scheduled(fixedDelay = TRANSACTION_SEARCH_DELAY)
    public void findLongTransaction() {
        Map<String, DatabaseConnectionInfo> databases = DynamicDataSourceProperties.getDatabases();
        for (String databaseName : databases.keySet()) {
            long historyListLength = mysqlClient.findHistoryListLength(databases.get(databaseName));
            if (historyListLength >= HISTORY_LIST_LENGTH_THRESHOLD) {
                log.warn("{} 의 HLL이 {} 입니다. 임계치: {}", databaseName, historyListLength, HISTORY_LIST_LENGTH_THRESHOLD);
                int processlistId = mysqlClient.findLongTransactionProcesslistId(databases.get(databaseName));
                List<Query> queries = mysqlClient.findQueryInTransaction(databases.get(databaseName), processlistId);
                slackClient.sendMessage(new QueriesInLongTransactionResponseDTO(databaseName, historyListLength, queries).toString());
            }
        }
    }
}

HLL을 주기적으로 검사하는 Scheduled 클래스입니다.

검사해서 임계치 이상이면 쿼리를 추가로 조회해서 슬랙으로 전송합니다.

 

public long findHistoryListLength(DatabaseConnectionInfo databaseConnectionInfo) {
    String SQL = "SELECT COUNT FROM INFORMATION_SCHEMA.INNODB_METRICS WHERE NAME = 'trx_rseg_history_len'";
    long historyListLength = -1L;
    try (Connection connection = DriverManager.getConnection(
            databaseConnectionInfo.getUrl(), databaseConnectionInfo.getUsername(), databaseConnectionInfo.getPassword());
         Statement statement = connection.createStatement();
         ResultSet resultSet = statement.executeQuery(SQL)) {
        log.info("findHistoryListLength: {}", SQL);
        if (resultSet.next()) {
            historyListLength = resultSet.getLong("COUNT");
        }
    } catch (Exception e) {
        throw new RuntimeException(e.getMessage());
    }

    if (historyListLength == -1L) {
        throw new IllegalStateException("historyListLength 를 불러오는 데 실패했습니다. " + databaseConnectionInfo);
    }
    return historyListLength;
}

HLL을 조회하는 메서드입니다. (MysqlClient 클래스)

 

public int findLongTransactionProcesslistId(DatabaseConnectionInfo databaseConnectionInfo) {
    String SQL = "SELECT PROCESSLIST_ID FROM performance_schema.threads " +
            "WHERE PROCESSLIST_ID IS NOT NULL AND TYPE='FOREGROUND' AND PROCESSLIST_USER!='rdsadmin' AND PROCESSLIST_USER!='event_scheduler' " +
            "ORDER BY PROCESSLIST_TIME DESC limit 1;";
    int processlistId = -1;
    try (Connection connection = DriverManager.getConnection(
            databaseConnectionInfo.getUrl(), databaseConnectionInfo.getUsername(), databaseConnectionInfo.getPassword());
         Statement statement = connection.createStatement();
         ResultSet resultSet = statement.executeQuery(SQL)) {
        log.info("findLongTransactionProcesslistId: {}", SQL);
        if (resultSet.next()) {
            processlistId = resultSet.getInt("PROCESSLIST_ID");
        }
    } catch (Exception e) {
        throw new RuntimeException(e.getMessage());
    }

    if (processlistId == -1L) {
        throw new IllegalStateException("PROCSSLIST_ID 를 불러오는 데 실패했습니다. " + databaseConnectionInfo);
    }
    return processlistId;
}

롱 트랜잭션의 processlist id를 조회하는 메서드입니다.

 

public List<Query> findQueryInTransaction(DatabaseConnectionInfo databaseConnectionInfo, int processlistId) {
    String SQL = "SELECT ps.id , " +
            "       ps.user, " +
            "       ps.host, " +
            "       esh.event_name, " +
            "       esh.sql_text , " +
            "       esh.digest_text " +
            "FROM information_schema.innodb_trx trx " +
            "JOIN information_schema.processlist ps ON trx.trx_mysql_thread_id = ps.id " +
            "JOIN performance_schema.threads th ON th.processlist_id = trx.trx_mysql_thread_id " +
            "AND trx.trx_mysql_thread_id = ? " +
            "JOIN performance_schema.events_statements_history esh ON esh.thread_id = th.thread_id " +
            "WHERE esh.EVENT_ID >= ( " +
            "    SELECT MAX(EVENT_ID) " +
            "    FROM performance_schema.events_statements_history " +
            "    WHERE EVENT_NAME = 'statement/sql/begin') " +
            "ORDER BY esh.EVENT_ID";


    List<Query> queries = new ArrayList();
    try (Connection connection = DriverManager.getConnection(
            databaseConnectionInfo.getUrl(), databaseConnectionInfo.getUsername(), databaseConnectionInfo.getPassword());
         PreparedStatement statement = connection.prepareStatement(SQL)) {
        statement.setString(1, String.valueOf(processlistId));
        log.info("findQueryInTransaction: {}", statement);

        try (ResultSet resultSet = statement.executeQuery()) {
            while (resultSet.next()) {
                int findProcesslistId = resultSet.getInt("id");
                String user = resultSet.getString("user");
                String host = resultSet.getString("host");
                String eventName = resultSet.getString("event_name");
                String sqlText = resultSet.getString("sql_text");
                String digestText = resultSet.getString("digest_text");
                queries.add(new Query(databaseConnectionInfo.getDatabaseName(), findProcesslistId, user, host, eventName, sqlText, digestText));
            }
        }
    } catch (SQLException e) {
        throw new RuntimeException(e.getMessage());
    }
    return queries;
}

롱 트랜잭션에 속한 쿼리들을 조회하는 메서드입니다.

 

 

 

 

슬랙 결과

최종적으로 이렇게 날아오게 됩니다.

가독성은... 뭐.... 어떻게 꾸미면 되겠죠.

날아온다는 사실에 기뻐하면 됩니다 ㅎㅎ

 

이제 컴퓨터가 알아서 HLL 검사 및 쿼리까지 보내주니까 더 이상 느린 CloudWatch 알람을 기다리지 않아도 되고, 

추가적으로 cli로 접속해서 어떤 트랜잭션인지, 어떤 인스턴스인지, 유저가 누구인지 파악할 리소스가 줄어듭니다.

 

성 공 적

 

 

 

 

 

 

 

 

 

 

 

 

 

 

 

https://www.psce.com/en/blog/2015/01/22/tracking-mysql-query-history-in-long-running-transactions/

Tracking MySQL query history in long running transactions

 

https://docs.aws.amazon.com/AmazonRDS/latest/AuroraUserGuide/proactive-insights.history-list.html

The InnoDB history list length increased significantly - Amazon Aurora