{"id":"IL-0441","org":"ZOZO","date":"2021-03-04","docs":[],"title":{"en":"A ZOZO SQL Server database stalled and applications hit timeout storms whenever batch executions peaked in sales","ko":"세일 이벤트 때 SQL Server 의 초당 배치 실행 수가 임계값을 넘으면 쿼리가 밀려 애플리케이션 타임아웃 오류가 쏟아졌다"},"domain":["database"],"impact":{"scope":"Applications using one SQL Server database got many timeout errors during traffic peaks","users":"unknown","region":"unknown"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":{"en":"When the root cause of a failure cannot be found, choosing among the things observed during the failure those that can be removed or reduced, and acting on them, can still create a state in which the failure no longer happens.","ko":"근본 원인을 찾지 못한 장애에서도 장애 중에 관찰된 현상 가운데 없애거나 줄일 수 있는 것을 골라 대책을 세우면 장애가 나지 않는 상태를 만들 수 있었다. 조사는 특이하게 변한 지표를 먼저 보고 가설을 세운 뒤 DMV 와 확장 이벤트로 파고들고, 장애 앞뒤 몇 초의 변화를 자세히 보는 순서로 했다."},"related":[],"sources":[{"url":"https://techblog.zozo.com/entry/sqlserver-incident-management-2020","kind":"blog","archived":"https://web.archive.org/web/20260520033718/https://techblog.zozo.com/entry/sqlserver-incident-management-2020"}],"summary":{"en":"ZOZO investigated the failure with three sources: SQL Server metrics from Performance Monitor, the blocked_process_report extended event, and DMV (dynamic management view) data saved to a table every minute. The metrics only showed that queries piled up for some reason until the worker threads ran out and timeouts followed. Possible reasons considered were SOS_SCHEDULER_YIELD waits from high CPU, non-page latch contention, and long locks on a busy area causing blocking. The latch data suggested that ACCESS_METHODS_HOBT_VIRTUAL_ROOT waits might come from many last-page inserts into one table, and that ACCESS_METHODS_ACCESSOR_CACHE waits rise with compilations. ZOZO did not find a definite root cause.\n\nInstead, ZOZO looked for things observed during the failure that could be removed or reduced. When the failure happened again on another day, counting blocked_process_report events by waitresource showed blocking caused by waits for the compilation of specific stored procedures, so ZOZO fixed the plan guides of those four stored procedures. Compilations and recompilations were also reduced: the sql_statement_recompile extended event showed that the recompile_cause of most recompilations was \"Statistics changed\". ZOZO listed the tables whose statistics were updated during the failure window, disabled automatic statistics updates on them only for periods of expected high traffic with `UPDATE STATISTICS tablename WITH NORECOMPUTE`, and enabled them again with `UPDATE STATISTICS tablename` once traffic calmed down. Because plan cache evictions are controlled by SQL Server's memory management, ZOZO compressed the large indexes held in the data cache as a best-effort step.\n\nAfter these measures the failure stopped. With the same rise in batch executions, queries no longer piled up, connections stayed low, errors disappeared, peak CPU fell from close to 100% to about 60%, compilations and recompilations dropped clearly, and no lock contention was seen even at the highest batch rate. ZOZO's hypothesis for the drop in compilations is that compression shrank the data cache, which stabilised the plan cache.","ko":"ZOZO 는 서비스 일부에 SQL Server 를 쓴다. 2020년 중반부터 한 기능을 맡은 DB 에서 초당 배치 실행 수가 일정 임계값을 넘으면 쿼리가 밀리고 워커 스레드가 바닥나 애플리케이션에 타임아웃 오류가 쏟아졌다. 팀은 성능 모니터의 SQL Server 지표, 확장 이벤트 blocked_process_report, 1분마다 테이블에 저장해 둔 DMV 데이터를 가지고 사내 조사 흐름도를 따라 조사했다. 오류가 나기 시작할 때 Page Latch, Non-Page Latch, 블로킹 순으로 변화가 나타났지만 근본 원인은 끝내 찾지 못했다.\n\n팀은 장애 중에 관찰된 현상 가운데 없애거나 줄일 수 있는 것을 고르는 방식으로 대책을 정했다. 다른 날 같은 장애가 났을 때 blocked_process_report 의 waitresource 별 이벤트 수를 뽑아 보니, 특정 스토어드 프로시저의 컴파일 대기가 블로킹을 일으키고 있었다. 팀은 이 스토어드 프로시저 네 개의 실행 계획을 플랜 가이드로 고정했다. sql_statement_recompile 이벤트의 recompile_cause 를 보니 재컴파일 대부분이 Statistics changed 였다. 그래서 장애 시간대에 통계가 업데이트된 테이블들의 통계 자동 업데이트를 트래픽이 늘 시간대에만 끄고, 트래픽이 가라앉으면 다시 켰다. 플랜 캐시 축출은 SQL Server 가 메모리를 관리하므로 직접 제어할 수 없었다. 그래서 팀은 메모리에 올라간 큰 인덱스를 압축했다.\n\n대책을 적용한 뒤로는 같은 수준의 배치 실행 수에서도 쿼리가 밀리지 않았다. 커넥션 증가가 눈에 띄게 줄었고 오류가 사라졌다. CPU 사용률 피크는 100% 가까이에서 60% 정도로 내려갔다. 컴파일 수와 재컴파일 수가 크게 줄었고, 배치 실행 수가 가장 많을 때도 락 경합이 보이지 않았다."},"trigger":{"en":"Traffic increases during sales and lucky-bag launches pushed batch executions per second on the database above a threshold.","ko":"세일 이벤트나 럭키백 판매 이벤트로 트래픽이 늘어 초당 배치 실행 수가 일정 임계값을 넘었다."},"severity":"unknown","symptoms":["intermittent-timeouts","database-overloaded","lock-contention"],"timeline":{"detected_after":null,"resolved_after":null},"date_kind":"published","detection":null,"components":["database"],"root_cause":"unknown","remediation":[{"text":{"en":"Fixed the plan guides of the four stored procedures whose compilation waits caused blocking","ko":"컴파일 대기로 블로킹을 일으킨 스토어드 프로시저 네 개의 실행 계획을 플랜 가이드로 고정했다."}},{"text":{"en":"Disabled automatic statistics updates on the affected tables during periods of expected high traffic","ko":"장애 시간대에 통계가 한 번 이상 업데이트된 테이블을 뽑고, 트래픽이 늘 것으로 보이는 시간대에만 UPDATE STATISTICS tablename WITH NORECOMPUTE 로 그 테이블들의 통계 자동 업데이트를 껐다."}},{"text":{"en":"Enabled automatic statistics updates again once traffic calmed down","ko":"트래픽이 가라앉으면 WITH NORECOMPUTE 없이 UPDATE STATISTICS tablename 을 실행해 통계 자동 업데이트를 다시 켰다."}},{"text":{"en":"Compressed the large indexes held in the data cache to use memory more efficiently","ko":"플랜 캐시 축출을 줄이려고 메모리에 올라간 데이터 캐시 가운데 용량이 큰 인덱스를 압축해 메모리를 더 효율적으로 쓰게 했다."}}],"action_items":[],"contributing":[],"recurrence_of":null,"symptoms_text":{"en":"From around mid-2020, a SQL Server database behind one ZOZO feature made the applications throw many timeout errors whenever batch executions per second passed a certain threshold.\n\nTraffic rises at events such as sales and lucky-bag (fukubukuro) launches. A batch in SQL Server is a group of one or more queries. At the moment the errors began, batch executions per second dropped sharply while total batch execution time rose steeply, so each query was taking much longer.\n\nThe Performance Monitor metrics for SQL Server showed CPU usage close to 100% at the peak, driven mainly by batches using 20 to 100 msec of CPU in Batch Resp Statistics. They also showed blocking, errors on the SQL Server side, a spike of non-page latch waits early in the failure, compilations rising with batch executions, more queries granted workspace memory, and many waits to obtain a worker thread, which suggested the worker threads had run out.\n\nLooking at a shorter time window around the start of the errors, CPU usage fell when the Attention events appeared, so CPU was unlikely to be the cause. The first changes were Page Latch, then Non-Page Latch, then blocking. In the blocked_process_report extended event, the first blocking event was recorded about 15 seconds after the failure began, because the event is only written after blocking passes a threshold; the first blocker was a background process that was itself waiting on a latch of type ACCESS_METHODS_HOBT_VIRTUAL_ROOT, and what it was doing could not be found. The DMV data showed no CPU-heavy query worth tuning; the largest total latch waits were ACCESS_METHODS_ACCESSOR_CACHE, then BUFFER, then ACCESS_METHODS_HOBT_VIRTUAL_ROOT, and apart from the secondary THREADPOOL wait most waiting time was non-page latches, page latches and locks.","ko":"2020년 중반부터 세일 이벤트처럼 트래픽이 몰릴 때, 한 기능을 맡은 SQL Server DB 의 초당 배치 실행 수가 일정 임계값을 넘으면 애플리케이션에서 타임아웃 오류가 많이 났다. 여기서 배치는 SQL Server 에서 하나 이상의 쿼리를 묶은 단위다.\n\n타임아웃 오류가 쏟아지기 시작한 순간 초당 배치 실행 수가 급격히 떨어지고 배치 총 실행 시간이 급격히 늘었다. 쿼리 하나의 실행 시간이 크게 길어졌다는 뜻이었다.\n\n성능 모니터에서 CPU 사용률은 피크 때 100% 가까이 올랐다. Batch Resp Statistics 를 보면 CPU 사용 시간이 20msec 에서 100msec 사이인 배치가 CPU 사용률을 올린 주된 원인이었다. 블로킹과 SQL Server 쪽 오류도 보였다. 장애 초기에는 비페이지 래치 대기가 튀었다. 배치 실행 수와 함께 컴파일 수가 늘었고, 작업 영역 메모리를 할당받은 쿼리 수도 늘었다. 워커 스레드를 기다리는 일이 많아 워커 스레드가 바닥났을 가능성이 컸다.\n\n팀은 쿼리가 밀린 이유로 세 가지를 의심했다. CPU 사용률이 치솟아 생긴 SOS_SCHEDULER_YIELD 대기, 비페이지 래치 경합, 접근이 몰리는 곳에 락이 오래 걸려 생긴 블로킹이었다. 오류가 나기 시작한 지점을 짧은 시간 단위로 다시 보니 Attention 이벤트가 난 때 CPU 사용률은 오히려 내려가 있었다. 그래서 CPU 는 원인으로 보기 어려웠다. 오류 앞뒤로 Page Latch 가 먼저 나타났고, 이어서 Non-Page Latch, 그다음 블로킹이 나타났다.\n\n확장 이벤트 blocked_process_report 에는 장애 시작 15초쯤 뒤에 첫 블로킹 이벤트가 찍혔다. 첫 블로커는 background 프로세스였고, 이 프로세스도 ACCESS_METHODS_HOBT_VIRTUAL_ROOT 래치를 기다리고 있었다. 확장 이벤트는 정해진 시간 넘게 이어진 블로킹만 기록하므로 성능 모니터보다 늦게 찍혔다. 첫 블로커가 무슨 일을 하고 있었는지는 알 수 없었다.\n\nDMV 로 파고들어도 CPU 부하 면에서 튜닝할 쿼리는 나오지 않았다. 래치 총 대기 시간은 ACCESS_METHODS_ACCESSOR_CACHE, BUFFER, ACCESS_METHODS_HOBT_VIRTUAL_ROOT 순으로 컸다. 대기 유형은 이차적인 THREADPOOL 을 빼면 비페이지 래치, 페이지 래치, 락이 대부분이었다. 팀은 끝내 근본 원인을 찾지 못했다."},"updated_at":"2026-11-14T12:34:09.055958Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0441","org_slug":"zozo"}