Go(Golang)으로 Asynchronous Non-Blocking Logger 만들기 3편

개요

Go(Golang)으로 Asynchronous Non-Blocking Logger 만들기 2편

오늘은 이전 포스팅에 이어서 테스팅에 대해서 알아볼 것이다. 먼저 기본적인 테스팅과 테스트 방법을 알아보고, 이 전 포스팅에서 만들었던 로거의 플래그를 이용해서 async 와 sync 모드에 따른 성능 차이를 비교해본다.

완성된 로거 패키지는 github 에서 소스를 보거나 아래 명령으로 받아서 사용할 수 있다.

$ go get github.com/banaconda/nb-logger@v1.0.0

기본 테스팅

Go 의 테스트는 .go 확장자 앞에 접미어로 _test 를 붙인다. 예를 들어서 logger.go 의 경우 logger_test.go 가 된다. logger_test.go 파일을 만들고, 아래와같이 기본 테스트를 만들어보자.

testing 을 import 하고, go test 를 수행하기 위해서 테스트 함수는 Test 로 시작해야하고, *testing.T 인자를 가져야한다. 

package nblogger

import (
	"fmt"
	"testing"
)

func TestSuccess(t *testing.T) {
	fmt.Printf("Success test\n")
}

func TestFatal(t *testing.T) {
	t.Fatalf("fatal test")
}

 

테스트를 실행하는 방법은 간단하다. "go test" 만 입력해주면 된다. 실행하게 되면 TestSuccess 는 성공하고, TestFatal 은 실패한 것을 볼 수 있다.

$ go test -v
=== RUN   TestSuccess
Success test
--- PASS: TestSuccess (0.00s)
=== RUN   TestFatal
    logger_test.go:21: fatal test
--- FAIL: TestFatal (0.00s)
FAIL
exit status 1
FAIL    github.com/banaconda/nb-logger  0.002s

벤치마크

먼저 모든 테스트에 사용할 파일 이름은 test.log 를 쓰고, channel 의 버퍼 사이즈는 10000 으로 고정한다.

var LogFilePath = "test.log"
var bufferSize = 100000

 

벤치마크 본체는 이렇다. "#" 1000 개 짜리 스트링을 로그로 bufferSize 만큼 쓰게 한다. 그리고 로그를 쓰기 직전부터 로그를 다 쓰고(async 모드에서는 logging server 에게 다 보내는 것 까지) 걸린 시간(milliseconds)를 리턴한다.

func benchmark(logger Logger) int64 {
	var buf []byte
	for i := 0; i < 1000; i++ {
		buf = append(buf, "#"...)
	}

	s := string(buf)

	start := time.Now()
	for i := 0; i < bufferSize; i++ {
		logger.Info(s)
	}

	return time.Since(start).Milliseconds()
}

싱글 쓰레드 벤치마크

두 테스트 모두 로거를 생성하고, 벤치마크를 돌린결과를 출력한다. Lblocking 플래그를 제외한 모든 코드는 같다.

func TestAsyncBenchmark(t *testing.T) {
	logger, err := NewLogger(LogFilePath, Info, bufferSize, Lshortfile|LstdFlags|Lmicroseconds)
	defer func() {
		logger.Close()
	}()

	if err != nil {
		t.Fatalf("%v", err)
	}

	os.Remove(LogFilePath)
	fmt.Printf("Async result: %d milis\n", benchmark(logger))
}

func TestSyncBenchmark(t *testing.T) {
	logger, err := NewLogger(LogFilePath, Info, bufferSize, Lshortfile|LstdFlags|Lmicroseconds|Lblocking)
	defer func() {
		logger.Close()
	}()

	if err != nil {
		t.Fatalf("%v", err)
	}

	os.Remove(LogFilePath)
	fmt.Printf("Sync result: %d milis\n", benchmark(logger))
}

 

출력 결과를 보면 약 0.2 초 정도 차이가 나는 것을 볼 수 있다. Sync 모드일 때에 피해 30~40% 가량 줄어든 속도를 볼 수 있다.

$ go test -v
=== RUN   TestAsyncBenchmark
Async result: 330 milis
--- PASS: TestAsyncBenchmark (0.33s)
=== RUN   TestSyncBenchmark
Sync result: 506 milis
--- PASS: TestSyncBenchmark (0.51s)
PASS
ok      github.com/banaconda/nb-logger  0.854s

 

멀티 쓰레드 벤치 마크

Async 로거는 멀티 쓰레드 일때 더 극적인 차이를 보여줄 것이다. 기본적으로 여러 쓰레드가 하나의 IO 에 병목 되는 것보다. channel 에 쓰고 리턴하게 되면 응답 시간이 빨라 질 것이다.

먼저 멀티 쓰레드 테스트 전에 계산을 위한 아래 코드를 보자. 최소 최대 값과 평균치를 리턴하는 것이다. T constraints.Integer 는 go 에 최근에 들어간 Generic 인데 이 부분은 추후 알아보도록 하자.

func minMaxAvg[T constraints.Integer](array []T) (T, T, T) {
	var max T = array[0]
	var min T = array[0]
	var avg T = 0
	for _, value := range array {
		if max < value {
			max = value
		}
		if min > value {
			min = value
		}

		avg += value
	}

	avg /= T(len(array))
	return min, max, avg
}

 

자 이제 본격적으로 멀티쓰레드 로깅 벤치 마크 코드를 보자. 20개의 쓰레드를 만들어서 동시에 bechmark 함수를 수행하고 결과를 저장한다. 그리고 minMaxAvg 함수를 통해서 결과를 리턴한다.

func TestAsyncThreadedBenchmark(t *testing.T) {
	num := 20
	wg := sync.WaitGroup{}
	wg.Add(num)

	result := make([]int64, num)
	for i := 0; i < num; i++ {
		logger, err := NewLogger(fmt.Sprintf("%s.%d", LogFilePath, i), Info, bufferSize, LstdFlags|Lmicroseconds)
		defer func() {
			logger.Close()
		}()

		if err != nil {
			t.Fatalf("%v", err)
		}
		go func(index int) {
			result[index] = benchmark(logger)
			wg.Done()
		}(i)
	}
	wg.Wait()

	for i := 0; i < num; i++ {
		os.Remove(fmt.Sprintf("%s.%d", LogFilePath, i))
	}

	min, max, avg := minMaxAvg(result)
	fmt.Printf("AsyncThreaded min=%d, max=%d, avg=%d\n", min, max, avg)
}

func TestSyncThreadedBenchmark(t *testing.T) {
	num := 20
	wg := sync.WaitGroup{}
	wg.Add(num)

	result := make([]int64, num)
	for i := 0; i < num; i++ {
		logger, err := NewLogger(fmt.Sprintf("%s.%d", LogFilePath, i), Info, bufferSize, LstdFlags|Lmicroseconds|Lblocking)
		defer func() {
			logger.Close()
		}()

		if err != nil {
			t.Fatalf("%v", err)
		}
		go func(index int) {
			result[index] = benchmark(logger)
			wg.Done()
		}(i)
	}
	wg.Wait()

	for i := 0; i < num; i++ {
		os.Remove(fmt.Sprintf("%s.%d", LogFilePath, i))
	}

	min, max, avg := minMaxAvg(result)
	fmt.Printf("SyncThreaded min=%d, max=%d, avg=%d\n", min, max, avg)
}

 

결과를 보면 확연히 차이가 난다는 것을 볼 수 있다. Async 모드일 경우에 평균 응답시간이 823 millis 인데 반해 Async 모드의 경우 6673 millis 이다. 거의 8배가 차이난다고 볼 수 있다.

그런데 한 가지 이상한 점이 있다. Async 모드일 때 실제 최대 응답 시간은 870milis 인데 테스트 종료 시간은 2.55 초나 걸렸다. Testcase 에서 logging server 가 모든 로그를 파일에 쓸 때 까지 기다려줘서 그렇다. 실제로 로그가 파일에 쓰여지기 까지 걸리는 시간은 2.55 초 인 것이다. 그래도 여전히 Sync 모드에 비해서는 빠른 것을 알 수 있다.

$ go test -v
=== RUN   TestAsyncThreadedBenchmark
AsyncThreaded min=720, max=870, avg=823
--- PASS: TestAsyncThreadedBenchmark (2.55s)
=== RUN   TestSyncThreadedBenchmark
SyncThreaded min=4364, max=7812, avg=6673
--- PASS: TestSyncThreadedBenchmark (7.81s)
PASS
ok      github.com/banaconda/nb-logger  12.512s

정리

이 번 포스팅에서 테스팅 모듈을 작성하는 법은 배웠다. 보통 테스팅에서는 동등 분할, 경계값 분석, 결정 테이블, 상태 전이, 유즈 케이스 등 다양한 테스팅 방법이 있지만 오늘은 기본적으로 테스트 코드를 작성하는 법을 배웠고, 이를 이용해서 Async 모드와 Sync 모드 간의 응답 시간 차이를 보았다.