17화 · 평균은 거짓말을 한다

7월 1일 월요일, 지난주에 낸 결론을 들고 출근했다. 문제는 CPU를 먹는 일의 양이고, 락은 부차적이다. 오늘은 처음으로 시간 축을 펼친다. 그리고 지난주 결론이 틀린 칸에서 나온 게 아니라 그 질문에 답할 수 없는 칸에서 나왔다는 것을 직접 재서 확인한다.

오전 9시 05분

매주 하던 대로 리비전 폴더부터 열었다. 이번 주에도 고칠 조각은 없었다. 대신 지난주에 쓴 T5-001을 열었다. 맨 아래 5번 칸에 내가 적어 둔 한 줄이 있었다. 【17화】 구간 안의 시간 분포. 이 리포트로 말할 수 없는 것: enq: TX 853번(599초)이 언제였나, 누가 그 행을 쥐었나.

말할 수 없다고 적어 놓고는, 그 위 8번 칸에서 말을 해 버렸다. 4. 행 락 5.5%, 부차적.

메신저에는 답장이 먼저 와 있었다.

조민우  08:47
T5-001 받았어요. "락은 한 시간의 5.5%, 부차적"이라고 쓰셨던데요.
6/17 10시 반에는 정말로 화면이 다 멈췄어요. 저희 팀 넷이 동시에 등록 버튼 누르고 기다렸고,
5분쯤 지나니까 한꺼번에 넘어갔어요. 그게 부차적인 건가요?

박팀장  09:02
금요일 회의 결과 — CPU 증설은 보류. "늘려도 최대 4분의 1" 이 통했습니다.
등급별 매출 화면은 개발팀이 따로 보기로 했고요.
그리고 부탁 하나. 인수한 버거 프랜차이즈 쪽 POS DB 가 오전마다 느리답니다.
그쪽 IT 에서 접속 계정을 보내왔으니, 거기도 AWR 한 장 뽑아서 봐 주세요.

두 번째로 온 박팀장의 메시지는 오후로 미뤘다. 첫 번째 메시지, 조민우 씨의 "그게 부차적인 건가요"가 오래 머리에 남았다.

오전 9시 20분 — 첫 번째 답

"근거는 칸마다 다 붙였어요." 커피를 들고 온 선배에게 내가 먼저 말을 꺼냈다. "853번 기다렸고, 한 번에 평균 702밀리초예요. 1초도 안 되는 기다림으로 화면이 5분씩 멈추지는 않아요. 조민우 씨 화면이 느렸던 건 CPU 때문일 거예요. 그 한 시간 내내 CPU 차례를 기다린 게 23.8%였으니까요."

"평균 702밀리초짜리 기다림을 실제로 한 번이라도 겪은 사람이 있어?"

대답을 못 했다. 평균이 702라고 해서 702짜리 기다림이 있었다는 뜻은 아니었다.

"하나 더." 선배가 의자를 끌어왔다. "그 5.5%는 뭘 기준으로 잰 5.5%야?"

"한 시간 DB Time이요. 181분 중에 599초."

"그 599초가 한 시간에 고르게 흩어져 있었으면 1분에 몇 초야?"

"…10초요."

"5분에 몰려 있었으면?"

계산해 봤다. 599를 300으로 나누면 2다. "1분에 120초요. 두 사람이 5분 내내 기다린 셈이에요."

"둘 중 어느 쪽이었는지 리포트 한 장으로 알 수 있었어?"

"…아뇨."

"그럼 지난주에 '부차적'이라고 쓰면 안 됐지. '모른다'라고 썼어야 해." 선배는 목소리를 높이지 않았다. "칸마다 근거를 붙인 건 잘했어. 틀린 근거도 하나도 없고. 전부 평균이었을 뿐이야. 평균은 '얼마나'는 알려 주는데 '언제'는 안 알려 줘. 조민우 씨가 물은 건 '언제'였고."

"그럼 언제였는지는 어떻게 알아요? 지난주는 이미 지나갔잖아요."

"지난주에 내가 덮어 둔 게 세 개 있었지. 발생기의 분별 기록, 리포트 뒤쪽의 ASH 절, 그리고 ADDM. 오늘 그걸 전부 열 거야." 선배가 시계를 봤다. "서둘러야 해. 지난주 그 한 시간 기록은 보존 기간이 8일이야. 오늘이 7일째고."

오전 9시 40분 — 방재실의 녹화기

"따라와. 지난주에 갔던 그 방이야."

엘리베이터는 B2에서 멈췄다. 방재실 겸 관리실이었다. 벽 한쪽을 채운 계기판도, 책상 위 검침 대장도 지난주 그대로였다. 달라진 건 선배가 계기판 옆, 모니터 여섯 대가 붙은 벽으로 곧장 갔다는 점이었다. 당직 주임이 의자를 돌렸다.

"녹화기 보러 오셨어요?"

"지난달 그 엘리베이터 얘기 좀 해 주세요." 선배가 말했다.

주임이 웃었다. "그거요. 7층에서 민원이 올라왔어요. 엘리베이터가 5분 동안 안 온다고요. 처음엔 대장부터 봤죠. 그 시간 엘리베이터 동력 검침은 평소보다 오히려 조금 적었어요. 대장만 보면 조용한 한 시간이에요."

"그런데요?"

"녹화기를 돌려 봤죠." 주임이 화면 하나를 가리켰다. "10시 31분부터 5분 동안 3층, 5층, 7층 엘리베이터 앞에 사람들이 서 있었어요. 엘리베이터는 8층에 문이 열린 채로 서 있었고요. 이삿짐 업체가 짐을 싣느라 문을 잡고 있었던 거예요. 엘리베이터가 서 있었으니 전기는 덜 쓴 거고."

"문을 잡은 사람은 화면에 있었어요?"

"그게 웃긴 부분이에요. 엘리베이터 안엔 카메라가 없거든요. 8층 복도 카메라에 짐 들고 들어가는 거랑 나오는 것만 찍혔어요. 그 5분 동안 문 잡고 서 있던 사람은 한 장에도 안 나와요. 화면에는 줄 선 사람들만 있죠. 다들 8층 표시등만 쳐다보고 있고요."

선배가 나를 돌아봤다. 녹화기 화면 아래에 적힌 글씨가 눈에 들어왔다. 1초 1장 · 동작 감지 녹화 · 원본 24시간 덮어쓰기 · 보관본 10장에 1장 · 8일.

"동작 감지요?"

"움직이는 게 있을 때만 찍어요. 빈 복도까지 다 찍으면 하드가 못 버티니까요. 그래도 하드가 작아서 원본은 하루쯤 지나면 덮어써요. 대신 열 장에 한 장씩 떼어서 따로 일주일 넘게 보관해요."

방재실을 나와 엘리베이터를 기다리며 선배가 말했다.

"저게 ASH야. Active Session History. 오라클이 1초에 한 번씩 그 순간 DB 안에서 일하고 있거나 기다리고 있는 세션만 사진을 찍어. 쉬는 세션은 안 찍고. 동작 감지처럼 말이야. 원본은 메모리에 두는데, 고리처럼 돌면서 오래된 걸 덮어써. 열 장에 한 장은 AWR 스냅샷을 찍을 때 디스크로 떼어 내고, 그건 AWR 보존 기간만큼 남아. 지난주 그 한 시간은 이제 디스크 쪽에만 있어."

"사진으로 시간을 어떻게 재요?"

"줄 선 사람을 장마다 세서 더하면 돼. 1초에 한 장이니까 사진 한 장에 찍힌 사람 하나가 1초야. 세 사람이 60장 내내 찍혀 있으면 180초, 그 1분 동안 DB Time이 180초인 거지. 열 장에 한 장만 남긴 보관본이면 한 장이 10초고." 선배가 엘리베이터에 올랐다. "그리고 주임님 얘기 마지막 대목 기억해 둬. 문을 잡은 사람은 녹화에 없다."

ASH가 무엇을, 얼마나 자주, 어디에 남기는지와 표본 수학 → 2_파고들기.md §1 · §2

오전 10시 10분 — 열 장에 한 장

지난주 그 한 시간의 보관본은 DBA_HIST_ACTIVE_SESS_HISTORY에 있었다. 런 번호도 스냅샷 번호도 따로 적어 둘 필요가 없었다. 발생기가 T_LD_RUN에 남긴 시작 시각으로 찾으면 됐다. 표본을 런 시작부터의 초 ÷ 60으로 1분 칸에 나눠 담는 쿼리를 짰다. 부하 발생기 세션(MODULE = LOAD_DRIVER)만 골라 상태별로 셌다.

"운영 시계로 읽어." 선배가 옆 칸을 가리켰다. "지난주 T7에 내가 적어 둔 약속대로, 런 +1분이 10시야."

MIN_NO CLOCK   SAMPLES   AAS   ON_CPU  CPU_WAIT  ENQ_TX  OTHER
    28 10:27        18     3       12         3       0      3
    29 10:28        18     3       16         1       0      1
    30 10:29        18     3       11         6       0      1
    31 10:30        12     2        0         0      12      0
    32 10:31        12     2        0         0      12      0
    33 10:32        12     2        0         0      12      0
    34 10:33        12     2        0         0      12      0
    35 10:34        12     2        0         0      12      0
    36 10:35        18     3       11         6       0      1
    37 10:36        18     3       16         0       0      2

한 시간 내내 18, 18, 18이었다. 1분에 표본 시각이 6번이고 세 세션이 쉬지 않으니 18이다. 그런데 10시 30분부터 다섯 줄이 12였다. 그 12개는 전부 enq: TX였다. CPU를 쓰는 표본은 0이었다.

"…10시 30분부터 10시 35분이요."

조민우 씨가 말한 "10시 반쯤 몇 분"이었다. 정확히 5분이었다.

"같은 표본을 칸만 바꿔서 세 봐. 5분 칸 12개, 그리고 한 시간 한 칸."

WIN          SAMPLES   AAS   CPU_PCT   CPU_WAIT_PCT   ENQ_TX_PCT
10:20-10:25       90     3      63.3           23.3            0
10:25-10:30       90     3      67.8           24.4            0
10:30-10:35       60     2         0              0          100
10:35-10:40       90     3        60           25.6            0
10:40-10:45       90     3      78.9             10            0
 …
한 칸 (60분)    1,050  2.92      63.8           19.6          5.7

같은 표본 1,050개를	`enq: TX`의 몫	평균 활성 세션	CPU의 몫
한 시간 한 칸으로 세면	5.7%	2.92	63.8%
10:30~10:35 칸으로 세면	100%	2.00	0%

표를 한참 들여다봤다. 5.7%와 100%. 표본도 쿼리도 같았다. 다른 것은 GROUP BY의 칸 하나뿐이었다.

"그 5분 동안 DB는 뭘 했어?" 선배가 물었다.

"…아무것도요. 두 세션이 줄을 섰고, CPU는 아무도 안 썼어요."

"지난주 네 결론 1번이 뭐였지?"

이 한 시간은 오전의 9분과 같은 모양이다. 문제는 CPU를 먹는 일의 양이다. 3번 끝에 덧붙인 한 줄도 있었다. DB CPU가 오전(2.01)보다 조금 낮은 1.84인 것도 그 기다림만큼이다.

계산기를 두드렸다. 2.01 × 55 ÷ 60 = 1.84.

"그 한 줄은 맞았네요. 55분 동안 꽉 쓰고 5분 동안 0을 쓴 평균이 1.84예요." 내가 말했다. "근데 저는 그걸 '조금 덜 바빴다'로 읽었어요. 실제로는 5분 동안 완전히 멈춰 있었던 건데."

"엘리베이터가 서 있었으니 전기를 덜 쓴 거지. 대장에는 조용한 한 시간으로 적히고." 선배가 말했다.

표본 수학

"표본 60개가 진짜 599초야? 재 봐." 선배가 말했다. "녹화기 보관본은 열 장에 한 장이라고 했지. 표본 하나가 10초를 대신한다는 걸 네 눈으로 확인해 봐."

AWR이 같은 한 시간 동안 잰 시간과 나란히 놓았다. 대상은 이 PDB의 포그라운드 세션뿐이다.

WHAT                            ASH_SAMPLES   ASH_SEC (× 10)   AWR_SEC
DB time (all samples)                 1,050          10,500    10,504.5
DB CPU (ON CPU)                         668           6,680     6,624.2
enq: TX - row lock contention            60             600       599.0

10,500과 10,504.5, 600과 599.0. 1분에 6장만 남긴 사진을 세었을 뿐인데, 오라클이 마이크로초 단위로 잰 시간과 거의 똑같았다.

"이게 ASH의 전부야." 선배가 말했다. "표본 하나 ≈ DB Time 한 칸. 메모리 쪽이면 1초, 디스크 쪽이면 10초야. 이걸로 뭐든 세면 돼. 분 단위로, 5분 단위로, 세션별로, SQL별로. AWR은 한 시간에 숫자 하나를 주지만, ASH로는 그 숫자를 네가 원하는 칸으로 다시 쪼갤 수 있어."

표본 수학과 그 한계, 분 칸과 5분 창으로 자르는 쿼리 → 2_파고들기.md §2 · §4

오전 10시 40분 — 문을 잡은 사람

"그럼 누가 문을 잡고 있었는지 보자."

기다린 표본에는 칸이 하나 더 있었다. BLOCKING_SESSION과 BLOCKING_SESSION_SERIAL#. 12화에서 V$SESSION으로 블로킹 트리를 그릴 때 쓰던 바로 그 칸이 표본마다 붙어 있었다.

ACTION     SQL_ID         BLK_SID  BLK_SERIAL  BLOCKER_IS   OBJ             SAMPLES  WAITERS
N1 hotfix  9ph8h7j79zbh7      175       62822  session 1    T_STLM_NUM_LD        60        2

9ph8h7j79zbh7은 SELECT LAST_NO + 1 FROM T_STLM_NUM_LD WHERE NUM_TP = 'STLM' FOR UPDATE, 채번 테이블을 잡는 문장이었다. 기다린 두 세션은 60장 모두 같은 세션 하나(SID 175, SERIAL# 62822)에게 막혀 있었다. 발생기의 T_LD_SESS에서 그 번호를 찾아보니 지난주 런의 세션 1이었다.

"175는 그 5분 동안 뭘 하고 있었어요?"

"그 세션의 표본을 찾아봐."

결과는 두 줄뿐이었다. 폭발 전 186장, 폭발 뒤 156장. Q1, Q2, Q3, P1, N1을 번갈아 돌리는 평범한 사진들이었다. 폭발 중에는 줄 자체가 없었다. 0장이었다.

"…문을 잡은 사람이 녹화에 없어요."

"쉬고 있었으니까. ASH는 활성 상태가 아닌 세션은 안 찍어." 선배가 지난주 ASH 리포트의 한 칸을 띄웠다. 같은 5분을 ASH_REPORT_TEXT로 뽑은 것이었다.

Top Blocking Sessions
 Blocking Sid (Inst) % Activity Event Caused                      % Event
 User                 Program                         # Samples Active     XIDs
   175,62822(     1)     100.00 enq: TX - row lock contention      100.00
 ** NOT FOUND **      BLOCKING SESSION NOT FOUND          0/30 [  0%]       N/A

BLOCKING SESSION NOT FOUND. 오라클이 직접 그렇게 적어 놓았다. 막은 세션의 이름은 막힌 쪽 사진에만 남는다. 줄 선 사람들이 쳐다보던 8층 표시등처럼.

"그래서 12화에서 블로킹 트리를 '지금' 찍으라고 한 거야. 장애 중에 V$SESSION으로 찍으면 뿌리가 보여. 무슨 이벤트로 쉬고 있는지, 직전에 뭘 했는지(PREV_SQL_ID)까지. 다 지나간 다음에 ASH로 보면 뿌리는 이름만 남아." 선배가 말했다. "그러면 그 이름을 들고 다른 데를 뒤져야 해. 그 세션이 일하던 때의 표본, 애플리케이션 기록, 배치 로그 같은 데."

지난주에 일부러 읽지 않은 기록 하나가 떠올랐다. 16화에서 남겨 둔 의문도 하나 있었다. "RUN_SESSION(1)만 다른 둘보다 Elapsed가 300초 짧았어요."

"5분이 300초야. 그 5분 동안 세션 1은 DB 안에서 아무것도 안 했으니 DB Time에서 빠진 거지." 선배가 발생기 기록을 열었다. 16화에서 닫아 두었던 그 창이었다.

MIN_NO    Q1     Q2     Q4    N1  N1_HOTFIX  N1_HOLD   P1
    30  10990   1868  14595  5152                       349
    31     22      5     42           12          6
    32     16      3     19           10          6       2
    33     15      1     20            8          6
    34     20      4     19            9          6
    35     31      3     37            8          6       2
    36  11078   1945  14715  5051                       367

N1 hold     execs  30   avg 10,004.67 ms
N1 hotfix   execs  47   avg 12,744.68 ms

1분에 1만 1천 번 돌던 Q1이 15~31번으로 줄었다. N1 hold는 1분에 6번, 한 번에 10초였다. 세션 1이 번호 행을 10초씩 쥐었다 놓기를 30번 되풀이한 것이다. 그사이 N1 hotfix(채번 테이블을 FOR UPDATE로 잡고 번호를 받는 판)는 47번 돌면서 한 번에 평균 12.7초씩 기다렸다.

"이게 지난주 그 한 시간에 내가 넣어 둔 거야." 선배가 T7의 명령 칸을 열었다. 내가 열어 보지 않았던 그 칸이었다. SPIKE_AT=31 SPIKE_LEN=5 SPIKE_KIND=LOCK HOLD_SEC=10. "12화 장애를 그대로 옮겼어. 번호 행을 쥔 세션 하나와, FOR UPDATE로 번호를 받는 화면 둘. 강도현 씨의 2019-03-14 커밋 로그에도 나오는 모양이야. 보정 배치가 도는 동안 정산 등록 화면이 대기함. 철회."

12화의 총무팀이 떠올랐다. 김대리가 발번 대장을 들고 회의실에 들어가 있던 7분 동안, 데스크 앞에는 줄 선 사람들만 있었고 회의실 안은 아무도 보지 못했다. 오늘 본 녹화기도 같은 장면을 담고 있었다.

"왜 하필 10시 반에 5분을…"

"조민우 씨가 그날 아침 '10시 반쯤 몇 분'이라고 했잖아. 그 말을 듣고 12화가 떠올랐어. 그 말이 맞다면 그 한 시간은 이런 모양이었을 거라고 봤지. 그래서 그 모양을 넣어 두고, 너한테 리포트 한 장으로 결론을 내 보라고 한 거야."

"그리고 저는 '부차적'이라고 썼고요."

"칸마다 근거까지 붙여서." 선배가 고개를 끄덕였다. "오늘 네가 배울 게 그거야. 운영팀이 가진 건 리포트 한 장이 전부야. 그 한 장에 '락은 5%'라고 나와도, 그걸로 현업의 '5분 멈췄다'를 기각하면 안 된다는 것."

"운영 DB의 6/17은요? 진짜 그날은요?"

"운영팀에 물어봤어. 운영 AWR도 보존 기간이 8일 그대로야. 6/17 표본은 6/25에 지워졌어." 선배가 말했다. "지난주 월요일에는 남아 있었고."

지난주 오후 6시가 떠올랐다. 조민우 씨가 "10시 반 건은요?"라고 물었을 때 나는 손을 멈췄다. 그때 리포트 뒤쪽을 열어 봤다면 운영 DB의 그 5분을 볼 수 있었다.

ASH로 보는 블로킹 체인, 막은 쪽이 표본에 없는 이유, ASH 리포트의 'Top Blocking Sessions' → 2_파고들기.md §6 · §7

⛳ 오늘은 여기까지(중단 지점 1) 여기까지가 오늘의 절반이다. 지난주 한 시간을 10초 표본으로 펼치자, 10:30~10:35의 5분은 enq: TX가 100%를 차지했고 CPU는 0%였다. 한 시간을 한 칸으로 세면 같은 표본이 5.7%다. 표본 하나가 10초를 대신한다는 것(600 ≈ 599.0)을 쟀고, 문을 잡은 세션은 그 5분 동안 한 장도 찍히지 않았다는 것을 봤다. 이어서 읽으면 같은 한 시간을 다시 만들어 1초 표본으로 보고, ADDM의 권고를 하나하나 표본으로 검증하고, 팩이 없는 서버에서 같은 일을 하는 법을 배운다.

오전 11시 00분 — 같은 한 시간을 다시

"같은 인자로 다시 돌려. NOTE 하나만 바꾸고." 선배가 말했다. "부하 발생기는 결정적이야. 같은 씨앗이면 같은 순서로 조각을 고르고, 같은 분에 폭발이 와. 그럼 이번에는 끝나자마자 메모리 쪽, 그러니까 1초 표본을 볼 수 있어."

"그 전에 하나만 깔아 두자." 선배가 스크립트 하나를 가리켰다. 01_Statspack_설치였다. "오후에 쓸 거야."

"Statspack이요? AWR이 있는데요."

"오후가 되면 알게 돼." 선배가 말했다. "PDB에 깔아. 루트에는 안 돼."

설치는 2초 만에 끝났다. 그리고 창을 두 개 띄웠다. 하나는 지난주와 같은 발사기 명령(NOTE=C17-H만 다르다)이고, 다른 하나는 스냅샷 스크립트다. 지난주와 같은 자리인 +1분과 +61분에 AWR 스냅샷을 찍고, 그 사이에는 5분마다 Statspack 스냅샷만 찍는다.

"기다리는 동안 ADDM을 보자. 지난주 그 한 시간 걸로."

오전 11시 15분 — ADDM의 네 칸

ADDM은 스냅샷이 찍힐 때마다 저절로 돌아가 있었다. 지난주 그 한 시간(루트 스냅샷 19 → 20)의 과제를 열었다. 맨 위에 요약이 있었다.

   Description                         Active Sessions       Recommendations
                                       Percent of Activity
1  Sequence Usage                      2.65 | 88.06          1
2  Top SQL Statements                  2.32 | 77.15          5
3  Resource Manager CPU Throttling      .69 | 22.88          1
4  Row Lock Waits                       .19 | 6.24           1
5  Checkpoints Due to DROP or TRUNCATE  .18 | 6.13           0
6  "User I/O" wait Class                .13 | 4.19           0
7  PL/SQL Execution                      .1 | 3.46           2

"ADDM의 한 줄은 네 칸으로 돼 있어." 선배가 화이트보드에 적었다. "Finding은 무엇이 문제인지, Impact는 얼마나인지(평균 활성 세션으로), Recommendation은 뭘 하라는지, Rationale은 왜 그렇게 말하는지야. 우리가 검증할 건 마지막 칸이야. Rationale에 적힌 사실을 ASH로 다시 세서, 맞으면 쓰고 안 맞으면 가설로 남겨."

4번을 펼쳤다.

Finding 4: Row Lock Waits — Impact is .19 active sessions, 6.24% of total activity.
   Recommendation: Significant row contention was detected in the TABLE "SQLP.T_STLM_NUM_LD" …
   Rationale:      The SQL statement with SQL_ID "9ph8h7j79zbh7" was blocked on row locks.
   Rationale:      The session with ID 175 and serial number 62822 … was the blocking session responsible for 100% …

SID 175, SERIAL# 62822. 아까 표본으로 센 그 세션, 그 SQL, 그 테이블이었다.

"ADDM은 지난주에 벌써 범인을 짚었네요."

"넷째 줄에서." 선배가 말했다. "그리고 Impact는 .19야. 한 시간 평균으로. ADDM도 리포트처럼 구간 하나를 통째로 평균 내. 그러니 순위가 넷째지. 그 0.19명이 사실은 5분 동안 2명이었다는 건 ADDM도 말해 주지 않아."

"그럼 지난주 리포트 ⑧ 칸은요? 행 락의 88%가 OPTSTAT_HIST_CONTROL$이라고 나왔는데, ADDM은 T_STLM_NUM_LD라고 하잖아요."

"그 표 이름이 뭐였지?"

Segments by Row Lock Waits. "…Waits. 횟수요."

"ADDM은 시간으로 셌어. 리포트의 그 표는 횟수로 셌고. 서로 다른 걸 세면 1등도 달라져." 선배가 같은 리포트의 다른 칸 하나를 짚었다. 대기 이벤트 히스토그램으로, 지난주 그 853번을 길이별로 나눈 것이었다.

enq: TX - row lock contention    853 waits     (지난주 한 시간 · DBA_HIST_EVENT_HISTOGRAM)
   16 µs 이하          505
   16 µs ~ 4 ms        288
   8 ~ 16 s             60

793번은 4밀리초도 안 됐다. 그중 505번은 16마이크로초도 안 됐다. 그리고 60번이 10초 안팎이었다.

"평균 702밀리초는 10초짜리 60번하고 4밀리초도 안 되는 793번을 섞은 평균이었어요." 나는 천천히 말했다. "702밀리초짜리 기다림은 한 번도 없었어요."

"그 793번은 누구 거야?"

그건 오후에 쟀다. 결론부터 적으면 이렇다. 빈 테이블에 APPEND로 넣으면 오라클이 그 자리에서 통계를 모으는데(온라인 통계), 그때마다 SYS.OPTSTAT_HIST_CONTROL$의 한 행을 고친다. 세 세션의 P1이 1분에 수백 번씩 빈 작업 테이블에 적재하니, 그 한 행 앞에 아주 잠깐씩 줄을 선 것이다. 한 번에 수십 마이크로초(두 번 재서 73, 93)짜리 문장이었다. 16화에서 내가 P1의 온라인 통계라고 짐작한 것은 맞았다. 틀린 것은 그 88%를 시간의 88%로 읽은 것이었다.

1번이 남았다. Sequence Usage · 2.65 | 88.06. Sequence cache misses were consuming significant database time. 권고는 한 줄이었다. Use a larger cache size for those sequences. 지난주 Time Model에서 맞지 않던 그 줄이 1위에 올라 있었다.

"Rationale이 없어요."

"그럼 이 Finding이 기댄 칸을 직접 세 봐. ASH 표본에도 '지금 시퀀스를 채우는 중'이라는 깃발이 있어. IN_SEQUENCE_LOAD."

같은 한 시간의 10초 표본을 ACTION별로 셌다.

ACTION        IN_SEQUENCE_LOAD = Y   전체 표본
Q2 rev01                        391         420
P1 rev02                        239         259
Q3 rev01                        216         240
Q1 rev03                         56          63
N1 hotfix                        60          60
N1 rev01                          5           5

넷째 줄에서 웃음이 나왔다. N1 hotfix는 60장 중 60장이 시퀀스를 채우는 중이었다. 그 60장은 전부 FOR UPDATE로 줄 서서 enq: TX를 기다리던 사진이었다. 시퀀스 근처에도 안 가는 집계인 Q2 rev01도 420장 중 391장이었다.

"줄 서 있던 사람이 시퀀스를 채우고 있었대요."

"깃발이 한번 켜지고 안 꺼진 거지." 선배가 말했다. "그래서 Time Model의 그 줄이 SQL 시간과 230배나 어긋났던 거고, ADDM은 그 줄을 믿고 1위로 올린 거야. 오후에 그 권고를 그대로 따라 해 보자. 시퀀스 캐시를 키워서, 정말 뭐가 바뀌는지."

ADDM의 Finding, Impact, Recommendation, Rationale을 검증하는 법, 지난주와 이번 주의 ADDM → 2_파고들기.md §8

오후 12시 10분 — 1초 표본

런이 끝나자마자 메모리 쪽을 열었다. 선배가 재촉했다. "점심 먹고 오면 늦을지도 몰라. 메모리는 고리라고 했지."

맨 처음 칸을 보니 그 말이 무슨 뜻인지 알 수 있었다. OLDEST_MIN_NO 13.6 · OK - spike window is in memory. 메모리에 남은 가장 오래된 1초 표본은 런이 시작되고 13.6분이 지난 때의 것이었다. 앞쪽 13분 남짓은 이미 덮어써졌다. 이 DB의 ASH 버퍼는 4MB라서, 세 세션이 쉬지 않고 돌면 한 시간을 다 담지 못했다. 31분째에 온 폭발은 아직 버퍼 안에 있었다.

1분 칸으로 세 줄을 나란히 놓았다. 이번 주 1초 표본, 이번 주 10초 표본, 지난주 10초 표본이다.

MIN_NO CLOCK  M_SAMPLES  M_AAS  M_CPU  M_ENQ_TX | D_AAS  D_TX_SEC | L_AAS  L_TX_SEC
    30 10:29        180      3    123          |     3           |     3
    31 10:30        120      2             120 |     2       120 |     2       120
    32 10:31        120      2             120 |     2       120 |     2       120
    33 10:32        120      2             120 |     2       120 |     2       120
    34 10:33        120      2             120 |     2       120 |     2       120
    35 10:34        120      2             119 |     2       110 |     2       120
    36 10:35        180      3    120          |     3           |     3

1초 표본으로는 1분에 180장, 폭발 5분 동안은 120장이었다. 거의 전부 enq: TX였고, 마지막 분의 한두 장은 폭발이 끝나는 순간에 찍힌 것이었다. 열 장에 한 장 남긴 보관본도, 지난주 보관본도 같은 자리에 같은 모양이 나왔다.

"같은 모양이에요. 씨앗이 같으니까."

"그래서 이 런으로 지난주를 대신 설명할 수 있는 거야. 결정적인 부하가 있으면 '그때'를 다시 만들 수 있어." 선배가 말했다. "표본 수학도 1초 표본으로 해 봐."

메모리 표본이 빠짐없이 남아 있는 AWR 구간(사이에 낀 정각 자동 스냅샷부터 S2까지 9.1분)에서 1초 표본 수와 AWR 시간을 맞춰 봤다. 폭발의 enq: TX는 한 시간 전체로 맞췄다.

WHAT                           MEM_1S   AWR_SEC
DB time (all samples)           1,639    1,643.2
DB CPU (ON CPU)                 1,082    1,094.9
enq: TX - row lock contention     599      598.8

1초짜리 사진 한 장이 정말로 1초였다. 천육백여 장을 세었는데 오라클의 계량기와 몇 초밖에 차이 나지 않았다.

10초마다

"이제 12화의 트리를 과거로 돌려 봐."

1초 표본을 10초씩 묶어, 그 10초 동안 누가 기다렸고 누구에게 막혔는지 셌다.

RUN_MMSS  CLOCK     SAMPLES  WAITING  ON_CPU  WAITERS  BLOCKERS
30:50     10:29:50       30        0      21
31:00     10:30:00       20       20       0  S2,S3    S1
31:10     10:30:10       20       20       0  S2,S3    S1
 …            (30줄이 같다 — 하나만 WAITING 19)
35:50     10:34:50       20       20       0  S2,S3    S1
36:00     10:35:00       30        0      23

10초마다 20장이었다. 두 세션이 10초 내내 기다렸고, 막은 쪽은 30줄 내내 S1이었다. 기다림을 하나하나 세어 보니(같은 세션에서 대기 번호 SEQ#가 같은 표본이 이어지면 한 번으로 친다) S2가 30번, S3가 30번이었고 한 번에 10초씩이었다(60번 중 하나만 9초). 기다린 표본의 P2와 P3 칸도 셌다. 12화에서 V$LOCK의 ID1, ID2로 풀었던 TX 이름표다. 서로 다른 트랜잭션이 30개였다. S1이 10초씩 쥐었던 트랜잭션 30개다.

폭발 한가운데, 런 +33분 30초의 표본 한 장으로 블로킹 트리를 다시 그렸다.

SID_TREE   SERIAL#  EVENT                           ACTION     CLIENT_ID  WHO
223          41986  (no sample - idle?)                                   S1
  17         44014  enq: TX - row lock contention   N1 hotfix  LD22-S2    S2
  203        49536  enq: TX - row lock contention   N1 hotfix  LD22-S3    S3

런이 도는 동안, 바로 그 초에 12화의 쿼리로 V$SESSION 트리를 한 번 찍어 두었다. 뿌리 223(N1 hold, PL/SQL lock timer) 밑에 17과 203이 enq: TX로 매달린 모양이었다. V$LOCK에서는 223이 TX를 LMODE 6 · BLOCK 1로 쥐고 있었고, 두 세션이 같은 이름표에 REQUEST 6으로 줄을 서 있었다. 두 장을 나란히 놓으니 똑같았다. 다른 것은 뿌리 한 줄뿐이었다. V$SESSION에는 뿌리가 무엇을 하며 쉬는지가 나와 있었고, ASH에는 이름만 있었다.

블로킹 체인의 시계열, 과거의 트리, TX 이름표 → 2_파고들기.md §6

오후 1시 30분 — 왜 뒤집혔나

점심을 먹고 돌아오자 선배가 화이트보드를 지웠다. "지난주 결론이 왜 뒤집혔는지 세 줄로 말해 봐. 조민우 씨한테 보낼 거야."

세 줄을 적었다.

1. 평균 — 599초를 3,600초로 나눴다. 그 599초는 300초 안에 있었다.
2. 칸 — 한 시간을 한 칸으로 셌다. 5분 칸으로 세면 같은 표본이 5.7 % → 100 % 다.
3. 단위 — AWR 은 누적된 시간을 준다. '언제' 는 버린다. ASH 는 순간을 준다. 그래서 다시 쪼갤 수 있다.

"하나 더." 선배가 넷째 줄을 적었다. "4. 횟수와 시간: '88%'는 행 락 횟수의 88%였다. 853번의 '평균 702ms'는 두 무리를 섞은 평균이었다. 지난주 리포트에서 네가 쓴 숫자 넷 중에 셋이 평균이었고, 하나는 횟수였어."

"그럼 AWR 리포트는 쓸모없는 거예요?"

"쓸모없었으면 지난주에 그걸로 세 문장이나 뒤집었겠어?" 선배가 웃었다. "AWR은 '얼마나'를 잘 보여 줘. 오전 내내 CPU가 모자랐다는 건 이번 주에도 맞아. 55분 동안은. 문제는 한 시간 한 칸으로 '얼마나'를 본 다음에 '언제'를 묻지 않은 거야. 순서는 이래. AWR로 얼마나, ASH로 언제와 누가. ADDM은 그 둘 위에 세운 가설이고."

선배가 하나를 더 보여 줬다. 같은 한 시간을 디스크의 10초 표본으로 ASH_REPORT_TEXT에 넣어 뽑은 리포트의 맨 끝 칸이었다.

Activity Over Time                          (시각은 연습 DB 의 시계 — 13:39:49 가 운영 시계 10:30)
Slot Time (Duration)   Slot Count  Event                            Event Count
13:35:00   (5.0 min)          108  CPU + Wait for CPU                        56
                                   resmgr:cpu quantum                        18
                                   enq: RO - fast object reuse               10
13:40:00   (5.0 min)           66  enq: TX - row lock contention             55
                                   CPU + Wait for CPU                         5
13:45:00   (5.0 min)          108  CPU + Wait for CPU                        73

"이 칸, 지난주 AWR 리포트 뒤쪽에도 있었어. awr_H.txt 맨 끝에. 16화에서 네가 '17화'라고 적고 덮어 둔 그 절이야."

지난주 파일을 다시 열었다. 5,000줄짜리 리포트의 끝에서 두 번째 절, Activity Over Time이었다.

09:35:00   (5.0 min)           85  CPU + Wait for CPU                        32
                                   enq: TX - row lock contention             30
09:40:00   (5.0 min)           86  CPU + Wait for CPU                        30
                                   enq: TX - row lock contention             30

처음부터 거기 있었다. 다만 칸 경계가 시계의 5분 단위에 맞춰져 있어서, 지난주에는 폭발이 두 칸에 반씩(30장과 30장) 나뉘었고 두 칸 모두 1등은 여전히 CPU였다. 이번 주에는 폭발이 거의 한 칸(13:40)에 들어가 55장으로 1등이 됐다. 같은 5분이라도 칸 경계와 어디서 만나느냐에 따라 1등이 되기도 하고 2등이 되기도 했다.

"리포트 한 장에 이미 있었어요."

"있었지. 안 읽었을 뿐이야." 선배가 말했다. "그리고 하나 조심할 게 있어. 앞쪽이 메모리에서 밀려난 한 시간을 리포트로 뽑을 때 표본을 어디서 읽을지 정해 주지 않으면, 이 버전은 둘을 이어 붙이다가 실패했어. 두 번 해 봤는데 두 번 다 표본은 300개 안팎(313, 267), 평균 활성 세션은 0.87, 0.74였고 enq: TX는 아예 없는 리포트가 나왔어. 한 시간짜리는 디스크 쪽(l_data_src => 2)으로 뽑아."

16화 결론이 뒤집힌 네 가지(평균 · 칸 · 단위 · 횟수) → 2_파고들기.md §5 · ASH 리포트 읽는 순서와 함정 → §7

⛳ 오늘은 여기까지(중단 지점 2) 같은 한 시간을 다시 만들어 1초 표본으로 봤다. 두 런은 모양이 같았고, 10:30~10:35에는 10초마다 20장이 찍혔다. 두 세션이 S1에게 막혀 10초씩 30번 기다린 것이다. 지난주 결론이 뒤집힌 이유는 평균, 칸, 단위, 횟수 네 가지다. 그리고 그 5분은 처음부터 지난주 리포트 뒤쪽에 있었다. 여기까지만 해도 오늘 할 일은 다 했다. 이어지는 오후에는 ADDM 1위 권고를 그대로 따라 해 보고, SQL Monitor가 무엇을 잡는지 재고, 팩이 없는 서버에서 같은 일을 하는 법을 배운다.

오후 2시 10분 — 권고를 그대로 해 본다

이번 주 한 시간으로 ADDM을 직접 돌렸다. addmrpt의 대화형 질문 대신 DBMS_ADDM.ANALYZE_DB 한 줄이면 된다. 1위는 지난주와 같았다. Sequence Usage · 2.85 | 97.54. Row Lock Waits는 다섯째로 .17이었고, Rationale에는 이번 주 런의 세션 1이 100%로 적혀 있었다. 1위의 Impact를 초로 꺼내 보니 같은 구간 인스턴스 Time Model의 sequence load elapsed time과 소수점까지 같았다. 10,277.5초와 10,277.5초. ADDM의 1위는 그 한 줄을 그대로 옮겨 온 것이었다.

그 시퀀스를 실제로 부른 문장(N1 rev01의 INSERT … SQ_STLM_LD.NEXTVAL)은 같은 한 시간 동안 31.1초를 썼다.

"권고대로 하면 최대 몇 초가 줄어?" 선배가 물었다.

"그 문장 전체가 31.1초니까… 다 없어져도 31.1초요. 1만 초가 아니라."

"그래도 해 봐. 짐작 말고."

먼저 혼자서 쟀다. 복사본 시퀀스를 하나 만들고, 번호 2,000개를 받은 다음 시퀀스와 상관없는 집계를 100번 돌리는 호출을 여섯 가지로 바꿔 가며 돌렸다. 캐시 20과 1000, 순서 바꾸기, 중간에 0.2초 쉬기, 호출 나누기였다.

A  CACHE 20   seq -> q2            DB time 2.95 s | sequence load 0.00 s | ASH samples 3 (IN_SEQUENCE_LOAD=Y 0)
B  CACHE 1000 seq -> q2            DB time 2.95 s | sequence load 0.00 s | ASH samples 3 (IN_SEQUENCE_LOAD=Y 0)
E  CACHE 20   seq only (call 1)    DB time 0.01 s | sequence load 0.00 s | ASH samples 0 (IN_SEQUENCE_LOAD=Y 0)
(C · D · F — 순서 바꾸기 · 0.2초 쉬기 · 호출 나누기 — 도 전부 0.00 s · 깃발 0)

전부 0.00초였다. 깃발도 한 번도 켜지지 않았다. 번호 2,000개를 받는 데 든 시간은 0.01초였다.

"혼자서는 안 켜지네요."

"그럼 부하를 걸고 해 보자." 선배가 말했다. "7분짜리 런을 두 번 돌려. 첫 번째는 캐시 20 그대로, 두 번째는 1000으로. 그 5분을 ADDM으로 보고."

                         CACHE 20     CACHE 1000 (ADDM 의 권고)
DB time (5분)             900.7 s        902.2 s
sequence load             721.5 s        717.8 s
ADDM Sequence Usage       2.41 AAS       2.39 AAS   — 같은 권고 "Use a larger cache size"
그 시퀀스를 부른 INSERT     1.98 s         2.87 s

권고대로 했더니 ADDM이 같은 권고를 또 내놓았다. DB Time은 그대로였고, 정작 시퀀스를 쓰는 문장의 시간은 잡음 수준으로 흔들렸을 뿐이다.

선배가 하나를 더 시켰다. 발생기 가중치에서 N1을 0으로 바꿔, 시퀀스를 한 번도 부르지 않는 부하를 세 세션으로 3분 동안 돌렸다.

세션 하나에서 136초째에 깃발이 켜졌다. 그리고 꺼지지 않았다.

"…우리 시퀀스가 아니에요. 시퀀스를 안 불러도 켜져요."

"그러니까 권고대로 캐시를 키울 시퀀스가 처음부터 없었던 거야." 선배가 말했다. "깃발이 왜 켜지는지는 오늘 다 밝히지 못했어. 혼자서는 안 켜지고, 세 세션이 CPU를 넘치게 쓰면 1~4분 사이 어딘가에서 켜지고, 한번 켜지면 그 호출이 끝날 때까지 안 꺼진다. 우리가 잰 건 거기까지야. 그걸로 충분해. 이 칸으로는 결론을 내지 않는다. 지난주에 네가 정한 규칙으로 오늘 ADDM 1위를 기각한 거야."

깃발 실험 전체, 권고를 적용한 두 판, 이 화에서 밝히지 못한 것 → 2_파고들기.md §9

오후 3시 00분 — SQL Monitor는 무엇을 잡나

"N1 hotfix가 한 번에 10초 넘게 기다렸지. SQL Monitor에 그 문장이 있을까?"

"5초 넘으면 저절로 감시한다고 들었어요. 있겠죠."

V$SQL_MONITOR를 열었다. 런 동안 감시된 것은 세 개, 부하 발생기 세션 셋이 부른 BEGIN PKG_LOAD_DRIVER.RUN_SESSION(n); END;였다. 한 시간짜리 PL/SQL 호출이다. FOR UPDATE 문장은 0줄이었다.

"5초는 CPU와 I/O를 합친 거야. 기다림은 안 세." 선배가 말했다. "그래서 자물쇠 앞에서 10초를 서 있어도 SQL Monitor는 안 켜져. 락은 ASH로 보는 거고."

조건을 하나씩 확인했다. 블록은 하나도 읽지 않고 CPU만 쓰는 같은 모양의 문장을 크기만 바꿔 두 번 돌렸다. 1.5초짜리는 감시되지 않았고, 8초짜리는 시작하고 6초 뒤부터 감시가 붙었다. 06화의 100만 번 왕복(Q2 rev00, 블록 1,026,838개)은 0.27초라 감시되지 않았다. /*+ MONITOR */를 단 0.03초짜리 집계는 감시됐다. /*+ PARALLEL(o 4) */는 실행계획부터 직렬이었다. 병렬 서버를 쓴 실행도 0, 감시도 0이었다.

"Free에서는 병렬이 안 일어나. 그래서 '병렬이면 저절로 감시'는 여기서 볼 수가 없어. 큰 서버는 별권에서 다룰 거야."

8초짜리 문장의 리포트를 TEXT로 뽑았다. 실행계획 줄마다 실제 행수와 활동 시간이 붙어 있었다. ALLSTATS LAST와 비슷하지만, 문장이 도는 동안 볼 수 있다는 점이 달랐다. "SQL Monitor는 문장 하나를 보는 도구야." 선배가 말했다. "오늘 본 5분은 문장 하나의 문제가 아니었어. 줄 서기 문제였지."

감시된 셋 가운데 하나가 눈에 걸렸다. RUN_SESSION(1)의 Elapsed만 다른 둘보다 정확히 300초 짧았다. 지난주 AWR에서 본 그 300초가 여기에도 있었다.

SQL Monitor 시작 조건 실측, 리포트, Free의 병렬 → 2_파고들기.md §10

오후 3시 40분 — 팩이 없는 서버

박팀장의 두 번째 부탁을 열었다. 버거 프랜차이즈 POS DB의 접속 계정이었다. 습관처럼 SQL*Plus로 접속하자마자 @?/rdbms/admin/awrrpt를 쳤다. 엔터를 누르기 직전에 선배가 내 손목을 잡았다.

"에디션부터 봐."

V$VERSION의 첫 줄은 Standard Edition 2였다.

"SE2는 진단 팩을 살 수가 없어. 그 서버에서 AWR 리포트를 뽑으면 그게 라이선스 위반이야. 우리 회사 이름으로." 선배가 손을 놓았다. "CONTROL_MANAGEMENT_PACK_ACCESS는?"

NONE. 그 서버는 그 값이었다.

"Free에는 팩이 들어 있어서 오늘 아침까지 아무 생각 없이 썼지. 운영 EE라도 계약이 없으면 마찬가지야. 16화에서 T5 양식에 팩 확인란을 만든 게 이것 때문이야." 선배가 말했다. "그 서버에서는 아무것도 하지 말고, 연습 DB를 그 서버처럼 만들어 보자. NONE이면 뭐가 막히는지."

연습 DB의 값을 메모리에서만 NONE으로 내렸다. spfile은 건드리지 않았다. 그리고 오늘 쓴 도구를 하나씩 불러 봤다.

[NONE]   a AWR snapshot (CREATE_SNAPSHOT)          OK - snap 42
[NONE]   b AWR report (AWR_REPORT_TEXT)            OK - 5826 lines
[NONE]   c ASH report (ASH_REPORT_TEXT)            OK - 377 lines
[NONE]   d ADDM (DBMS_ADDM.ANALYZE_DB)             ORA-13716: Diagnostic Package License is needed for using this feature.
[NONE]   e SQL Monitor report                      OK - 21 chars
[NONE]   f ASH sampling (my 3 s of CPU)            0 samples in V$ACTIVE_SESSION_HISTORY
[NONE]   g /*+ MONITOR */ -> V$SQL_MONITOR          0 row(s) in the last minute
[NONE]   h SELECT DBA_HIST_ACTIVE_SESS_HISTORY     returns 1224 rows
[NONE]   i V$SESSION / V$SYSSTAT / V$SYSTEM_EVENT  OK
[NONE]   j Statspack (STATSPACK.SNAP in PDB)       OK - statspack snap 21

예상과 다른 줄이 여럿이었다. 막힌 것은 셋뿐이었다. ADDM은 에러를 냈고, ASH는 표본을 그만 찍었고, SQL Monitor는 감시를 그만뒀다. 그런데 AWR 스냅샷도, AWR 리포트도, ASH 리포트도, DBA_HIST 조회도 다 됐다.

"막아 주는 줄 알았어요."

"스위치는 새로 모으는 걸 멈출 뿐이야. 이미 쌓인 걸 읽는 건 안 막아." 선배가 말했다. "그래서 라이선스는 기술이 아니라 계약으로 지키는 거야. 안 막힌다고 써도 되는 게 아니야. 팩이 없는 서버에서는 DBA_HIST_*도, awrrpt도, ashrpt도 열지 마."

값을 DIAGNOSTIC+TUNING으로 되돌렸다. ASH가 다시 내 세션을 3장 찍었고, 스냅샷도 찍혔다.

"그럼 그 서버에서는 뭘로 봐요?"

"아침에 깐 거." 선배가 웃었다. "Statspack. 오라클이 함께 주는 스크립트라 팩이 필요 없어. 이번 주 런 동안 5분마다 찍어 뒀어."

spreport.sql로 한 시간짜리 리포트를 뽑았다.

Top 5 Timed Events                                  Avg   %Total
Event                              Waits  Time (s)  (ms)  Call Time
CPU time                                     6,628          62.8
resmgr:cpu quantum                 7,969     2,158   271    20.5
enq: TX - row lock contention      1,060       599   565     5.7

AWR 한 장과 같은 그림이었다. 한 시간 동안 enq: TX는 5.7%. 평균도 같고 함정도 같았다. 게다가 Statspack에는 ASH가 없었다.

"그럼 Statspack으로는 그 5분을 못 봐요?"

"5분마다 찍어 뒀다고 했지. 10:30부터 10:35까지로 뽑아 봐."

Begin Snap:  7 (+31:00 = 10:30)    End Snap:  8 (+36:00 = 10:35)    Elapsed: 5.00 (mins)   Av Act Sess: 2.0
   DB time: 10.10 (mins)    DB CPU: 0.11 (mins)
Top 5 Timed Events                                  Avg   %Total
enq: TX - row lock contention        143      599  4,187    99.5

99.5%.

"칸을 좁히면 보여." 선배가 말했다. "ASH가 없는 현장에서 '언제'를 보는 방법은 하나야. 칸을 직접 좁게 만드는 거지. Statspack 스냅샷을 5분마다 찍거나, 12화 포스트모템 재발방지 3번처럼 블로킹 트리를 1분마다 찍어서 남겨. 대신 미리 해 둬야 해. 지나간 다음에는 칸을 다시 자를 수 없어. ASH가 있으면 지나간 다음에도 자를 수 있고. 돈을 내는 이유가 그거야."

NONE에서 막힌 것과 남은 것, Statspack 설치와 리포트, AWR과 다른 점 → 2_파고들기.md §11 · §12

오후 5시 30분 — 네 칸짜리 표

T5 리포트 2호를 썼다. 1호는 고치지 않고, 1호의 결론 칸 옆에 무엇이 왜 틀렸는지 적는 교차검증판이었다. ADDM을 적는 4번 칸에는 처음으로 채택과 기각을 적었다. Row Lock Waits는 채택했고(Rationale의 세션이 ASH와 100% 일치), Sequence Usage는 기각했다(시퀀스를 안 불러도 깃발이 켜지고, 권고를 적용해도 그대로다). 구간 안의 시간 분포를 적는 5번 칸에는 오늘 아침에 만든 5분 칸 표를 그대로 옮겼다.

선배가 시킨 표도 하나 만들었다. 오늘 쓴 도구 네 개(AWR, ASH, ADDM, Statspack)를 같은 질문 앞에 나란히 세우는 표다. 얼마나 바빴나에는 넷 다 답했다. 언제에는 ASH만 답했고, Statspack은 미리 좁혀 둔 칸만큼만 답했다. 누가 누구를 막았나에는 ASH가 답했고, ADDM은 Rationale에 이름을 적었다. 무엇을 하라는 ADDM만 말했는데, 그건 가설이었다.

"이 표가 18화 표준에 들어갈 거야." 선배가 말했다. "도구 하나를 들고 가지 말고, 질문을 들고 가서 그 질문에 답하는 칸을 골라."

오후 6시 20분

조민우 씨에게 답장을 보냈다.

나  18:20
지난주 리포트에서 "락은 부차적"이라고 쓴 것은 정정합니다.
같은 한 시간을 연습 DB 에서 다시 만들어 1분 · 5분 단위로 펴 보니, 그 '5.5%' 는 한 시간에 고르게 퍼진 게 아니라
10:30 ~ 10:35 의 5분에 전부 몰려 있었고, 그 5분 동안은 등록하려던 세션이 전부 번호 행 하나를 기다리느라
일을 하나도 못 했습니다. 한 시간짜리 리포트에는 그게 '5%' 로만 남습니다.
그래서 6/17 에 화면이 5분 멈췄다는 말씀을 그 리포트로 반박할 근거는 처음부터 없었습니다.
다만 운영의 6/17 기록은 보존 기간(8일)이 지나 지워져서, 그날 무엇이 번호 행을 쥐었는지는 확인할 수 없습니다.
다음에 같은 일이 생기면 시각만 바로 알려 주세요. 그 5분을 그날 바로 떠 두겠습니다.

조민우  18:31   이제야 숫자가 저희 말을 하네요. 다음엔 시계 보고 바로 연락드릴게요.
박팀장  18:40   운영팀에 '민원 오면 그 시각 ASH 를 바로 저장' 절차 추가 요청했습니다. 버거 쪽은 Statspack 으로 부탁해요.

선배가 가방을 챙기다가 화면을 봤다. "지난주에 '모른다'고 쓰라고 했지. 오늘은 '모른다'와 '틀렸다'를 둘 다 썼네."

"6/17은 정말 모르니까요."

"그게 맞아. 하나 더 기억해 둬." 선배가 말했다. "오늘 네가 뒤집은 건 지난주의 너야. 다음 주에는 지금까지 쓴 리포트를 전부 꺼내서, 그중에 뭐가 표준이 될지 고를 거야. 그때도 오늘처럼 물어봐. 이건 평균인가, 이건 횟수인가, 이건 언제인가."

오늘 남은 것

무엇	값
지난주 한 시간(C16-H) · 10초 표본	10:30~10:35: 표본 60 · 평균 활성 세션 2.00 · `enq: TX` 100% · CPU 0% / 한 시간 한 칸: 1,050 · 2.92 · 5.7%
표본 수학	10초 표본 1건 ≈ 10초: DB time 1,050 × 10 = 10,500 vs AWR 10,504.5 · `enq: TX` 60 × 10 = 600 vs 599.0 · 1초 표본도 같다
막은 쪽	SID 175 · SERIAL# 62822 = 지난주 런의 세션 1 · 폭발 중 표본 0(ASH 리포트 BLOCKING SESSION NOT FOUND 0/30) · `RUN_SESSION(1)`이 300초 짧은 이유
이번 주 한 시간(C17-H) · 1초 표본	같은 모양: 1분에 180 → 120 · 10초마다 20(S2와 S3가 S1에게 막힘) · 기다림 30 × 10초씩 · TX 30개 · 과거의 트리는 뿌리만 표본이 없다
16화 결론이 뒤집힌 넷	평균 · 칸 · 단위 · 횟수. 'Row Lock Waits 88%'는 횟수 · '평균 702ms'는 10초 × 60과 4ms 미만 × 793의 평균
ADDM	Row Lock Waits: Rationale의 세션이 ASH와 일치 → 채택 / Sequence Usage: 시퀀스를 안 불러도 깃발이 켜진다 · 권고(CACHE 1000)를 따라도 그대로 → 기각
SQL Monitor	5초는 CPU + I/O만 센다. 10초 넘게 기다린 `FOR UPDATE`는 감시되지 않았다 · 1.5초 ✗ / 8초 ○ / `MONITOR` 힌트 ○ / Free의 병렬은 직렬로
팩 없는 현장	`NONE`이 막는 것: ADDM(`ORA-13716`) · ASH 표본 · SQL Monitor 감시 / 막지 않는 것: AWR 스냅샷 · AWR · ASH 리포트 · `DBA_HIST` 조회(그래도 쓰면 위반) · Statspack 한 시간 5.7% / 5분 99.5%
새 양식	T5 2호(교차검증판) · 진단도구 4열 대응표

오늘 배운 한 문장

평균은 '얼마나'를 말하고 '언제'를 버린다. 한 시간을 한 칸으로 셀 때 5%인 것이 5분 칸에서는 100%일 수 있다. 칸을 다시 자를 수 있는 것은 순간을 남긴 기록(ASH)뿐이고, 그런 기록이 없는 곳에서는 칸을 미리 좁혀 두어야 한다.

다음으로 넘기는 것

그동안 쓴 리포트를 전부 다시 꺼낸다. 오늘의 질문 셋(평균인가 · 횟수인가 · 언제인가)을 표준 조문으로, 4열 대응표도 함께 → 18화
ADDM의 'Top SQL' 권고: SQL Tuning Advisor · Q2 보류안 · 계획 고정(SPM) → 18화
깃발 IN_SEQUENCE_LOAD가 켜지는 조건: 오늘 다 밝히지 못했다(혼자서는 안 켜진다 · 세 세션이면 켜진다) → 열어 둔다

다음 → 3_실습과_기록.md에서 지난주 한 시간을 10초 표본으로 펼치고, 같은 한 시간을 다시 만들어 1초 단위로 본다. ADDM을 검증하고, 팩 없는 현장을 만들어 Statspack으로 같은 한 시간을 읽은 뒤, T5 2호와 4열 대응표를 쓴다. 개념이 막히면 → 2_파고들기.md

17화 · 평균은 거짓말을 한다 ​

오전 9시 05분 ​

오전 9시 20분 — 첫 번째 답 ​

오전 9시 40분 — 방재실의 녹화기 ​

오전 10시 10분 — 열 장에 한 장 ​

표본 수학 ​

오전 10시 40분 — 문을 잡은 사람 ​

오전 11시 00분 — 같은 한 시간을 다시 ​

오전 11시 15분 — ADDM의 네 칸 ​

오후 12시 10분 — 1초 표본 ​

10초마다 ​

오후 1시 30분 — 왜 뒤집혔나 ​

오후 2시 10분 — 권고를 그대로 해 본다 ​

오후 3시 00분 — SQL Monitor는 무엇을 잡나 ​

오후 3시 40분 — 팩이 없는 서버 ​

오후 5시 30분 — 네 칸짜리 표 ​

오후 6시 20분 ​

오늘 남은 것 ​

오늘 배운 한 문장 ​

다음으로 넘기는 것 ​