목록 하나에 조회가 수백 번 붙었다

주문 목록이 간헐적으로 느렸다. 코드를 봐도 무거운 쿼리가 없었다.

Open Table of contents

증상 — 코드에는 조회 하나
조사 — 쿼리 로그가 보여 준 것
원인 — 화면 쪽의 속성 접근
조치 — 조회 시점에 묶기
제약 — 건수가 적을 때는 안 드러난다
검증 — 요청당 쿼리 수
정리

증상 — 코드에는 조회 하나

컨트롤러는 이게 전부였다.

$orders = $this->orderRepo->recent($limit);
return $this->view('order/list', ['orders' => $orders]);

orderRepo->recent 로 한 번 조회하고 그대로 화면에 넘기는 것으로 끝난다.

무거운 조인도 없고 반복문도 없어서 코드에서 원인을 찾는 동안에는 아무것도 나오지 않았다.

조사 — 쿼리 로그가 보여 준 것

한 요청에서 나가는 것을 전부 찍어 봤다.

DB::listen(function ($q) {
    Log::debug('sql', ['q' => $q->sql, 'ms' => $q->time]);
});

한 요청에 412개가 찍혔다.

SELECT * FROM orders WHERE ... ORDER BY no DESC LIMIT 50
SELECT * FROM members WHERE no = 8812
SELECT * FROM members WHERE no = 8813
SELECT * FROM order_item WHERE order_no = 41022
SELECT * FROM order_item WHERE order_no = 41023
...

orders 를 읽는 쿼리 하나 뒤에 행마다 조회가 붙고 있었다.

members 와 order_item 이 번갈아 나오는 모양이 50건짜리 목록의 행 수와 맞아떨어졌다. 코드에서 안 보이던 것이 로그에서는 첫 줄부터 드러났다.

원인 — 화면 쪽의 속성 접근

조회는 컨트롤러가 아니라 화면에 있었다.

<?php foreach ($orders as $o): ?>
  <td><?= $o->member->name ?></td>
  <td><?= count($o->items) ?>건</td>
<?php endforeach ?>

$o->member 를 처음 읽는 순간 members 조회가 나간다.

화면 쪽에서는 $o->member->name 이 그냥 속성을 읽는 것처럼 보인다. 조회가 나가는 자리와 그것이 적힌 자리가 다르니 컨트롤러만 봐서는 안 보인다.

count($o->items) 도 마찬가지여서 건수를 세려고 항목을 통째로 가져온다. 한 줄에 조회가 둘 붙고 그것이 50번 돈 결과가 412개였다.

조치 — 조회 시점에 묶기

필요한 것을 조회 시점에 같이 받게 했다.

$orders = $this->orderRepo->recent($limit, ['member', 'items']);

recent 안에서는 member_no 를 모아 한 번에 가져와 붙인다.

public function recent(int $limit, array $with = []): array
{
    $rows = $this->db->select('SELECT * FROM orders ORDER BY no DESC LIMIT ?', [$limit]);
    if (in_array('member', $with, true)) {
        $ids = array_unique(array_column($rows, 'member_no'));
        $members = $this->memberRepo->byIds($ids);
        foreach ($rows as &$r) { $r['member'] = $members[$r['member_no']] ?? null; }
    }
    ...
}

array_unique 로 중복을 없애니 같은 회원이 여러 건 주문했어도 한 번만 조회한다.

412개가 3개가 되어 orders 하나와 members 하나와 order_item 하나로 끝난다.

제약 — 건수가 적을 때는 안 드러난다

개발 환경에서는 이 문제가 보이지 않았다.

orders 가 20건이라 61개쯤이고 그 정도로는 느리다고 느껴지지도 않는다. 운영에서 목록이 50건이고 항목이 많으면 수백 개가 된다.

간헐적으로 느렸던 것도 같은 이유여서 LIMIT 안에 드는 행이 많을 때만 느렸고 나머지는 빠르게 나왔다.

행 수에 비례해 조회가 느는 구조는 자료가 적으면 안 드러난다. 그래서 코드 리뷰로도 잘 안 잡힌다.

검증 — 요청당 쿼리 수

숫자로 드러나야 다음에 또 안 생긴다.

$count = 0;
DB::listen(function () use (&$count) { $count++; });

register_shutdown_function(function () use (&$count) {
    if ($count > 50) {
        Log::warning('query count high', ['n' => $count, 'uri' => $_SERVER['REQUEST_URI'] ?? '']);
    }
});

50을 넘으면 REQUEST_URI 와 함께 로그에 남는다.

임계값을 낮게 잡고 시끄러운 것부터 줄여 나갔더니 며칠치에서 같은 모양의 화면이 몇 개 더 나왔다.

로그는 안 보게 되므로 개발 환경에서는 화면에 띄웠다.

if (APP_ENV === 'local') {
    echo "<div class=\"devbar\">queries: {$count} / {$ms}ms</div>";
}

화면을 만들면서 필드 하나를 추가했을 때 숫자가 뛰는 것이 그 자리에서 보인다. 배포한 뒤에 아는 것과 만들면서 아는 것은 값이 다르다.

with 에 전부 넣는 것도 답은 아니어서 필요한 것만 지정하게 뒀다.

if (!array_key_exists('member', $row)) {
    throw new LogicException('member를 with에 넣지 않았습니다');
}

with 에 지정을 빠뜨리면 조용히 조회가 나가는 대신 LogicException 으로 그 자리에서 걸린다.

정리

컨트롤러가 조회 하나여도 화면에서 행마다 조회가 나갈 수 있다
조회가 나가는 자리와 적힌 자리가 다르면 코드만 봐서는 안 보인다
쿼리 로그를 켜서 한 요청에 몇 개가 나가는지 센다
로그의 반복 패턴이 목록 행 수와 맞으면 그 구조다
필요한 것을 조회 시점에 묶어서 가져온다
식별자를 모을 때 중복을 없애면 조회가 더 준다
행 수에 비례하는 구조는 자료가 적으면 안 드러난다
요청당 쿼리 수에 임계값을 두고 넘으면 로그에 남긴다
개발 환경에서는 화면에 숫자를 띄운다
전부 미리 가져오는 것도 답은 아니다
빠뜨렸을 때 조용히 넘어가지 않게 한다