Retoday의 방문 기록 저장 API에서는 기록이 참조할 웹사이트를 Upsert한 뒤, 저장된 웹사이트를 조회합니다. 그런데 같은 웹사이트에 여러 사용자의 요청이 몰리면 DB에 행이 있는데도 조회 결과가 없어 요청이 실패하는 문제가 있었습니다.

이 글에서는 실패한 요청의 SELECT를 데이터베이스 단에서 디버깅하며 실제 레코드를 찾은 뒤에도 결과에서 제외되는 이유를 확인하고 해결한 과정을 소개합니다.

문제 현상

서로 다른 사용자 100명이 동시에 기록 생성 요청을 보내는 테스트를 통해 문제를 재현했습니다. 모두 같은 웹사이트에 대한 기록 생성 요청이며, 해당 웹사이트는 데이터베이스에 존재하지 않는 상태로 테스트를 시작했습니다.

실패한 요청들에서는 다음과 같이 SELECT의 조회 결과가 비어서 발생한 예외 로그가 남아 있었습니다.

org.jooq.exception.NoDataFoundException: Cursor returned no rows
	at org.jooq_3.19.24.MYSQL.debug(Unknown Source) ~[?:?]
	at org.jooq.impl.Tools.fetchSingle(Tools.java:2952) ~[jooq-3.19.24.jar!/:?]
	at org.jooq.impl.ResultQueryTrait.fetchSingle(ResultQueryTrait.java:605) ~[jooq-3.19.24.jar!/:?]
	at org.jooq.impl.ResultQueryTrait.fetchSingleInto(ResultQueryTrait.java:626) ~[jooq-3.19.24.jar!/:?]
	at com.retoday.core.domain.history.repository.CustomWebsiteRepositoryImpl.upsertByDomain(CustomWebsiteRepositoryImpl.kt:36) ~[core-0.0.1-plain.jar!/:?]

문제 원인

앞서 Upsert는 다음과 같이 INSERT ... ON DUPLICATE KEY UPDATE를 실행한 뒤 같은 도메인으로 SELECT하는 방식으로 구현되어 있는데요.

1override fun upsertByDomain(website: Website): Website {
2    dsl
3        .insertInto(WEBSITE)
4        .columns(
5            WEBSITE.ID,
6            WEBSITE.DOMAIN,
7            WEBSITE.FAVICON_URL
8        )
9        .values(
10            website.id ?: createUuid(),
11            website.domain,
12            website.faviconUrl
13        )
14        .onDuplicateKeyUpdate()
15        .set(WEBSITE.FAVICON_URL,website.faviconUrl)
16        .execute()
17
18    return dsl
19        .selectFrom(WEBSITE)
20        .where(WEBSITE.DOMAIN.equal(website.domain))
21        .fetchSingleInto()
22}

레코드를 찾지 못해 오류가 발생한 쿼리는 Upsert에서 수행하는 SELECT입니다.

1SELECT id, domain, category, favicon_url
2FROM website
3WHERE domain = 'earlgrey02.com';

Upsert를 했음에도 레코드를 찾지 못하는 이유를 분석하기 위해 LLDB(Low Level Debugger)로 실패한 요청의 SELECT를 추적해보기로 했습니다.

인덱스 탐색

해당 쿼리에서는 세컨더리 인덱스(Secondary Index)만으로 모든 프로젝션(Projection)을 구성할 수 없으므로 추가적으로 PK(Primary Key) Lookup이 수행되는데요. 그렇기에 이 PK Lookup을 수행하는 Row_sel_get_clust_rec_for_mysql::operator()에 중단점을 잡았습니다.

1dberr_t Row_sel_get_clust_rec_for_mysql::operator()(...) {
2  row_build_row_ref_in_tuple(prebuilt->clust_ref, rec, sec_index, *offsets);
3
4  clust_index = sec_index->table->first_index();
5  prebuilt->clust_pcur->open_no_init(clust_index, prebuilt->clust_ref, PAGE_CUR_LE, BTR_SEARCH_LEAF, 0, mtr, UT_LOCATION_HERE);
6
7  clust_rec = prebuilt->clust_pcur->get_rec();
8  ...
9}

여기서 저희가 추적해볼 값은 clust_rec인데요. clust_rec는 기본 키로 탐색한 클러스터드 인덱스(Clustered Index) 레코드의 주소입니다.

> frame variable clust_rec
(const rec_t *) clust_rec = 0x00000001130400f6

이 주소가 찾으려던 레코드인지 확인하기 위해 메모리 덤프로 해당 주소의 데이터를 읽어보겠습니다.

> memory read --format bytes --count 16 --num-per-line 16 clust_rec
0x1130400f6: 34 86 9d a9 c4 93 11 f1 a4 08 fd 45 84 84 c7 86

현재 테이블에서 16바이트 크기의 기본 키 BINARY(16)에 해당하는 첫 16바이트만 읽었습니다.

이때 이전 요청에서 웹사이트를 생성할때 사용한 INSERT 쿼리는 다음과 같았는데요.

1INSERT INTO website (id, domain, favicon_url)
2VALUES (
3    X'34869da9c49311f1a408fd458484c786',
4    'earlgrey02.com',
5    NULL
6)
7ON DUPLICATE KEY UPDATE favicon_url = NULL;

해당 쿼리로 삽입된 레코드의 기본 키와 현재 조회한 레코드의 기본 키가 일치합니다. 즉, 인덱스 탐색에는 문제가 없었다는 것을 확인할 수 있었습니다.

가시성 검사

레코드를 찾은 다음에는 해당 레코드의 버전(Version)을 현재 트랜잭션에서 읽을 수 있는지 확인하는 가시성 검사를 수행하는데요. 이러한 가시성 검사는 lock_clust_rec_cons_read_sees()에서 수행합니다.

1dberr_t Row_sel_get_clust_rec_for_mysql::operator()(...) {
2  if (trx->isolation_level > TRX_ISO_READ_UNCOMMITTED && !lock_clust_rec_cons_read_sees(clust_rec, clust_index, *offsets, trx_get_read_view(trx))) {
3    err = row_sel_build_prev_vers_for_mysql(trx->read_view, clust_index, prebuilt, clust_rec, offsets, offset_heap, &old_vers, vrow, mtr, lob_undo);
4
5    if (old_vers == nullptr) {
6      goto err_exit;
7    }
8  }
9  ...
10}

만약 가시성 검사를 통과하지 못하면 row_sel_build_prev_vers_for_mysql()가 언두 로그(Undo Log)에서 읽을 수 있는 이전 버전을 찾아 old_vers에 저장합니다.

> expression -- lock_clust_rec_cons_read_sees(clust_rec, clust_index, *offsets, trx->read_view)
(bool) $2 = false

실패한 요청에서는 가시성 검사를 통과하지 못했었는데요.

> frame variable old_vers
(rec_t *) old_vers = 0x0000000000000000

또한 찾은 레코드는 이전 버전이 존재하지 않아 old_vers가 nullptr이 되는 것을 확인할 수 있었습니다. 결국 찾은 레코드는 가시성 검사를 통과하지 못했고, 읽을 수 있는 이전 버전의 레코드도 없어 SELECT가 어떠한 레코드도 반환하지 못한 것이었습니다.

문제 해결

문제를 해결하기 위해선 Upsert 직후 조회가 과거의 읽기 뷰(Read View) 때문에 저장된 레코드를 제외하지 않도록 해야하는데요.

If you want to see the “freshest” state of the database, use either the READ COMMITTED isolation level or a locking read
MySQL 공식 문서

공식 문서에서 가장 최신 상태를 조회하기 위해 권장하는 두 가지 방법을 검토했습니다.

첫 번째 방법: 격리 수준 변경

1@Transactional(isolation = Isolation.READ_COMMITTED)
2fun createHistory(
3    userId: UUID,
4    command: CreateHistoryCommand
5): CreateHistoryResult = ...

첫 번째 방법은 격리 수준을 REPEATABLE READ보다 한 단계 낮은 READ COMMITTED로 변경하는 방법입니다.

If the transaction isolation level is REPEATABLE READ, all consistent reads within the same transaction read the snapshot established by the first such read in that transaction
MySQL 공식 문서

REPEATBALE READ에서는 첫 번째 일관된 읽기(Consitent Read)의 읽기 뷰를 이후 조회에서도 재사용합니다. 그렇기에 레코드를 삽입한 이전 트랜잭션이 커밋된 이후에도 해당 레코드를 읽을 수 없었던 것인데요.

With READ COMMITTED isolation level, each consistent read within a transaction sets and reads its own fresh snapshot.
MySQL 공식 문서

이와 달리 READ COMMITTED에서는 일관된 읽기마다 새로운 읽기 뷰를 만듭니다. 따라서 Upsert 이후의 SELECT는 이전 트랜잭션에서 삽입한 레코드를 읽을 수 있습니다.

다만 격리 수준은 트랜잭션 단위로 적용되기 때문에 해당 트랜잭션의 다른 쿼리에도 영향을 줄 가능성이 있습니다. 그렇기에 단순히 Upsert에서의 조회 하나를 위해 격리 수준을 바꾸는 것은 영향 범위가 클 수 있다고 생각해 다른 방법을 고려하기로 했습니다.

두 번째 방법: Locking Read 사용

1override fun upsertByDomain(website: Website): Website {
2    ...
3
4    return dsl
5        .selectFrom(WEBSITE)
6        .where(WEBSITE.DOMAIN.equal(website.domain))
7        .forShare()
8        .fetchSingleInto()
9}

두 번째 방법은 SELECT ... FOR SHARE와 같은 잠금 읽기(Locking Read)를 사용하는 방법인데요.

1dberr_t Row_sel_get_clust_rec_for_mysql::operator()(...) {
2  if (prebuilt->select_lock_type != LOCK_NONE) {
3    ...
4  } else {
5    if (trx->isolation_level > TRX_ISO_READ_UNCOMMITTED && !lock_clust_rec_cons_read_sees(clust_rec, clust_index, *offsets, trx_get_read_view(trx))) {
6      err = row_sel_build_prev_vers_for_mysql(trx->read_view, clust_index, prebuilt, clust_rec, offsets, offset_heap, &old_vers, vrow, mtr, lob_undo);
7      ...
8    }
9  }
10  ...
11}

잠금 읽기는 가시성 검사를 수행하지 않기 때문에 항상 최신 버전의 레코드를 조회할 수 있습니다.

다만 잠금 읽기는 락을 사용하므로 락 경합으로 인한 성능 감소 가능성을 생각해야 하는데요. 현재 격리 수준인 REPEATABLE READ 기준 잠금 읽기는 검색 조건에 따라 레코드뿐만 아니라 주변의 갭(Gap)에도 락을 겁니다.

For a unique index with a unique search condition, InnoDB locks only the index record found, not the gap before it.
MySQL 공식 문서

그러나 유니크 인덱스를 사용하는 경우에는 찾은 레코드에는 다른 락을 걸지 않는데요. 앞서 사용한 SELECT는 유니크 인덱스인 uk_website_domain을 사용하므로 이 조건에 해당합니다. 이때 INSERT ... ON DUPLICATE KEY UPDATE에서는 어떤 경우에도 반드시 레코드 락이 걸립니다. 그러므로 SELECT ... FOR SHARE가 추가적인 락을 잡는다고 할 수 없습니다.

결론적으로 잠금 읽기를 사용하는 방법이 격리 수준을 변경하는 방법보다 적은 영향 범위를 가지기에 해당 방법을 도입하기로 했습니다.

회귀 테스트

서로 다른 사용자 100명이 동일한 웹사이트에 대해 기록 생성 요청을 동시에 보내는 테스트로 변경 전후의 성능을 비교했습니다. API를 재시작하고 정상 요청으로 워밍업한 뒤, 방문 데이터와 캐시를 비우고 측정했습니다.

변경 후에는 큰 성능 변화 없이 모든 요청이 정상적으로 처리되는 것을 확인할 수 있었습니다.