1. 데이터 다운로드 이슈

9월 중순경, 파트너사에서 대시보드에서 이벤트로그가 다운로드 실패하는 CS가 인입되었다.

바로 재현해본 결과, 대시보드에서 적정 기간을 설정하여 데이터 저장 시 응답으로 게이트웨이 타임아웃(504)을 받고 있었다.

 

https://developer.mozilla.org/ko/docs/Web/HTTP/Status/504

504 Gateway Timeout - HTTP | MDN

문서에 따르면 504는 웹서버 혹은 프록시에서 발생하는 것이다. 해당 요청을 받았을 때, 우리 서버에서는 실제로 쿼리가 실행되는 것을 확인했으므로, dashboard proxy server 가 504를 응답하는 것으로 확인했다.

그런데, 그럼 dash proxy server 에 우리서버가 응답을 계속 안주고 있다는 의미였고, 해당 요청이 요구하는 데이터는 이벤트 발생시각이 PK 로 걸린 테이블로, 범위조회쿼리 자체가 느릴리는 없다고 생각하였다. 

 

해당 다운로드 API 의 핸들러 모의 구현은 아래와 같았다.

func DownloadData(c *fiber.Ctx) error {
	req := EventDataDownloadRequestDTO{}
	if err := c.QueryParser(&req); err != nil {
		return c.Status(http.StatusBadRequest)
	}

	// validate reqeust... (생략)
    
        // [1]: get rows to scan at dest
        rows, err := m.replicaDB.Raw(fmt.Sprintf(`
        SELECT CONVERT_TZ(event_at, 'UTC', 'Asia/Seoul') event_at, event_name, user_id, metadata
        FROM event_table
        WHERE event_at >= %s and event_at <= %s
        `, req.StartTime, req.EndTime).
        .Order("event_at desc").
        Rows()

	// set header
	c.Set("Content-Type", "text/csv")
	c.Set("Connection", "keep-alive")
	c.Set("Transfer-Encoding", "chunked")

	// open stream writer
	c.Context().SetBodyStreamWriter(func(w *bufio.Writer) {
		defer rows.Close()

        	// define columns to write on csv header.
		columns := (생략)

		if _, err := fmt.Fprint(w, strings.Join(columns, ",")+"\n"); err != nil {
			return
		}

		values := make([]string, len(columns))
		valuePtrs := make([]interface{}, len(columns))
		for rows.Next() {
			for i := range columns {
				valuePtrs[i] = &values[i]
			}
			
            		// [2]: fetch data
			if err := rows.Scan(valuePtrs...); err != nil {
				break
			}

			// [3]: write data on writer interface
			if _, err := fmt.Fprint(w, strings.Join(values, ";")+"\n"); err != nil {
				break
			}

			// [4]: client closed connection
			if err := w.Flush(); err != nil {
				break
			}
		}
	})

	return nil
}

위 핸들러에서 [1] ~ [4] 까지중 실제 병목이 어디인지 확인해본 결과, [1] 이 병목인 것을 확인하였다.

실제 쿼리는 아래와 같다

SELECT CONVERT_TZ(event_at, 'UTC', 'Asia/Seoul') event_at, event_name, user_id, metadata
FROM event_table
WHERE event_at >= req.StartTime and event_at <= req.EndTime
ORDER BY event_at desc

실행계획을 분석해본 결과, extra 항목에 Using filesort 를 확인할 수 있었고, PK를 활용하지 못하는 것을 알 수 있었다.

즉, 쿼리 자체가 비효율적이라는 것을 알 수 있었다.

 

이는 CONVERT_TZ 의 결과로 얻은 event_at 컬럼으로 where 절 및 order 절이 실행되기 때문이었고, 위 쿼리에서 event_at 을 select 한 후 별도의 컬럼명(event_at_kst)으로 조회하는 것으로 PK 를 활용하도록 유도해서 해결하였다. (이경우 backward_index_scan)

 

 

## mysql 에서 쿼리 실행 순서

위 쿼리의 실행 순서는 다음과 같다

FROM(어느 테이블에서) -> WHERE(어느 조건에 맞는) -> SELECT(레코드중 어떤 컬럼을) -> ORDER(컬럼 기준으로 정렬)

즉 SELECT 전후로 event_at 이 CONVERT_TZ 함수가 적용되기 전인지 후인지 결정된다. 따라서 WHERE 절의 event_at 은 PK, ORDER 절의 event_at 은 PK와 관련없는 함수실행 결과 얻은 새로운 컬럼이다.

새로운 컬럼에 대해서는 인덱스가 없기 때문에 정렬하기 위해 filesort가 실행되고, 이벤트 테이블은 사이즈가 매우크기 때문에 큰 부하가 된다.

 

## filesort

레코드 정렬 시 적절한 인덱스를 찾지 못한 경우, MySQL 서버는 filesort를 사용하여 레코드를 정렬한다.

filesort 는 조회된 레코드를 정렬용 메모리 버퍼(sort buffer)에 복사한 후 퀵 소트 혹은 힙 소트 로 정렬한 후 클라이언트에 반환한다.

 

## backward index scan

쿼리가 인덱스를 활용할 수 있지만 인덱스 저장 순서와 요청 쿼리 순서가 다를 때 스캔하는 방식.

인덱스 트리의 리프노드를 조회하는 순서는 일반 index scan과 동일하지만, 리프노드 페이지 안에서 데이터를 조회할 때는 좀 더 복잡하게 맨 뒤의 레코드부터 읽기 때문에 부하가 더 크다. backward index scan 이 자주 발생하는 경우 인덱스 생성시 정렬 순서를 반대로 지정하여 생성하면 된다. https://tech.kakao.com/2018/06/19/mysql-ascending-index-vs-descending-index/ 에 따르면 1천2백여 건 레코드를 조회할 때 forward vs backward 의 성능차이가 1.2초 정도, 퍼센테이지로는 29% 정도라고 한다.

 

## 사후

간단해 보이는 쿼리 병목이었지만 처음 문제를 마딱뜨리고 원인 파악까지 꽤 시간이 지체되었다. 추석 연휴전에 발생한 이슈이고, 파트너사 에서는 매일 이벤트로그를 다운받아야하는 니즈가 있었기 때문에, 원인 파악을 못했던 당시에 팀에서는 해당 테이블을 s3에 적재하는 파이프라인을 (임시적으로) 생성하여 매일 아침 슬랙봇으로 s3링크를 전달하는 방식으로 해결했다. 하지만 추석 연휴 이후, 슬랙봇 자동업로드에 대한 요구사항이 일일 1회 -> 3회로 늘어나고 임시적으로 생성한 파이프라인을 내려야한다는 점(다른팀의 기술부채), 애초에 이벤트로그 테이블이 정규화 되지 않아 불필요하게 많은 용량을 차지하고 있는 점 등으로 현재는 다른 OLAP db를 도입하여 경량화 해서 s3에 적재 및 제공하였다. 이 작업은 우리팀에서 하지 않고 데이터팀에서 리드하였다. 이 작업 또한 임시적으로 궁극적으로는 우리 서버에서 해당 OLAP db 를 서비스의 db로 사용, 직접 해당 db의 정규화된 테이블에 적재하여야한다.