{"id":"IL-0443","org":"Repro","date":"2019-11-11","docs":[],"title":{"en":"A Repro Aurora MySQL reader restarted unexpectedly and writer insert latency rose about sevenfold for a day or more","ko":"Aurora MySQL reader 가 이유 없이 재시작한 뒤 writer 의 insert latency 가 7배쯤 오르고 replication lag 가 하루 넘게 이어졌다"},"domain":["database","aws"],"impact":{"scope":"Writer performance of the Aurora MySQL cluster for a day or more after each reader restart; the applications processing data collected by the Repro SDK were delayed","users":"unknown","region":"unknown"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":{"en":"Once the rollback segment has grown large, nothing speeds up its release across the cluster, so the way to avoid the latency is to keep transactions small and stop long-running queries before the rollback segment grows.","ko":"롤백 세그먼트가 커지지 않도록 트랜잭션을 작게 해야 한다. 롤백 세그먼트는 클러스터 전체가 함께 쓰므로, 한번 커지면 인스턴스를 바꿔도 해제가 끝나기를 기다리는 수밖에 없다. 롤백 세그먼트 길이는 show engine innodb status 의 \"History list length\" 값으로 볼 수 있다."},"related":[],"sources":[{"url":"https://tech.repro.io/entry/2024/10/23/085610","kind":"blog","archived":"https://web.archive.org/web/20260805141333/https://tech.repro.io/entry/2024/10/23/085610"}],"summary":{"en":"AWS Support found from internal information that the rollback segment area had kept growing until the reader restarted, and that it began to be released after the restart. For this occurrence the rollback segment grew from about 11/05 10:16 JST, its release began when the reader restarted at about 11/11 19:20 JST, and the release finished at about 11/13 14:31 JST; the restart on 11/5 had followed the same sequence of growth, release and higher commit latency. The rollback segment keeps old versions of updated rows for rollbacks and for other transactions that need to read old data. It is released when transactions end, but a large one takes a long time to release, and the I/O of the release affects the latency of other work. Long transactions on a reader can also keep it growing. AWS considered the higher commit latency after the restart most likely an effect of the release, and suggested that slower commits held locks longer and that the changed spin waits were related to the long transactions and the release. The length of the rollback segment shows as \"History list length\" in `show engine innodb status`.\n\nThe rollback segment is shared by the whole cluster, not tied to one DB instance, so deleting or adding instances or changing I/O performance could not speed up the release, and the only option was to wait for it to finish. AWS advised keeping transactions small so the rollback segment does not grow large.\n\nRepro added a monitor on the rollback segment (mysql.innodb.history_list_length in Datadog) and from then on killed queries that ran long enough to make the reader restart as soon as they were found, which prevented the same failure. About two years after the monitor was added it began alerting almost every week, so Repro, after telling the company, set max_execution_time so that queries are stopped after a fixed time.","ko":"Repro 는 Aurora MySQL 을 쓴다. 2019년 11월 reader 가 이유를 알 수 없이 재시작하고, 그 뒤 writer 의 insert latency 가 7배쯤 오르고 replication lag 가 커진 상태가 하루 넘게 이어지는 일이 두 번 있었다. 그동안 SDK 가 모은 데이터를 처리하는 애플리케이션이 지연됐고, 팀은 writer 성능이 돌아오기를 지켜보기만 했다.\n\nAWS 지원팀이 내부 정보로 조사해 보니 reader 가 재시작하기 전까지 롤백 세그먼트 영역이 계속 늘었고, reader 가 재시작한 뒤에 해제가 시작됐다. 롤백 세그먼트는 레코드가 바뀔 때 롤백이나 다른 트랜잭션의 옛 데이터 읽기에 대비해 옛 정보를 남겨 두는 영역이다. 이 영역은 reader 의 트랜잭션이 길어져도 계속 늘 수 있다. 롤백 세그먼트는 11월 5일 10:16 JST 쯤부터 커졌고, reader 가 재시작한 11월 11일 19:20 JST 쯤 해제가 시작되어 11월 13일 14:31 JST 쯤 끝났다. AWS 지원팀은 커진 롤백 세그먼트를 해제하는 데 드는 I/O 가 커밋 레이턴시를 올린 것으로 봤고, 11월 5일 재시작 때도 같은 흐름이었다고 했다. 롤백 세그먼트는 DB 인스턴스가 아니라 클러스터 전체가 함께 쓴다. 그래서 인스턴스를 지우거나 더해도 해제를 앞당길 수 없었고, 미리 막는 것 말고는 할 수 있는 일이 없었다.\n\n팀은 Datadog 의 mysql.innodb.history_list_length 로 롤백 세그먼트를 감시하는 모니터를 더했고, reader 가 재시작할 만큼 오래 도는 쿼리를 찾는 대로 kill 하게 했다. 그 뒤로는 같은 일을 미리 막을 수 있었다. 모니터를 둔 지 2년쯤 지나 알림이 거의 매주 울리자, 팀은 사내에 알린 뒤 max_execution_time 을 설정했다."},"trigger":{"en":"Long-running queries on the reader; the author recalls that the cause was a query sent to the reader from Redash.","ko":"reader 에서 오래 도는 쿼리 때문에 롤백 세그먼트가 계속 커진 끝에 reader 가 재시작했다. 글쓴이는 그 쿼리가 Redash 에서 reader 로 보낸 것이었다고 기억한다."},"severity":"unknown","symptoms":["high-latency","replication-lag","throughput-degraded"],"timeline":{"detected_after":null,"resolved_after":null},"date_kind":"incident","detection":null,"components":["database","database-replication"],"root_cause":"capacity","remediation":[{"text":{"en":"Waited for writer performance to return, since the rollback segment release could not be sped up","ko":"팀은 writer 성능이 원래대로 돌아올 때까지 지켜보기만 했다."}}],"action_items":[{"text":{"en":"Add a monitor on the rollback segment, mysql.innodb.history_list_length in Datadog","ko":"롤백 세그먼트 길이를 Datadog 의 mysql.innodb.history_list_length 로 감시하는 모니터를 더했다."}},{"text":{"en":"Kill queries that run long enough to make the reader restart as soon as they are found","ko":"reader 가 재시작할 만큼 오래 도는 쿼리를 찾으면 바로 kill 하게 했다."}},{"text":{"en":"Set max_execution_time so queries are stopped after a fixed time","ko":"모니터 알림이 거의 매주 울리게 되자 사내에 알린 뒤 max_execution_time 을 설정해, 일정 시간이 지난 쿼리를 강제로 끝내게 했다."}}],"contributing":["monitoring-blind-spot"],"recurrence_of":null,"symptoms_text":{"en":"A reader of Repro's Aurora MySQL cluster restarted for no known reason, and right after that the writer's insert latency rose to about seven times normal and writer performance stayed badly degraded for a long time. This happened more than once, twice within two weeks by 11 November 2019. While the writer was slow, the applications that process data collected by the Repro SDK fell behind, and the team could only watch until the writer recovered.\n\nThe metrics had the same pattern every time: the reader restarted; its freeable memory dropped fast before the restart; mutex spin waits fell sharply; Rw-excl spin rounds / RW-excl spin waits roughly doubled; commit latency and other latencies rose; replication lag rose; volume read iops increased; and everything returned to normal after one or two days. On the writer, the metric trends changed sharply at the restart and stayed that way for more than a day.\n\nThe team's first hypothesis was that the reader restart emptied its buffer pool, which raised network traffic between the DB instances and the cluster storage and the storage IOPS, and that this also hurt the writer. With this hypothesis the team asked AWS Support.","ko":"Aurora MySQL 의 reader 가 이유를 알 수 없이 재시작했다. 그 직후부터 writer 의 insert latency 가 7배쯤 오르는 등 writer 성능이 크게 떨어진 상태가 오래 이어졌다. 같은 일이 2019년 11월 두 주 사이에 두 번 일어났다.\n\nwriter 성능이 떨어진 동안 SDK 가 모은 데이터를 처리하는 애플리케이션이 지연됐다.\n\n지표에는 매번 같은 모습이 나타났다. reader 가 재시작했고, 재시작 전에 freeable memory 가 빠르게 줄었다. mutex spin waits 는 크게 줄고 Rw-excl spin rounds 와 RW-excl spin waits 는 2배쯤 늘었다. commit latency 를 비롯한 latency 와 replication lag 가 오르고 volume read iops 가 늘었다. writer 지표는 reader 재시작 시점에 갑자기 바뀐 뒤 그 상태로 하루 넘게 이어졌고, 하루이틀 지나면 원래대로 돌아왔다.\n\n팀은 가설을 하나 세웠다. reader 가 재시작해 buffer pool 이 비면서 DB 인스턴스와 클러스터 스토리지 사이의 네트워크 통신과 클러스터 스토리지의 IOPS 가 늘었고, 그것이 writer 에도 영향을 줬다는 가설이었다. 팀은 이 가설을 가지고 AWS 지원팀에 문의했다."},"updated_at":"2026-11-14T12:34:09.264457Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0443","org_slug":"repro"}