회사에서 마주친 에러

$ [mysql] 2024/03/11 18:37:09 packets.go:122: closing bad idle connection: unexpected read from socket
$ [mysql] 2024/03/11 18:37:09 packets.go:122: closing bad idle connection: unexpected read from socket

Batch 처리를 요하는 작업들이 모여있는 인스턴스에서 발생했다.

비즈니스 로직 자체에는 문제가 없었고, 커넥션 관련 설정도 디폴트로 되어있는 상황이었다.

사실 서비스 전체적으로 보면 MySQL 자체를 많이 쓰는 상황은 아니었고, 동시에 실행되는 job 이 MySQL 기반이었어서 커넥션 관련 문제로 좁혀놓고 디버깅을 시작했다.

이 과정에서 새롭게 알게된 사실에 대한 기록.

gorm 은 sql 패키지의 DB 객체를 wrapping 하고 있다.

sql.DB 구조체에는 Stats 라는 메소드가 있다.

var db := &sql.DB{}
        
stats := db.Stats() // stats ?

Stats 구조체는 아래와 같이 생겼다.

// DBStats contains database statistics.
type DBStats struct {
    MaxOpenConnections int // Maximum number of open connections to the database.

    // Pool Status
    OpenConnections int // The number of established connections both in use and idle.
    InUse           int // The number of connections currently in use.
    Idle            int // The number of idle connections.

    // Counters
    WaitCount         int64         // The total number of connections waited for.
    WaitDuration      time.Duration // The total time blocked waiting for a new connection.
    MaxIdleClosed     int64         // The total number of connections closed due to SetMaxIdleConns.
    MaxIdleTimeClosed int64         // The total number of connections closed due to SetConnMaxIdleTime.
    MaxLifetimeClosed int64         // The total number of connections closed due to SetConnMaxLifetime.
}

위에서 부터 읽어보자.

• 최대 커넥션 개수

• 현재 열려있는 커넥션 개수

• 사용중인 커넥션 개수

• 유휴 커넥션 개수

• 커넥션을 대기하는 개수

• 총 대기 시간

• SetMaxIdleConns 로 인해 닫힌 유휴 커넥션 개수

• SetConnMaxIdleTime 로 인해 닫힌 유휴 커넥션 개수

• SetConnMaxLifetime 로 인해 닫힌 커넥션 개수

go 의 *sql.DB 구조체에서는 아래와 같이 설정들을 커스터마이징 할 수 있다.

// 값은 예시 
db.SetConnMaxLifetime(time.Hour)
db.SetMaxIdleConns(100)
db.SetConnMaxIdleTime(time.Hour)
db.SetMaxOpenConns(100)

참고로 기본값은 0으로 들어가는데, 이 경우 제한이 없다는 말이다.

물론 제한이 없다고해서 커넥션을 무한대로 만들어낼수는 없다. 또한 어지간한 경우에는 비즈니스 로직을 먼저 검토해보는 것이 좋다.

GORM 에서는 아래와 같이 커스터마이징 할 것을 권고하고 있다.

// Get generic database object sql.DB to use its functions
sqlDB, err := db.DB()
// SetMaxIdleConns sets the maximum number of connections in the idle connection 
pool.sqlDB.SetMaxIdleConns(10)
// SetMaxOpenConns sets the maximum number of open connections to the 
database.sqlDB.SetMaxOpenConns(100)
// SetConnMaxLifetime sets the maximum amount of time a connection may be reused.
sqlDB.SetConnMaxLifetime(time.Hour)

위에서 언급했듯이, 커넥션 관련 문제로 보고 모니터링을 시작했다.

주기적으로 Stats 를 찍어봤을때 MaxConn 이 많아도 20을 넘어가지 않았고, 특이사항으로 보기에는 어려웠다.

다만 특정 작업이 실행될때마다 OpenConn 이 늘어나고 줄어들지 않는 문제가 발견되었다.

이유는 다음과 같았다.

var db := &gorm.DB{}
    
    
db.Transaction(func(tx *gorm.DB) error {		
    db.Where("~~~").Find(&Something{})
})

트랜잭션 안에서 트랜잭션 대신 다른 커넥션을 계속해서 집어오는 레거시가 있었다.

이러한 Job 이 실행되고 나면 커넥션 개수가 하나 늘어나는데, 이런 작업이 몇 개가 있다보니 일종의 커넥션 누수가 발생한 것으로 추정했다.

특이한 것은 강제로 재실행을 했을때 SavePoint 로그가 찍히는 것도 아니고, 에러가 찍힌 뒤에 실행이 되지 않는 경우와 실행이 되는 경우 등 불규칙적인 행태를 보인다는 것이다.

우선 해당 레거시를 모두 수정하고, MaxConnLifetime 을 한 시간으로 설정해서 계속해서 좀비 커넥션이 계속해서 살아남는 것을 방지했다.

아직 작업은 못했지만 추후 커넥션 풀에서 하나씩 폴링해서 받아오는 구조로 변경을 고려중이다.

https://github.com/go-sql-driver/mysql/issues/1120 https://gorm.io/docs/generic_interface.html

회사에서 마주친 에러

$ [mysql] 2024/03/11 18:37:09 packets.go:122: closing bad idle connection: unexpected read from socket
$ [mysql] 2024/03/11 18:37:09 packets.go:122: closing bad idle connection: unexpected read from socket

Batch 처리를 요하는 작업들이 모여있는 인스턴스에서 발생했다.

비즈니스 로직 자체에는 문제가 없었고, 커넥션 관련 설정도 디폴트로 되어있는 상황이었다.

사실 서비스 전체적으로 보면 MySQL 자체를 많이 쓰는 상황은 아니었고, 동시에 실행되는 job 이 MySQL 기반이었어서 커넥션 관련 문제로 좁혀놓고 디버깅을 시작했다.

이 과정에서 새롭게 알게된 사실에 대한 기록.

gorm 은 sql 패키지의 DB 객체를 wrapping 하고 있다.

sql.DB 구조체에는 Stats 라는 메소드가 있다.

var db := &sql.DB{}
        
stats := db.Stats() // stats ?

Stats 구조체는 아래와 같이 생겼다.

// DBStats contains database statistics.
type DBStats struct {
    MaxOpenConnections int // Maximum number of open connections to the database.

    // Pool Status
    OpenConnections int // The number of established connections both in use and idle.
    InUse           int // The number of connections currently in use.
    Idle            int // The number of idle connections.

    // Counters
    WaitCount         int64         // The total number of connections waited for.
    WaitDuration      time.Duration // The total time blocked waiting for a new connection.
    MaxIdleClosed     int64         // The total number of connections closed due to SetMaxIdleConns.
    MaxIdleTimeClosed int64         // The total number of connections closed due to SetConnMaxIdleTime.
    MaxLifetimeClosed int64         // The total number of connections closed due to SetConnMaxLifetime.
}

위에서 부터 읽어보자.

• 최대 커넥션 개수

• 현재 열려있는 커넥션 개수

• 사용중인 커넥션 개수

• 유휴 커넥션 개수

• 커넥션을 대기하는 개수

• 총 대기 시간

• SetMaxIdleConns 로 인해 닫힌 유휴 커넥션 개수

• SetConnMaxIdleTime 로 인해 닫힌 유휴 커넥션 개수

• SetConnMaxLifetime 로 인해 닫힌 커넥션 개수

go 의 *sql.DB 구조체에서는 아래와 같이 설정들을 커스터마이징 할 수 있다.

// 값은 예시 
db.SetConnMaxLifetime(time.Hour)
db.SetMaxIdleConns(100)
db.SetConnMaxIdleTime(time.Hour)
db.SetMaxOpenConns(100)

참고로 기본값은 0으로 들어가는데, 이 경우 제한이 없다는 말이다.

물론 제한이 없다고해서 커넥션을 무한대로 만들어낼수는 없다. 또한 어지간한 경우에는 비즈니스 로직을 먼저 검토해보는 것이 좋다.

GORM 에서는 아래와 같이 커스터마이징 할 것을 권고하고 있다.

// Get generic database object sql.DB to use its functions
sqlDB, err := db.DB()
// SetMaxIdleConns sets the maximum number of connections in the idle connection 
pool.sqlDB.SetMaxIdleConns(10)
// SetMaxOpenConns sets the maximum number of open connections to the 
database.sqlDB.SetMaxOpenConns(100)
// SetConnMaxLifetime sets the maximum amount of time a connection may be reused.
sqlDB.SetConnMaxLifetime(time.Hour)

위에서 언급했듯이, 커넥션 관련 문제로 보고 모니터링을 시작했다.

주기적으로 Stats 를 찍어봤을때 MaxConn 이 많아도 20을 넘어가지 않았고, 특이사항으로 보기에는 어려웠다.

다만 특정 작업이 실행될때마다 OpenConn 이 늘어나고 줄어들지 않는 문제가 발견되었다.

이유는 다음과 같았다.

var db := &gorm.DB{}
    
    
db.Transaction(func(tx *gorm.DB) error {		
    db.Where("~~~").Find(&Something{})
})

트랜잭션 안에서 트랜잭션 대신 다른 커넥션을 계속해서 집어오는 레거시가 있었다.

이러한 Job 이 실행되고 나면 커넥션 개수가 하나 늘어나는데, 이런 작업이 몇 개가 있다보니 일종의 커넥션 누수가 발생한 것으로 추정했다.

특이한 것은 강제로 재실행을 했을때 SavePoint 로그가 찍히는 것도 아니고, 에러가 찍힌 뒤에 실행이 되지 않는 경우와 실행이 되는 경우 등 불규칙적인 행태를 보인다는 것이다.

우선 해당 레거시를 모두 수정하고, MaxConnLifetime 을 한 시간으로 설정해서 계속해서 좀비 커넥션이 계속해서 살아남는 것을 방지했다.

아직 작업은 못했지만 추후 커넥션 풀에서 하나씩 폴링해서 받아오는 구조로 변경을 고려중이다.

https://github.com/go-sql-driver/mysql/issues/1120 https://gorm.io/docs/generic_interface.html