问题
当Go系统遭遇突增流量,洪峰过境,流量恢复正常后,整个系统的资源消耗是否会变大?
第一反应,应该是会恢复到之前的水平吧!资源消耗在流量恢复正常之后,为什么会变大呢...
复现
模拟一下该场景。
我们知道Go原生的网络模型goroutine-per-connection,即一个连接分配一个goroutine去处理。当流量突增,瞬间高并发,很有可能使协程数量也同步增加。
即如:
原本正常流量情景下,有1000个goroutine,但此时突然来了大量请求,goroutine数暴增至100w。
可用如下代码模拟:
package main
import (
"fmt"
_ "net/http/pprof"
"runtime"
"time"
)
func main() {
fmt.Printf("最初!程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
for i := 0; i < 1000000; i++ {
go func() {
time.Sleep(time.Second * 10)
}()
}
fmt.Printf("for循环结束后!程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
time.Sleep(5e9)
fmt.Printf("5s后程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
time.Sleep(5e9)
fmt.Printf("10s后程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
time.Sleep(5e9)
fmt.Printf("15s后程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
time.Sleep(5e9)
fmt.Printf("20s后程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
// 用于阻塞不使程序退出
select {}
// 或者用这种方式
// //ch := make(chan int, 0)
// //ch <- 1
}
执行结果如下:
最初!程序中goroutine的数量为:1
for循环结束后!程序中goroutine的数量为:1000001
5s后程序中goroutine的数量为:1000001
10s后程序中goroutine的数量为:1
15s后程序中goroutine的数量为:1
20s后程序中goroutine的数量为:1
...
当前代码无从得知在启动100w协程前后的内存/CPU等信息,增加部分代码, 提升资源层面的可观测性。如下:
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"os"
"runtime"
"runtime/debug"
"time"
"github.com/arl/statsviz"
"github.com/shirou/gopsutil/process"
)
var DateTime = "2006-01-02 15:04:05"
// 提升资源层面的可观测性
func main() {
statsviz.RegisterDefault() // 实时查看 Go 应用程序运行时统计信息(GC,MemStats 等)
// 打印GC信息
go printGCStats()
// pprof
go func() {
fmt.Println(http.ListenAndServe(fmt.Sprintf("127.0.0.1:%s", "6060"), nil))
}()
// 打印cpu和内存的使用信息
go func() {
pid := os.Getpid()
fmt.Println("当前程序的进程号为:", pid)
p, _ := process.NewProcess(int32(pid))
for {
v, _ := p.CPUPercent()
if v > 0 {
memPercent, _ := p.MemoryPercent()
fmt.Printf("该进程的cpu占用率:%v,内存占用:%v, 时间:%v\n", v, memPercent, time.Now().Format(DateTime))
println("---------------分割线------------------")
}
time.Sleep(5 * time.Second)
}
}()
fmt.Printf("最初!程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
//for i := 0; i < 1000000; i++ {
// go func() {
// time.Sleep(time.Second * 10)
// }()
//}
time.Sleep(5e9)
fmt.Printf("for循环结束后!程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
time.Sleep(5e9)
fmt.Printf("5s后程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
time.Sleep(5e9)
fmt.Printf("10s后程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
time.Sleep(5e9)
fmt.Printf("15s后程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
time.Sleep(5e9)
fmt.Printf("20s后程序中goroutine的数量为:%d\n", runtime.NumGoroutine())
// 用于阻塞不使程序退出
select {}
}
func printGCStats() {
t := time.NewTicker(time.Second)
s := debug.GCStats{}
for {
select {
case <-t.C:
debug.ReadGCStats(&s)
fmt.Printf("gc %d last@%v, PauseTotal %v\n", s.NumGC, s.LastGC, s.PauseTotal)
}
}
}
和之前代码比,新增了4块代码,其中
- statsviz.RegisterDefault() 是一个第三方的可视化工具(github.com/arl/statsviz),能够查看Go 应用程序运行时统计信息(GC,MemStats 等)
- printGCStats(), 每隔1s打印程序的GC信息
- fmt.Println(http.ListenAndServe(fmt.Sprintf("127.0.0.1:%s", "6060"), nil)) 开启pprof,这步在很多项目中非常常见,属常规操作
- p.CPUPercent() && p.MemoryPercent(), 借助github.com/shirou/gopsutil这个库,每隔5s打印一下当前程序的CPU和内存使用信息
将开启100w协程的代码注释,记录"空跑"的性能:
最初!程序中goroutine的数量为:4
当前程序的进程号为:95252
该进程的cpu占用率:0.8364421098415779,内存占用:0.044441223, 时间:2023-06-16 10:29:23
---------------分割线------------------
gc 0 last@1970-01-01 08:00:00 +0800 CST, PauseTotal 0s
gc 0 last@1970-01-01 08:00:00 +0800 CST, PauseTotal 0s
gc 0 last@1970-01-01 08:00:00 +0800 CST, PauseTotal 0s
gc 0 last@1970-01-01 08:00:00 +0800 CST, PauseTotal 0s
for循环结束后!程序中goroutine的数量为:11
gc 0 last@1970-01-01 08:00:00 +0800 CST, PauseTotal 0s
该进程的cpu占用率:0.6441600370520854,内存占用:0.09536743, 时间:2023-06-16 10:29:28
---------------分割线------------------
gc 0 last@1970-01-01 08:00:00 +0800 CST, PauseTotal 0s
gc 0 last@1970-01-01 08:00:00 +0800 CST, PauseTotal 0s
gc 0 last@1970-01-01 08:00:00 +0800 CST, PauseTotal 0s
gc 0 last@1970-01-01 08:00:00 +0800 CST, PauseTotal 0s
5s后程序中goroutine的数量为:11
gc 0 last@1970-01-01 08:00:00 +0800 CST, PauseTotal 0s
该进程的cpu占用率:0.44540045197456263,内存占用:0.10166168, 时间:2023-06-16 10:29:33
---------------分割线------------------
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
10s后程序中goroutine的数量为:11
该进程的cpu占用率:0.3693817952398507,内存占用:0.10223389, 时间:2023-06-16 10:29:38
---------------分割线------------------
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
15s后程序中goroutine的数量为:11
该进程的cpu占用率:0.32912235386802935,内存占用:0.102996826, 时间:2023-06-16 10:29:43
---------------分割线------------------
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
20s后程序中goroutine的数量为:11
该进程的cpu占用率:0.34234244240639955,内存占用:0.10328293, 时间:2023-06-16 10:29:48
---------------分割线------------------
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
该进程的cpu占用率:0.28744831080521077,内存占用:0.10385513, 时间:2023-06-16 10:29:53
---------------分割线------------------
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
gc 1 last@2023-06-16 10:29:33.227392 +0800 CST, PauseTotal 70.042µs
该进程的cpu占用率:0.27528844379029793,内存占用:0.10404587, 时间:2023-06-16 10:29:58
...
可见GC频次很低。CPU使用大致在0.2~0.8,内存在0.04~0.11
同时访问 http://localhost:6060/debug/statsviz/
heap in-use 只有几M
此时将开启100w协程,每个协程sleep 10s(模拟业务处理)的代码取消注释,再次运行:
最初!程序中goroutine的数量为:4
当前程序的进程号为:96105
该进程的cpu占用率:4.517216078449847,内存占用:0.44116974, 时间:2023-06-16 10:36:53
---------------分割线------------------
gc 7 last@2023-06-16 10:36:54.255362 +0800 CST, PauseTotal 8.854457ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:63.50660430793033,内存占用:15.632629, 时间:2023-06-16 10:36:58
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
for循环结束后!程序中goroutine的数量为:1000004
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:37.10674171813685,内存占用:15.63282, 时间:2023-06-16 10:37:03
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
5s后程序中goroutine的数量为:5
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:32.49715724959919,内存占用:15.641212, 时间:2023-06-16 10:37:08
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
10s后程序中goroutine的数量为:5
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:24.971469749626166,内存占用:14.190102, 时间:2023-06-16 10:37:13
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
15s后程序中goroutine的数量为:5
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:20.3450391244844,内存占用:13.17606, 时间:2023-06-16 10:37:18
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
20s后程序中goroutine的数量为:5
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:17.15503649797085,内存占用:12.8685, 时间:2023-06-16 10:37:23
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:14.835354648135736,内存占用:12.566948, 时间:2023-06-16 10:37:28
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:13.075560238064284,内存占用:12.267494, 时间:2023-06-16 10:37:33
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:11.71420929097974,内存占用:9.054565, 时间:2023-06-16 10:37:38
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:10.579057654995502,内存占用:7.7142715, 时间:2023-06-16 10:37:43
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:9.662050852130408,内存占用:7.715225, 时间:2023-06-16 10:37:48
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:8.894093245091423,内存占用:7.716179, 时间:2023-06-16 10:37:53
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:8.241124350205666,内存占用:6.7832947, 时间:2023-06-16 10:37:58
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:7.692988065351502,内存占用:6.7634583, 时间:2023-06-16 10:38:03
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:7.203602945727484,内存占用:3.948021, 时间:2023-06-16 10:38:08
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:6.761852639726575,内存占用:3.780079, 时间:2023-06-16 10:38:13
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:6.382606190610497,内存占用:3.671646, 时间:2023-06-16 10:38:18
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:6.055940735976846,内存占用:3.6726952, 时间:2023-06-16 10:38:23
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:5.752774396590926,内存占用:3.6736488, 时间:2023-06-16 10:38:29
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:5.47945995030865,内存占用:0.18644333, 时间:2023-06-16 10:38:34
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:5.231086125367948,内存占用:0.17595291, 时间:2023-06-16 10:38:39
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:5.014285852070234,内存占用:0.17576218, 时间:2023-06-16 10:38:44
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:4.798984172890425,内存占用:0.10681152, 时间:2023-06-16 10:38:49
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
该进程的cpu占用率:4.6097949036744055,内存占用:0.09908676, 时间:2023-06-16 10:38:54
---------------分割线------------------
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 8 last@2023-06-16 10:36:54.928286 +0800 CST, PauseTotal 8.925248ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
该进程的cpu占用率:5.040456346089843,内存占用:14.997578, 时间:2023-06-16 10:38:59
---------------分割线------------------
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
该进程的cpu占用率:4.856690266348459,内存占用:14.652634, 时间:2023-06-16 10:39:04
---------------分割线------------------
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
该进程的cpu占用率:4.693492356239568,内存占用:14.085388, 时间:2023-06-16 10:39:09
---------------分割线------------------
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
该进程的cpu占用率:4.534741370763308,内存占用:11.00502, 时间:2023-06-16 10:39:14
---------------分割线------------------
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
该进程的cpu占用率:4.386747711219474,内存占用:6.7001343, 时间:2023-06-16 10:39:19
---------------分割线------------------
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
该进程的cpu占用率:4.242128730141223,内存占用:6.6851616, 时间:2023-06-16 10:39:24
---------------分割线------------------
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
该进程的cpu占用率:4.119332039884263,内存占用:6.0071945, 时间:2023-06-16 10:39:29
---------------分割线------------------
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
gc 9 last@2023-06-16 10:38:55.995177 +0800 CST, PauseTotal 9.118457ms
该进程的cpu占用率:3.997977651649899,内存占用:6.0079575, 时间:2023-06-16 10:39:34
...
循环结束并等待5s后,协程的数量已经降了下来。
但即便goroutine已经执行结束后,GC的耗时明显增加,CPU和内存使用更是大幅上涨。
访问 http://localhost:6060/debug/statsviz/
heap in-use 达到了几百M
前后占用差不多如下:
before: 该进程的cpu占用率:0.27528844379029793,内存占用:0.10404587, 时间:2023-06-16 10:29:58
after: 该进程的cpu占用率:3.997977651649899,内存占用:6.0079575, 时间:2023-06-16 10:39:34
伴随时间消逝,CPU和内存占用会有回落,但相比开启100w协程之前的资源消耗,也还是会多一些。
简而言之,协程执行结束后,协程数量会恢复正常,内存却恢复不了
定位
先抓一下heap的profile,看一下heap in-use 这几百M都用在了哪里。
curl http://127.0.0.1:6060/debug/pprof/heap -o heap_info.out
go tool pprof --http :9091 heap_info.out
(新的火焰图看起来不错)
可见调用关系是 runtime.systemstack-->runtime.newproc func1-->runtime.newproc1-->runtime.malg
runtime/proc.go:
// Create a new g running fn.
// Put it on the queue of g's waiting to run.
// The compiler turns a go statement into a call to this.
func newproc(fn *funcval) {
gp := getg()
pc := getcallerpc()
systemstack(func() {
newg := newproc1(fn, gp, pc)
pp := getg().m.p.ptr()
runqput(pp, newg, true)
if mainStarted {
wakep()
}
})
}
//--------分割线----------
// Create a new g in state _Grunnable, starting at fn. callerpc is the
// address of the go statement that created this. The caller is responsible
// for adding the new g to the scheduler.
func newproc1(fn *funcval, callergp *g, callerpc uintptr) *g {
if fn == nil {
fatal("go of nil func value")
}
mp := acquirem() // disable preemption because we hold M and P in local vars.
pp := mp.p.ptr()
newg := gfget(pp)
if newg == nil {
newg = malg(stackMin)
casgstatus(newg, _Gidle, _Gdead)
allgadd(newg) // publishes with a g->status of Gdead so GC scanner doesn't look at uninitialized stack.
}
if newg.stack.hi == 0 {
throw("newproc1: newg missing stack")
}
if readgstatus(newg) != _Gdead {
throw("newproc1: new g is not Gdead")
}
totalSize := uintptr(4*goarch.PtrSize + sys.MinFrameSize) // extra space in case of reads slightly beyond frame
totalSize = alignUp(totalSize, sys.StackAlign)
sp := newg.stack.hi - totalSize
spArg := sp
if usesLR {
// caller's LR
*(*uintptr)(unsafe.Pointer(sp)) = 0
prepGoExitFrame(sp)
spArg += sys.MinFrameSize
}
memclrNoHeapPointers(unsafe.Pointer(&newg.sched), unsafe.Sizeof(newg.sched))
newg.sched.sp = sp
newg.stktopsp = sp
newg.sched.pc = abi.FuncPCABI0(goexit) + sys.PCQuantum // +PCQuantum so that previous instruction is in same function
newg.sched.g = guintptr(unsafe.Pointer(newg))
gostartcallfn(&newg.sched, fn)
newg.parentGoid = callergp.goid
newg.gopc = callerpc
newg.ancestors = saveAncestors(callergp)
newg.startpc = fn.fn
if isSystemGoroutine(newg, false) {
sched.ngsys.Add(1)
} else {
// Only user goroutines inherit pprof labels.
if mp.curg != nil {
newg.labels = mp.curg.labels
}
if goroutineProfile.active {
// A concurrent goroutine profile is running. It should include
// exactly the set of goroutines that were alive when the goroutine
// profiler first stopped the world. That does not include newg, so
// mark it as not needing a profile before transitioning it from
// _Gdead.
newg.goroutineProfiled.Store(goroutineProfileSatisfied)
}
}
// Track initial transition?
newg.trackingSeq = uint8(fastrand())
if newg.trackingSeq%gTrackingPeriod == 0 {
newg.tracking = true
}
casgstatus(newg, _Gdead, _Grunnable)
gcController.addScannableStack(pp, int64(newg.stack.hi-newg.stack.lo))
if pp.goidcache == pp.goidcacheend {
// Sched.goidgen is the last allocated id,
// this batch must be [sched.goidgen+1, sched.goidgen+GoidCacheBatch].
// At startup sched.goidgen=0, so main goroutine receives goid=1.
pp.goidcache = sched.goidgen.Add(_GoidCacheBatch)
pp.goidcache -= _GoidCacheBatch - 1
pp.goidcacheend = pp.goidcache + _GoidCacheBatch
}
newg.goid = pp.goidcache
pp.goidcache++
if raceenabled {
newg.racectx = racegostart(callerpc)
if newg.labels != nil {
// See note in proflabel.go on labelSync's role in synchronizing
// with the reads in the signal handler.
racereleasemergeg(newg, unsafe.Pointer(&labelSync))
}
}
if traceEnabled() {
traceGoCreate(newg, newg.startpc)
}
releasem(mp)
return newg
}
//--------分割线----------
// Allocate a new g, with a stack big enough for stacksize bytes.
func malg(stacksize int32) *g {
newg := new(g)
if stacksize >= 0 {
stacksize = round2(stackSystem + stacksize)
systemstack(func() {
newg.stack = stackalloc(uint32(stacksize))
})
newg.stackguard0 = newg.stack.lo + stackGuard
newg.stackguard1 = ^uintptr(0)
// Clear the bottom word of the stack. We record g
// there on gsignal stack during VDSO on ARM and ARM64.
*(*uintptr)(unsafe.Pointer(newg.stack.lo)) = 0
}
return newg
}
其中:
malg
proc.go文件中的malg函数是用于分配goroutine的空间的。在每个goroutine启动前,都需要分配一定的空间用于存储goroutine的信息和状态。该函数所做的工作是从堆上分配一块足够大的空间,然后将其转换为一个goroutine结构体。
具体来说,malg函数首先会调用runtime·stackalloc函数从堆上分配一块大小为StackMin的空间,这个函数返回的指针指向刚刚分配的空间。然后,malg将这个指针转换为一个goroutine结构体指针,并将其初始化为一个全新的goroutine,设置一些必要的初始值,如栈顶指针、栈底指针、栈大小等。接着,malg函数会将goroutine加入到运行时系统的调度队列中,等待被调度执行。
值得注意的是,malg函数除了分配goroutine的空间外,还会在栈顶处设置一个安全区域(安全边界),以确保goroutine不会误用或越界访问栈上的数据。如果goroutine使用了超过安全边界的栈空间,则会触发SIGSEGV信号,导致程序崩溃。
总之,malg函数是runtime包中的一个关键函数,用于分配goroutine的空间并进行初始化,是实现并发调度的重要部分。
newproc
newproc是Go语言运行时中的一个函数,它的作用是创建一个新的goroutine并将其加入到调度器中进行调度。
在Go语言中,goroutine是轻量级的线程,可以同时运行多个goroutine,并且它们的创建和销毁非常快速。而调度器负责管理这些goroutine的运行,并确保它们能够正确地共享CPU资源。
newproc的具体实现过程如下:
- 首先,它会检查当前的堆栈空间是否足够创建一个新的goroutine。如果足够,则继续执行下一步;否则,会触发栈扩容的操作。
- 然后,newproc会将新创建的goroutine加入到可运行队列中,并将其状态设置为可运行。
- 接着,它会将当前的G(goroutine)保存到调用栈中,并将当前的P(处理器)添加到全局P列表中,以便进行调度。
- 然后,newproc会创建一个新的G,并设置其状态为等待运行,并将它的入口点设置为所需函数的地址。
- 最后,newproc会返回新创建的G的地址。
newproc函数的调用者和参数由go语句生成的代码控制,因此,它通常不会在代码中直接调用,而是由编译器和运行时自动调用。
newproc1
newproc1是Go语言运行时的一个函数,用于创建新的goroutine(轻量级线程)。它的作用是将一个函数(或方法)和它需要的参数打包成一个newproc结构体,并将其加入到Goroutine的调度队列中,以便执行。
newproc1函数的主要作用包括:
- 创建一个新的G(goroutine)结构体,其中包含了需要运行的函数、参数和执行的栈空间等信息。
- 向调度器发送一个调度请求,要求分配一个P(processor)来运行新的G。
- 将新创建的G对象加入到调度队列中,等待调度器进行调度。
- 在G执行过程中,会根据需要进行栈扩展或缩小,并且当G退出时,运行时会自动回收占用的内存空间。
通过newproc1函数的调用,我们可以轻松地创建新的goroutine,实现并发编程,提高程序的运行效率,提高系统的吞吐量和稳定性。
来自: https://github.com/cuishuang/explain-source-code-by-chatgpt/blob/main/runtime/proc.go.md#malg
分析
在newproc1中有这样一段:
newg := gfget(pp)
if newg == nil {
newg = malg(stackMin)
casgstatus(newg, _Gidle, _Gdead)
allgadd(newg) // publishes with a g->status of Gdead so GC scanner doesn't look at uninitialized stack.
}
正常在创建 goroutine 结构体时,会优先复用 g 和 sudog 结构体。但如果在当前 p 的 goroutine空闲列表(gFree) 及全局的goroutine空闲列表找不到可用的 g,则会创建一个新的 g 结构体。该 g 结构体会被 append 到allgs 切片(是一个全局变量)中:
func allgadd(gp *g) {
if readgstatus(gp) == _Gidle {
throw("allgadd: bad status Gidle")
}
lock(&allglock)
allgs = append(allgs, gp)
if &allgs[0] != allgptr {
atomicstorep(unsafe.Pointer(&allgptr), unsafe.Pointer(&allgs[0]))
}
atomic.Storeuintptr(&allglen, uintptr(len(allgs)))
unlock(&allglock)
}
//--------分割线----------
var (
// 其他变量
allgs []*g
)
allgadd
在Go语言中,goroutine是一种轻量级的线程,它可以在单个OS线程上运行。当一个Go程序启动时,它会创建一个或多个goroutine来执行程序中的各个任务。每当一个函数被调用时,该函数的代码会在一个新的goroutine中运行,从而允许程序在多个并发任务之间切换执行。
在Go语言的运行时环境中,有一个名为allgadd的函数,它的作用是将一个新的goroutine添加到goroutine调度器中。当一个函数被调用时,它会创建一个新的goroutine,并将它添加到运行时环境中的goroutine队列中。此时,goroutine还没有被运行,需要等待调度器调度它。
allgadd函数在运行时环境的处理器(processor)中执行。每个处理器都有一个goroutine队列,用于存储等待执行的goroutine。当一个新的goroutine被添加到队列中时,处理器会检查是否已经有一个可用的OS线程,如果有,则将goroutine分配给该线程执行。如果没有可用的线程,则处理器会等待,直到有一个可用的线程。
allgadd函数的实现非常重要,它需要考虑多线程并发的问题,保证goroutine的安全运行。在实现中,需要使用原子操作和锁来保证操作的原子性和互斥性。同时,allgadd函数还需要处理goroutine退出和垃圾回收的问题,即当一个goroutine完成运行时,需要将它从队列中移除并进行垃圾回收,以保证程序的性能和稳定性。
总之,allgadd函数是Go语言运行时环境中非常重要的一个函数,它实现了goroutine的添加和管理,保证了多线程并发的稳定性和性能。
来自: https://github.com/cuishuang/explain-source-code-by-chatgpt/blob/main/runtime/proc.go.md#allgadd
allgs
allgs是一个全局变量,定义在proc.go这个文件中。它是一个指向所有G(goroutine)的切片的指针。G是Go语言中的协程,是实现并发的基本单元。allgs的作用是跟踪所有的goroutine,用于调试和监控。
具体来说,allgs的作用有以下几个方面:
- Debugging:allgs变量可用于调试Go程序。通过打印切片中的所有元素,可以查看当前正在运行的所有goroutine的堆栈跟踪信息,以及它们的状态、调度情况等信息。
- Garbage Collection(垃圾回收):垃圾回收器需要跟踪所有的goroutine以了解它们是否还在运行。allgs变量在垃圾回收期间用于遍历所有的goroutine,并标记它们的栈。
- Runtime Statistics(运行时统计):allgs变量还用于收集关于运行时的统计信息。例如,可以计算运行时同时存在的最大goroutine数量、goroutine数量的平均值等等。
总之,allgs变量在Go语言的运行时系统中扮演着重要的角色,用于跟踪所有的goroutine,为调试、垃圾回收和运行时统计等提供支持。
来自: https://github.com/cuishuang/explain-source-code-by-chatgpt/blob/main/runtime/proc.go.md#allgs
proc.go:
// forEachG calls fn on every G from allgs.
//
// forEachG takes a lock to exclude concurrent addition of new Gs.
func forEachG(fn func(gp *g)) {
lock(&allglock)
for _, gp := range allgs {
fn(gp)
}
unlock(&allglock)
}
forEachG函数是Go语言运行时中的一部分,其作用是遍历所有活跃的Goroutine(也称为G),并执行一个指定的函数,对于每个G而言,都会调用该函数。该函数可以被看做一个并发的迭代器,用于访问运行时中的每个Goroutine。 此函数在一些场景中非常有用,例如在Go的GC过程中,需要暂停所有的Goroutine,防止它们继续执行并干扰GC的过程。在这种情况下,可以使用forEachG函数来实现对所有Goroutine的扫描,并暂停它们。 其他一些场景中也可以使用该函数,例如在调试工具中,需要列出所有当前运行的Goroutine,或者在监视系统中进行性能分析时,需要统计所有Goroutine的状态等等。 总之,forEachG函数是Go语言运行时中的一个非常有用的工具,可以帮助开发者更好地管理Goroutine,从而提高应用程序的性能和可靠性。 来自: https://github.com/cuishuang/explain-source-code-by-chatgpt/blob/main/runtime/proc.go.md#foreachg
forEachG主要在以下几个地方使用:
mgc.go:
// gcResetMarkState resets global state prior to marking (concurrent
// or STW) and resets the stack scan state of all Gs.
//
// This is safe to do without the world stopped because any Gs created
// during or after this will start out in the reset state.
//
// gcResetMarkState must be called on the system stack because it acquires
// the heap lock. See mheap for details.
//
//go:systemstack
func gcResetMarkState() {
// This may be called during a concurrent phase, so lock to make sure
// allgs doesn't change.
forEachG(func(gp *g) {
gp.gcscandone = false // set to true in gcphasework
gp.gcAssistBytes = 0
})
// Clear page marks. This is just 1MB per 64GB of heap, so the
// time here is pretty trivial.
lock(&mheap_.lock)
arenas := mheap_.allArenas
unlock(&mheap_.lock)
for _, ai := range arenas {
ha := mheap_.arenas[ai.l1()][ai.l2()]
for i := range ha.pageMarks {
ha.pageMarks[i] = 0
}
}
work.bytesMarked = 0
work.initialHeapLive = gcController.heapLive.Load()
}
gcResetMarkState是在Go语言中垃圾回收器(gc)的运行过程中调用的一个函数,它的作用是重置垃圾回收器中与标记相关的状态,以便下一轮垃圾回收能够正确地进行。 在Go语言中的垃圾回收器执行过程中,需要分为两个阶段:标记阶段和清扫阶段。在标记阶段中,会从根对象出发,遍历所有能够到达的对象,并将这些对象标记为活动对象。在这个过程中,为了防止对象被多次标记或者不被标记的情况出现,需要记录一些状态,并在完成标记后进行清理。 gcResetMarkState函数就是负责重置这些状态的函数。具体来说,它会清理各种指针标记位,还会重置某些内存区域的状态,以防止垃圾回收器在下一轮回收时受到干扰。 总之,gcResetMarkState函数是垃圾回收器中关键的重置函数之一,它确保垃圾回收器在下一轮运行前的状态是正确的,这样才能准确地找到所有的垃圾对象进行回收。 来自: https://github.com/cuishuang/explain-source-code-by-chatgpt/blob/main/runtime/mgc.go.md#gcresetmarkstate
proc.go:
// Check for deadlock situation.
// The check is based on number of running M's, if 0 -> deadlock.
// sched.lock must be held.
func checkdead() {
// ...
forEachG(func(gp *g) {
if isSystemGoroutine(gp, false) {
return
}
s := readgstatus(gp)
switch s &^ _Gscan {
case _Gwaiting,
_Gpreempted:
grunning++
case _Grunnable,
_Grunning,
_Gsyscall:
print("runtime: checkdead: find g ", gp.goid, " in status ", s, "\n")
unlock(&sched.lock)
throw("checkdead: runnable g")
}
})
// ...
}
checkdead函数主要负责检查并清理已经死亡的Goroutine(Go语言中的轻量级线程)。该函数是Go语言运行时系统中调度器的一部分,用于确保使用Go语言编写程序时,不会出现已经死亡的Goroutine占用内存和其他资源的情况。具体来说,checkdead函数会通过检查schedule队列中的Goroutine列表以及其他相关的数据结构,查找已经标记为死亡或者已经退出的Goroutine,并将其从队列和其他数据结构中清除。同时,checkdead函数会释放相关资源,比如堆栈内存等。在Go语言中,Goroutine是一种轻量级的并发机制,可以帮助程序编写者实现高效率、高并发的程序。但是在使用Goroutine时,如果程序中存在大量死亡的Goroutine没有得到清理,程序的性能和稳定性将会受到严重影响。checkdead函数的作用就是确保程序中已经死亡的Goroutine得到及时清理,保证程序的性能和稳定性。
来自: https://github.com/cuishuang/explain-source-code-by-chatgpt/blob/main/runtime/proc.go.md#checkdead
func schedtrace(detailed bool) {
//...
forEachG(func(gp *g) {
print(" G", gp.goid, ": status=", readgstatus(gp), "(", gp.waitreason.String(), ") m=")
if gp.m != nil {
print(gp.m.id)
} else {
print("nil")
}
print(" lockedm=")
if lockedm := gp.lockedm.ptr(); lockedm != nil {
print(lockedm.id)
} else {
print("nil")
}
print("\n")
})
// ...
}
schedtrace是一个用于调试的函数,它可以用于跟踪调度器的行为。当开启schedtrace时,调度器会在每次调用时发送相关信息到调用方提供的函数中。这些信息包括调度器中各个P(处理器)和G(goroutine)的运行情况,以及调整调度器行为的各种事件。 具体来说,schedtrace有以下作用: 跟踪P和G的状态:schedtrace可以提供P的数量、运行的G的数量、G的状态(running、runnable、waiting等)等信息。这些信息可以帮助调试进程中的调度问题,比如一个被阻塞的G是否存在,是否有足够的P来进行调度等等。 发送事件信息:schedtrace可以捕获调度器中各种事件的触发,比如调整P的数量、调整G的优先级等等。通过schedtrace提供的事件信息,可以更深入地了解调度器的运行机制、判断调度器是否正常工作,以及查找调度问题。 提供调试接口:schedtrace函数提供了一个调试接口,可以与调度器的其它调试工具(如gdb)结合使用,帮助调试调度问题。 综上,schedtrace是一个有着很重要作用的调试工具,开发人员可以通过这个工具更轻松地跟踪调度器的运行情况和调试调度问题。 来自:https://github.com/cuishuang/explain-source-code-by-chatgpt/blob/main/runtime/proc.go.md#schedtrace
allgs会在GC及检查死锁(以及用schedtrace调试)时用到,进行加锁遍历。
而这个切片只可能单向扩增,而没有收缩操作。
当流量恢复,这个在洪峰期间扩增的allgs切片,不会相应变小,还是要进行遍历扫描,从而cpu占用升高,用于处理业务的cpu占比相应减少。
验证
想要获知allgs的长度变化,考虑过用dlv或eBPF,一番折腾都有一些坑。
直接干脆在runtime中新增一个方法,如下:
func PrintAllgSize() int {
return len(allgs)
}
执行all.bash 重新编译源代码
package main
import (
"fmt"
_ "net/http/pprof"
"runtime"
"time"
)
func main() {
fmt.Printf("最初!程序中goroutine的数量为:%d,allg大小为 %d\n", runtime.NumGoroutine(), runtime.PrintAllgSize())
//
for i := 0; i < 1000000; i++ {
go func() {
time.Sleep(time.Second * 10)
}()
}
time.Sleep(5e9)
fmt.Printf("for循环结束后!程序中goroutine的数量为:%d,allg大小为 %d\n", runtime.NumGoroutine(), runtime.PrintAllgSize())
time.Sleep(5e9)
fmt.Printf("5s后程序中goroutine的数量为:%d,allg大小为 %d\n", runtime.NumGoroutine(), runtime.PrintAllgSize())
time.Sleep(5e9)
fmt.Printf("10s后程序中goroutine的数量为:%d,allg大小为 %d\n", runtime.NumGoroutine(), runtime.PrintAllgSize())
time.Sleep(5e9)
fmt.Printf("15s后程序中goroutine的数量为:%d,allg大小为 %d\n", runtime.NumGoroutine(), runtime.PrintAllgSize())
time.Sleep(5e9)
fmt.Printf("20s后程序中goroutine的数量为:%d,allg大小为 %d\n", runtime.NumGoroutine(), runtime.PrintAllgSize())
for i := 0; i < 50000; i++ {
go func() {
time.Sleep(time.Second * 10)
}()
}
time.Sleep(5e9)
fmt.Printf("25s后程序中goroutine的数量为:%d,allg大小为 %d\n", runtime.NumGoroutine(), runtime.PrintAllgSize())
time.Sleep(5e9)
fmt.Printf("30s后程序中goroutine的数量为:%d,allg大小为 %d\n", runtime.NumGoroutine(), runtime.PrintAllgSize())
// 用于阻塞不使程序退出
select {}
}
输出:
最初!程序中goroutine的数量为:1,allg大小为 6
for循环结束后!程序中goroutine的数量为:1000001,allg大小为 1000014
5s后程序中goroutine的数量为:842287,allg大小为 1000014
10s后程序中goroutine的数量为:1,allg大小为 1000014
15s后程序中goroutine的数量为:1,allg大小为 1000014
20s后程序中goroutine的数量为:1,allg大小为 1000014
25s后程序中goroutine的数量为:50001,allg大小为 1000014
30s后程序中goroutine的数量为:1,allg大小为 1000014
第二个循环,再开5w个协程,allgs的元素大小也没有继续增大
而如果将第一个for中 启协程的数量从100w改为1w,则输出如下:
最初!程序中goroutine的数量为:1,allg大小为 6
for循环结束后!程序中goroutine的数量为:10001,allg大小为 10014
5s后程序中goroutine的数量为:1,allg大小为 10014
10s后程序中goroutine的数量为:1,allg大小为 10014
15s后程序中goroutine的数量为:1,allg大小为 10014
20s后程序中goroutine的数量为:1,allg大小为 10014
25s后程序中goroutine的数量为:50001,allg大小为 50131
30s后程序中goroutine的数量为:1,allg大小为 50131
可以理解为撑大了,缩减不回去了
或者想象有这样一个模型:
我是一个导游,带游客住酒店。我最开始带10个人,酒店经在我名下安排10个房间;第二次带了12个人,原来我名下有10个房间,又要再开两个房间(开房间/退房间成本很高);第三次带了15个人,而我名下最多能住12人,所以还要继续开房间,挂在我名下的房间数量达到了15个; 第四次我带了8个人,就不需要进行昂贵的开房/退房操作了。。。倾向于这种只扩张,不回缩的策略。另外,保洁阿姨需要每天清扫我名下的房间,等同于程序的GC等操作
但有一天黄金周,带了10000人来...那要继续开9900多个房,按照这个策略,游客走了之后不会退。但平时实际只有10几位游客,而空余的,还需要做各种维护处理
总结&致谢
其实这算是一个陈年老问题,早在2019年,曹大(github: cch123)就已经遇到并在博客中记述:xargin-为什么 Go 模块在下游服务抖动恢复后,CPU 占用无法恢复 (https://xargin.com/cpu-idle-cannot-recover-after-peak-load/amp/)
同时提了一个issue: runtime: maybe allgs should shrink after peak load (https://github.com/golang/go/issues/34457),但迄今还是open状态。
使用github.com/shirou/gopsutil获取本进程cpu和内存占用的方式,参考自rfyiamcool老哥(http://xiaorui.cc/ )
以下是针对该问题的一些资料和讨论
其实allgs从来没有减少过,不利于稳定,应该提供减少的策略,比如sysmon监控发现g死了一半以上,就释放掉。
你的观察是正确的。目前运行时从不释放为goroutines创建的g对象,尽管它确实重用它们。其主要原因是调度器经常在没有写屏障的情况下操作g指针(许多调度器代码在没有P的情况下运行,因此不能有写屏障),这使得很难确定何时可以对g进行垃圾收集。
大致原因就是go的gc采用的是并发垃圾回收,调度器在操作协程指针的时候不使用写屏障(draveness: 7.2 垃圾收集器),因为调度器在很多执行的时候需要使用P(GPM),因此不能使用写屏障,所以调度器很难确定一个协程是否可以当成垃圾回收,这样调度器里的协程指针信息就会泄露。 https://blog.csdn.net/wuyuhao13579/article/details/109079570
allgs contains all Gs ever created (including dead Gs), and thus never shrinks. Access via the slice is protected by allglock or stop-the-world. Readers that cannot take the lock may (carefully!) use the atomic variables below. allgs 包含所有曾经创建的 G(包括死 G),因此永不收缩。通过切片的访问受到 allglock 或 stop-the-world 的保护。无法获取锁的读者可以(小心!)使用下面的原子变量。
最近Go Team在PGO上投入了不少精力,不知道能否做到: 当黄金周结束,多次发现平时周末的游客只有十位数,远远不需要同时维持上万个房间,进行缓慢缩减。