인연

최근 읽기<>(유금량, 2021.1) 본 시리즈 노트는 golang으로 연습할 예정

케이스 요구사항(채팅 서버)

사용자는 서버에 연결할 수 있습니다..

사용자는 자신의 사용자 이름을 설정할 수 있습니다..

사용자는 서버에 메시지를 보낼 수 있고 서버도 다른 사용자에게 이 메시지를 방송할 수 있다..

대상(Day 3)

Day2에서 기능성 인코딩을 기본적으로 완성했고 테스트도 통과했습니다. 오늘 압축 측정을 시도하고 메모리와 루틴 유출이 있는지 진단합니다

프로세스

단원 테스트 코드를 수정하고 클라이언트를 50개로 늘리며 클라이언트당 1-3초에 메시지를 보냅니다

ILOGging Service를 추가하여 전역 로그를 쉽게 수집할 수 있습니다

pprof 패키지의api를 사용하여 heap와goroutine의 진단 로그를 채집합니다

gotool pprof를 사용하여 메모리와 루틴 유출이 있는지 관찰한다

단원 테스트는 항상failed이고 몇몇 tChatClient가 있으며 서버가 로그를 닫지 않았습니다

루틴 진단 로그를 보니 루틴 유출이 있었다

tChatClient에 더 자세한 함수 호출 로그를 추가했는데 closeChan 채널 쓰기가 막혀서 발생한 것을 발견했습니다

루틴 유출된 버그를 복구하고 클라이언트를 500개로 늘리고 여러 차례의 테스트를 실시하여 메모리와 루틴 유출이 존재하는지 관찰한다

단원 테스트

ChatServer_test.go

클라이언트의 병발 수를 증가하고 pprof 진단을 추가합니다

진단 ILOGging Service.AllLogs(), 모든 클라이언트가 연결/분리된 폐쇄 루프를 완료했는지 판단합니다

package chat_server

import (
    "fmt"
    cs "learning/gooop/chat_server"
    "math/rand"
    "os"
    "runtime"
    "runtime/pprof"
    "strings"
    "sync"
    "testing"
    "time"
)

func Test_ChatServer(t *testing.T) {
    fnAssertTrue := func(b bool, msg string) {
        if !b {
            t.Fatal(msg)
        }
    }

    // create dump file
    memProfile, err := os.Create("/home/ioly/chat_server_mem.profile")
    if err != nil {
        t.Fatal(err)
    }
    cpuProfile, err := os.Create("/home/ioly/chat_server_cpu.profile")
    if err != nil {
        t.Fatal(err)
    }
    rtnProfile, err := os.Create("/home/ioly/chat_server_routine.profile")
    if err != nil {
        t.Fatal(err)
    }
    err = pprof.StartCPUProfile(cpuProfile)
    if err != nil {
        t.Fatal(err)
    }
    defer pprof.StopCPUProfile()

    port := 3333
    server := cs.NewChatServer()
    err = server.Open(port)
    if err != nil {
        t.Fatal(err)
    }

    clientCount := 500
    wg := &sync.WaitGroup{}

    rnd := rand.New(rand.NewSource(time.Now().UnixNano()))
    address := fmt.Sprintf("localhost:%v", port)
    for i := 0;i < clientCount;i++ {
        err, client := cs.DialChatClient(address)
        if err != nil {
            t.Fatal(err)
        }

        id := fmt.Sprintf("c%02d", i)
        //client.RecvHandler(func(client cs.IChatClient, msg cs.IMsg) {
        //    t.Logf("%v recv: %v
", id, msg)
        //})

        wg.Add(1)
        go func() {
            client.SetName(id)
            client.Send(&cs.NameMsg{id })

            n := 0
            duration := rnd.Intn(3) + 1
            for range time.Tick(time.Duration(duration) * time.Second) {
                client.Send(&cs.ChatMsg{id, fmt.Sprintf("msg %02d from %v", n, id) })

                n++
                if n > 10 {
                    break
                }
            }

            client.Close()
            wg.Done()
        }()
    }

    // wait and set status
    done := []bool{false}
    go func() {
        wg.Wait()
        done[0] = true
    }()

    // print passed seconds
    passedSeconds := 0
    for range time.Tick(time.Second) {
        passedSeconds++
        t.Logf("%v seconds passed", passedSeconds)

        if done[0] {
            break
        }
    }

    time.Sleep(5*time.Second)
    server.Close()

    // dump heap file
    runtime.GC()
    err = pprof.Lookup("heap").WriteTo(memProfile, 0)
    if err != nil {
        t.Fatal(err)
    }
    err = pprof.Lookup("goroutine").WriteTo(rtnProfile, 0)
    if err != nil {
        t.Fatal(err)
    }

    // check server logs
    logs := cs.Logging.AllLogs()
    fnHasLog := func(log string) bool {
        for _,it := range logs {
            if strings.Contains(it, log) {
                return true
            }
        }
        return false
    }
    for i := 0;i < clientCount;i++ {
        msg := fmt.Sprintf("tChatClient.postConnClosed, c%02d, serverFlag=false", i)
        fnAssertTrue(fnHasLog(msg), "expecting log: " + msg)

        msg = fmt.Sprintf("tChatServer.handleIncomingConn, clientCount=%v", i + 1)
        fnAssertTrue(fnHasLog(msg), "expecting log: " + msg)

        msg = fmt.Sprintf("tChatClient.postConnClosed, c%02d, serverFlag=true", i)
        fnAssertTrue(fnHasLog(msg), "expecting log: " + msg)

        msg = fmt.Sprintf("tChatServer.handleClientClosed, c%02d", i)
        fnAssertTrue(fnHasLog(msg), "expecting log: " + msg)
    }
}

테스트 출력

동시 500, 끝 부분만

tChatClient.beginWrite, write error, c496, serverFlag=true
tChatClient.beginWrite, 

루틴 유출 진단(복구 전)

누설 시 진단 로그 (병발 50)

$ go tool pprof ~/chat_server_routine.profile 
File: chat_server.test
Type: goroutine
Time: Mar 9, 2021 at 9:12am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 4, 100% of 4 total
Showing top 10 nodes out of 21
      flat  flat%   sum%        cum   cum%
         3 75.00% 75.00%          3 75.00%  runtime.gopark
         1 25.00%   100%          1 25.00%  runtime/pprof.runtime_goroutineProfileWithLabels
         0     0%   100%          1 25.00%  command-line-arguments.Test_ChatServer
         0     0%   100%          1 25.00%  learning/gooop/chat_server.(*tChatClient).beginWrite
         0     0%   100%          1 25.00%  learning/gooop/chat_server.(*tChatClient).closeConn
         0     0%   100%          1 25.00%  main.main
         0     0%   100%          1 25.00%  runtime.chanrecv
         0     0%   100%          1 25.00%  runtime.chanrecv1
         0     0%   100%          1 25.00%  runtime.chansend
         0     0%   100%          1 25.00%  runtime.chansend1
(pprof) 

closeConn 함수 막힘 보이기

func (me *tChatClient) closeConn() {
    if !atomic.CompareAndSwapInt32(&me.closeFlag, 0, 1) {
        return
    }

    Logging.Logf("tChatClient.closeConn, %v, serverFlag=%v", me.name, me.serverFlag)
    me.closeChan 

코드로 볼 때closeConn 함수가 막히는 것은 단지 하나의 가능성일 뿐이다. 바로closeChan이 막히는 것이다.이 원인은 좀 이상하다. 왜냐하면 이미 atomic를 넣었기 때문이다.Compare AndSwap Int32 보호는 여전히 막혀 있습니다. 유일한 원인은 병발 환경에서closeChan이 아직 읽기 시작하지 않아서 쓸 수 없습니다.

루틴 유출 복구

쓰기 차단을 초래하는closeChan에 버퍼를 추가하는 것입니다. 크기는closeConn 함수와 같은 호출 가능한 입구 수량입니다.

func openChatClient(conn net.Conn, serverFlag bool) IChatClient {
    it := &tChatClient{
        conn: conn,
        openFlag: 0,
        closeFlag: 0,
        serverFlag: serverFlag,

        closeChan: make(chan bool, 3),    //  closeChan !!
        sendChan: make(chan IMsg, gMaxPendingSend),

        name: "anonymous",
        sendLogs: []IMsg{},
        dropLogs: []IMsg{},
        recvLogs: []IMsg{},
    }
    it.open()
    return it
}

루틴 유출 진단(복구 후)

복구 후 500까지 확대 및 발송하였으나 뚜렷한 루틴 누출이 발견되지 않았습니다.

$ go tool pprof ~/chat_server_routine.profile 
File: chat_server.test
Type: goroutine
Time: Mar 9, 2021 at 9:28am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 3, 100% of 3 total
Showing top 10 nodes out of 17
      flat  flat%   sum%        cum   cum%
         2 66.67% 66.67%          2 66.67%  runtime.gopark
         1 33.33%   100%          1 33.33%  runtime/pprof.runtime_goroutineProfileWithLabels
         0     0%   100%          1 33.33%  command-line-arguments.Test_ChatServer
         0     0%   100%          1 33.33%  main.main
         0     0%   100%          1 33.33%  runtime.chanrecv
         0     0%   100%          1 33.33%  runtime.chanrecv1
         0     0%   100%          1 33.33%  runtime.main
         0     0%   100%          1 33.33%  runtime/pprof.(*Profile).WriteTo
         0     0%   100%          1 33.33%  runtime/pprof.profileWriter
         0     0%   100%          1 33.33%  runtime/pprof.writeGoroutine
(pprof) 

(end)