[SQLAlchemy] SQL Compilation Caching

목차

 

 

개요

SQLAlchemy를 통해 DB에 Query를 날리는 코드를 짜던 도중이었다. 평소에 만들던 방식으로 코드를 작성해 놓고 SQLAlchemy의 log를 살펴보던 도중 이상한 점을 발견했다. 이상한 점을 발견한 log는 다음과 같다.

2023-08-08 15:46:01,882 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2023-08-08 15:46:01,883 INFO sqlalchemy.engine.Engine SELECT * FROM member  WHERE member_id = %(member_id)s;
2023-08-08 15:46:01,883 INFO sqlalchemy.engine.Engine [cached since 23.18s ago] {'member_id': '38fc9de4-2bb4-497f-8daa-2dbd9e7c88cb'}
2023-08-08 15:46:02,173 INFO sqlalchemy.engine.Engine COMMIT
2023-08-08 15:46:02,259 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2023-08-08 15:46:02,259 INFO sqlalchemy.engine.Engine SELECT * FROM member  WHERE member_id = %(member_id)s;
2023-08-08 15:46:02,259 INFO sqlalchemy.engine.Engine [cached since 23.56s ago] {'member_id': '38fc9de4-2bb4-497f-8daa-2dbd9e7c88cb'}
2023-08-08 15:46:02,541 INFO sqlalchemy.engine.Engine COMMIT

최초로 이상하다고 여겼던건 같은 쿼리를 두 번 날리고 있었던 점이다. 이건 만들어둔 코드를 재사용하는 과정에서 발생한 실수라서 금방 고칠 수 있었다. 하지만 "cached since 23.18s.ago"와 같은 log는 "이게 뭘 뜻하는 로그지?"라는 궁금증이 생겼다.

 

동일한 쿼리를 두 번 날리는 과정에서 발견했기 때문에 단순히 "SqlAlchemy에서 쿼리를 캐싱하는 기능인가?"라고 유추해봤지만 SqlAlchemy에서 쿼리 캐싱이 뭔가 어색하다고 느껴졌기 때문에 이에 대한 호기심으로 더 파고들게 되었다.

 

SQL Compilation Caching

"쿼리 캐시"라고 하면 "쿼리 결과"에 대한 캐싱이다. 조회한 값을 저장하고 있다가 같은 쿼리 문을 요청하였을 때 미리 캐싱된 값을 반환하는 DBMS 기능이다. 하나 MySQL에서 이는 5.7부터 사라졌다고 알고 있다. 그래서 SqlAlchemy에서 이러한 기능이 있는 걸까라는 자가당착에 빠져서 삽질을 했지만 조사한 결과 "개요"에서 언급한 cached since 로그가 발생한 이유는 "쿼리 캐시"가 아닌 "컴파일 쿼리 캐시"에 대한 부분이었다. 

 

필자 스스로 이해를 하기 위해  "컴파일 쿼리 캐시"라고 적었지만 이는 SqlAlchemy의 "Compilation Caching"을 뜻하며

 "Compilation Caching"는 SqlAlchemy에서 실제로 쿼리를 날리기 전에 DBMS에 날리는 쿼리(SQL)를 컴파일하며 이에 대한 캐싱을 수행하는 기능이다.

즉, 컴파일된 쿼리를 캐싱 처리하는 기능인 것이다.

 

 

How to Compilation Caching  Setting

SQL Compilation Caching은 캐싱 처리를 담당하기 때문에 size를 조정할 수 있는 옵션을 제공하는데 이는 SqlAlchmey에서 engine을 생성할 때 "query_cache_size"를 이용함으로써 설정할 수 있다. 

from sqlalchemy import create_engine

def get_engine():
    return create_engine(
        url=get_url(),
        echo=True,
        echo_pool=True,
        query_cache_size=1
    )

create_engine 함수의 내부를 들여다보면 query_cache_size에 대해 다음과 같이 설명되어있다.

The cache is pruned of its least recently used items when its size reaches N * 1.5.

Defaults to 500, meaning the cache will always store at least500 SQL statements when filled, and will grow up to 750 items at whichpoint it is pruned back down to 500 by removing the 250 least recentlyused items.

요약하자면, query_cache_size의 default는 500개의 SQL 문을 저장하며 설정된 값의 1.5배 정도에 도달하면 최근 사용되지 않은 항목들이 삭제되어 크기를 유지한다고 한다. 

 

 

Compilation Caching  Logging

이제 SQL Compilation Caching가 뭐 하는 기능인지 대강 알았으니 실제로 어떻게 로그가 찍히는지 확인해 보자. 처음엔 단순히 "SELECT" 구문을 날리는 것으로 시작하자. 

SELECT * FROM `member` WHERE reference_id=%(member_id)s;

primary key로 단순 데이터를 조회하는 SELECT 쿼리이다. 최초로 날린 쿼리라면 아직 캐싱이 되지 않은 상황이기 때문에 다음과 같은 로그가 발생한다.

2023-08-13 01:33:39,411 INFO sqlalchemy.engine.Engine [generated in 0.00011s] {'member_id': 30}

이는 SqlAlchmey에서 다음과 같이 설명한다.

the statement was a cache miss and had to be compiled, then stored in the cache. it took X seconds to produce the compiled construct. The number X will be in the small fractional seconds.

cache miss이기 때문에 컴파일한 다음 캐시에 저장해야 하며, 컴파일된 구문을 생성하는 x초(로그에서는 0.00011 s)가 걸렸다는 의미라 한다.

 

이제 같은 쿼리를 두 번 날려보자. 

SELECT * FROM `member` WHERE reference_id=%(member_id)s;
SELECT * FROM `member` WHERE reference_id=%(member_id)s;

이 상황은 첫 번째로 날린 쿼리는 캐시 되었을 것이고 두 번째로 날린 쿼리는 첫 번째로 날린 쿼리와 동일하기 때문에 cache hit가 발생할 것으로 예상할 수 있다. SqlAlchemy의 Log에서는 다음과 같이 표시된다.

첫 번째로 날린 쿼리에 대해선 cache miss이므로 앞에서 살펴봤던 경우대로 generated 로그가 발생했고 두 번째로 날린 쿼리에 대해선 cache since 0.9285s ago라는 로그가 발생한 것을 확인할 수 있다. 이 로그에 대해서 SqlAlchemy의 Document에서는 다음과 같이 설명하고 있다.

[cached since Xs ago]
the statement was a cache hit  and did not have to be recompiled. The statement has been stored in the cache since X seconds ago.

요약하자면 statement가 cache hit이며 다시 컴파일할 필요가 없으며 X초(로그에서는 0.9285초) 전부터 캐시에 저장되었음을 뜻한다.

 

 

Compilation Caching  Pruning Logging

지금까지는 cache miss와 cache hit가 일어나는 경우에 대해서 어떤 로그가 발생하는지에 대해 살펴봤다. 그렇다면 query_cache_size를 1로 한 상태에서 여러 SELECT 문을 날린다면 어떤 로그가 발생할까? 아래 쿼리는 실험 목적으로 작성한 쿼리이다.

sqls = [
	"SELECT * FROM `member` WHERE reference_id=:member_id;",
	"select * from `member` where reference_id=:member_id;",
	"select * from `member` WHERE reference_id=:member_id;",
	"SELECT * from `member` where reference_id=:member_id;"
]

대소문자만 달리하여 준비한 쿼리이며 이를 대량으로 날리게 되면 다음과 같은 로그 발생한다.

"Compiled cache size pruning from 2 item to 1"라는 로그가 발생했으며 쿼리 캐시의 크기가 조정되고 있음을 알려주고 있다. 앞서 query_cache_size를 1로 조정했기 때문에 이와 같은 로그가 발생했음을 알 수 있다. 그 옆에는 친절하게 "Increate cache size to reduce the frequency of pruning"와 같은 메시지로 cache size를 조정하라는 로그가 발생한다. 

 

 

 

마치며

단순한 실수에서 비롯된 결과로 인해 조사하게 되었지만 SqlAlchemy가 이러한 기능도 가지고 있다는 것에 흥미로웠다. 처음엔 단순히 쿼리 캐싱인 줄 알고 DBMS에서 발생하는 로그도 살펴보는 과정에서 기존에 알고 있는 "쿼리 캐싱"은 뭔가 아니겠거니 싶었다. 그렇게 잘못된 방향에 삽질한 시간이 다소 아쉽긴 하다. 또한 query_cache_size의 최적화 값이 존재하느냐라고 누군가 묻는다면 그건 시스템 규모에 따라 조정하는 범위를 찾아내는 게 최선이다라고 답할 수밖에 없을 것 같다.

 

추가로 필자가 참고했던 SqlAlchemy의 링크를 남겨놓는다.

- https://docs.sqlalchemy.org/en/20/core/connections.html#sql-caching