저는 과거의 악몽같은 경험 때문에 sql connection을 다룰 때 항상 조심합니다. 한 프로젝트에서, 10번 정도의 request 이후에는 mysql이 매우 매우 느리게 (대략 20초 정도 지연해서) 동작하는 현상이 발생했었는데, 그게 바로 sql connection을 실수로 닫아주지 않아서 생긴 일이었기 때문입니다.
다만 자세한 원인은 기억이 나지 않았습니다. 이제와서 생각하는 것이지만 mysql의 max_connections 기본값은 150인데, 왜 150번의 request가 아니라 10번만에 뻗었을까요...? 궁금증을 못 참고 당시 진행하던 프로젝트의 git repo를 다시 다운 받고, 해당 오류가 났던 커밋으로 git reset한 뒤 오류를 재생산해보았습니다.
오류의 정확한 원인은 다음과 같았습니다.
오류의 원인: SqlSession에 대한 잘못된 이해
공식 문서: Never keep references to a SqlSession instance in a static field or even an instance field of a class.
- 저는 당시 멘토님들의 교육적인 의도를 따라서 Spring을 사용하지 않고 mybatis의 SqlSession을 SqlSessionFactory를 통해 직접 생성했습니다.
- 시간에 쫓기던 저는 SqlSession이 뭔지 제대로 알아보지 않고, PostRepository의 생성자에서 SqlSession을 생성한 다음, 이를 재사용하기 위해 PostRepository 클래스의 필드에 담았습니다. 사용한 후에 바로 close를 해줘야 한다는 사실을 몰랐습니다.
- MVC 패턴을 잘 몰랐던 저는 컨트롤러에서 request를 받을 때마다 서비스에서 PostRepository 인스턴스를 매번 생성했습니다!
- Mybatis의
poolMaximumActiveConnections는 기본값이 10으로 설정되어 있습니다. - 따라서 Request를 10번 정도만 날려줘도 뻗어버리는 것이었습니다....
06:16:57.062 [main] DEBUG org.apache.ibatis.datasource.pooled.PooledDataSource -- Waiting as long as 20000 milliseconds for connection.당시에 문제를 해결하지 못한 이유
- 구글에 Mybatis Sqlsession에 대해 검색하면 mybatis에 대한 페이지 대신 mybatis-spring에 대한 페이지가 나왔는데, 이 둘은 페이지 생김새는 비슷해도 내용이 많이 달랐습니다.
- 공식 Mybatis 문서는 검색이 불가능했기 때문에, 제가 원하는 내용을 찾기 위해서는 모든 문서를 다 읽어봐야 했는데, 제가 찾는 내용이 많은 페이지 어딘가에 있을 거라는 확신조차 할 수 없었습니다. (하지만 Get Started 하단부에 제가 있었습니다...)
상당히 당황스러운 케이스였습니다.
번외: 오류를 찾기 힘들었던 이유
해당 오류 메세지는 logging.level = debug 으로 설정된 상태에서 로그를 출력해야만 보이는데, 내용이 비어 있는 logback.xml 파일이 프로젝트에 생성이 되어 있으면 log가 출력이 전혀 되지 않는 것을 몰랐습니다. logback.xml 파일을 지우니까 정상 동작하기 시작했습니다.
결론
- 과거에 10번의 Connection 만으로 Mysql이 느려지던 문제는 사실 Mybatis의 PooledDataSource의 poolMaximumActiveConnections 값이 10이었기 때문입니다.
- 공식 문서를 꼭 읽고, 앞으로 적어도 Get Started, Introduction 등의 문서는 아무리 길더라도 정독하겠습니다.
vimkim