最近在線上發現一塊代碼邏輯在執行N次耗時波動很大1ms~800ms,最開始以為是gc的問題,對代碼進行逃逸分析,看哪些變量被分配到堆上了,后來發現是並發編程時對一個切片並發的寫,導致存在競爭,類似下面的代碼
func main() {
//var count int
array := make([]int, 100000)
wg := new(sync.WaitGroup)
for i := 0; i < 10; i++ {
wg.Add(1)
go func(a []int) {
now := time.Now()
print(a)
fmt.Println("耗時:", time.Since(now))
wg.Done()
}(array)
}
wg.Wait()
}
func print(array []int) {
array[0] = 1
array[1] = 1
for i := 0; i < len(array); i++ {
}
//fmt.Println(array)
}
output:
耗時: 85.532µs
耗時: 49.543µs
耗時: 53.306µs
耗時: 53.365µs
耗時: 47.73µs
耗時: 48.098µs
耗時: 70.815µs
耗時: 71.15µs
耗時: 89.213µs
耗時: 60.797µs
首先試一試逃逸分析:
go build -gcflags '-m -l' main.go
./main.go:27:20: print array does not escape
./main.go:11:15: make([]int, 100000) escapes to heap
./main.go:12:11: new(sync.WaitGroup) escapes to heap
./main.go:15:13: make([]int, 100000) escapes to heap
./main.go:17:6: func literal escapes to heap
./main.go:17:6: func literal escapes to heap
./main.go:20:16: "耗時:" escapes to heap
./main.go:20:37: time.Since(now) escapes to heap
./main.go:21:4: leaking closure reference wg
./main.go:17:15: main.func1 a does not escape
./main.go:20:15: main.func1 ... argument does not escape
結論:切片array由於size太大了被分配到堆上了,字符串"耗時:"被分配到堆上,這里分配到堆上的變量被頻繁創建地有newA和字符串"耗時:",newA可以采用變量池sync.Pool解決,字符串應該寫成常量形式
耗時47us~89us,很不穩定,對其進行競爭檢測
運行命令
go run -race main.go
output:
==================
WARNING: DATA RACE
Write at 0x00c420092000 by goroutine 7:
main.print()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:26 +0x49
main.main.func1()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:17 +0x8c
Previous write at 0x00c420092000 by goroutine 6:
main.print()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:26 +0x49
main.main.func1()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:17 +0x8c
Goroutine 7 (running) created at:
main.main()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:15 +0xe3
Goroutine 6 (running) created at:
main.main()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:15 +0xe3
==================
耗時: 58.625µs
==================
WARNING: DATA RACE
Write at 0x00c420092008 by goroutine 7:
main.print()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:27 +0x6d
main.main.func1()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:17 +0x8c
Previous write at 0x00c420092008 by goroutine 6:
main.print()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:27 +0x6d
main.main.func1()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:17 +0x8c
Goroutine 7 (running) created at:
main.main()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:15 +0xe3
Goroutine 6 (running) created at:
main.main()
/Users/qianxiaoli/work/mygopath/src/testpprof/bug/main.go:15 +0xe3
==================
結論:
顯然並發代碼存在競爭,print函數對array並發寫操作導致競爭,執行耗時變長。由於切片在拷貝時,底層的數組還是同一個,所以並發寫同一個數組會產生競爭。
將代碼加入變量池及切片拷貝
var arrayPool = sync.Pool{
New: func() interface{} {
a := make([]int, 2)
return a
},
}
func main() {
array := make([]int, 2)
wg := new(sync.WaitGroup)
for i := 0; i < 10000; i++ {
wg.Add(1)
newA := arrayPool.Get().([]int)
copy(newA, array)
go func(a []int) {
now := time.Now()
print(a)
fmt.Println("耗時:", time.Since(now))
wg.Done()
}(newA)
}
wg.Wait()
}
func print(array []int) {
array[0] = 1
array[1] = 1
for i := 0; i < len(array); i++ {
}
arrayPool.Put(array)
//fmt.Println(array)
}
