问题
「当Go系统遭遇突增流量,洪峰过境,流量恢复正常后,整个系统的资源消耗是否会变大? 」
第一反应,应该是会恢复到之前的水平吧!资源消耗在流量恢复正常之后,为什么会变大呢…
复现
模拟一下。
我们知道Go原生的网络模型goroutine-per-connection,即一个链接分配一个goroutine去处理。当流量突增,很有可能使协程数量也同步增加。(更多可参考Go原生网络模型)
即如:
原本正常流量情景下,有1000个goroutine,但此时突然来了大量请求,goroutine数暴增至100w。
可用如下代码模拟:
package main
import (
"fmt"
_ "net/http/pprof"
"runtime"
"time"
)
func main() {
fmt.Printf("最初!程序中goroutine的数量为:%dn", runtime.NumGoroutine())
for i := 0; i
执行结果如下:
最初!程序中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"
)
// after: 该进程的cpu占用率:0.12448928050371065,内存占用:0.047302246, 时间:2023-06-15 18:40:16
// before: 该进程的cpu占用率:3.9694322415591414,内存占用:13.763237, 时间:2023-06-15 18:43:47
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, 时间:%vn", v, memPercent, time.Now().Format(DateTime))
println("---------------分割线------------------")
}
time.Sleep(5 * time.Second)
}
}()
fmt.Printf("最初!程序中goroutine的数量为:%dn", runtime.NumGoroutine())
//for i := 0; i
和之前代码比,新增了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 5s(模拟业务处理)的代码取消注释,再次运行:
最初!程序中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后,协程的数量已经降了下来。
但之后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
}
分析
在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
)
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函数是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 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主要在以下几个地方使用:
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大小为 %dn", runtime.NumGoroutine(), runtime.PrintAllgSize())
//
for i := 0; i
输出:
最初!程序中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
而如果将第一个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
https://note.youdao.com/web/#/file/WEB484390d4553124b1472af71…
对系统压测影响有点大,每次压测都得重启一次服务。
发压力度差不多,但是cpu usage会变高,因为有些全局扫描会遍历allgs。
怀疑是这个原因,具体还得分析pprof
最近在看大量goroutine的回收问题:假如我有一个10万url的切片,都是正常情况下请求会超时的外网,设置超时时间10s。然后遍历切片进行顺序请求。 根据Go原生的网络模型,这时会有大量的goroutine。 我的问题是,即便等最后一个url被请求完并超过10s后,大量的goroutine数量还是降不下来。 有啥好的办法快速让goroutine降下来吗(优先不引入第三方库如reactor模型网络库和池化包)
症状: 协程执行结束后,协程数量会恢复正常,内存却恢复不了
goroutine数量降下来了…陈年老问题,一直没解决。。可以看一下曹大提的issue https://github.com/golang/go/issues/34457
其实allgs从来没有减少过,不利于稳定,应该提供减少的策略,比如sysmon监控发现g死了一半以上,就释放掉。
你的观察是正确的。目前运行时从不释放为goroutines创建的g对象,尽管它确实重用它们。其主要原因是调度器经常在没有写屏障的情况下操作g指针(许多调度器代码在没有P的情况下运行,因此不能有写屏障),这使得很难确定何时可以对g进行垃圾收集。
大致原因就是go的gc采用的是并发垃圾回收,调度器在操作协程指针的时候不使用写屏障(draveness: 7.2 垃圾收集器),因为调度器在很多执行的时候需要使用P(GPM),因此不能使用写屏障,所以调度器很难确定一个协程是否可以当成垃圾回收,这样调度器里的协程指针信息就会泄露。
xargin-为什么 Go 模块在下游服务抖动恢复后,CPU 占用无法恢复
保存heap,goroutine,cpu指标:
curl http://127.0.0.1:6060/debug/pprof/heap -o heap_cui.out && curl http://127.0.0.1:6060/debug/pprof/goroutine -o goroutine_cui.out && curl http://127.0.0.1:6060/debug/pprof/profile?seconds=30 -o profile_cui.out
go tool pprof heap_cui.out
,而后命令行输入web; 或直接go tool pprof --http :9091 heap_cui.out
(这种方式好一些,信息更全,有上方的各种选项; 前一种方式只能看到一张图)
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 的保护。无法获取锁的读者可以(小心!)使用下面的原子变量。
golang中的allgs是什么作用
在Go语言的运行时系统中,allgs是一个全局变量,它是一个保存所有goroutine信息的切片。这个切片中包含所有当前正在运行或者阻塞的goroutine的信息,包括它们的状态、调用栈、所属线程等等。
allgs变量在调试和监控程序中非常有用。例如,在程序崩溃时,可以使用allgs变量获取当前所有运行的goroutine的调用栈信息,以便更好地诊断问题。另外,allgs变量还可以用于性能分析和调试中,通过分析所有goroutine的状态和调用栈信息,找出程序中可能存在的瓶颈和问题。
瞬間高併發 goroutine結束回收問題 ,访问卡顿,备份地址
Runtime: 当一个goroutine 运行结束后会发生什么
goroutine栈的申请与释放
https://medium.com/@openmohan/go-scheduling-and-garbage-colle…
https://blog.csdn.net/wuyuhao13579/article/details/109079570
什么都不起:
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"os"
"runtime"
"time"
"github.com/shirou/gopsutil/process"
)
func main() {
go func() {
fmt.Println(http.ListenAndServe(fmt.Sprintf("127.0.0.1:%s", "6060"), nil))
}()
go func() {
pid := os.Getpid()
fmt.Println("当前程序的进程号为:", pid)
p, _ := process.NewProcess(int32(pid))
for {
v, _ := p.CPUPercent()
//if v != 0.0 {
if v > 0 {
memPercent, _ := p.MemoryPercent()
fmt.Printf("该进程的cpu占用率:%v,内存占用:%v, 时间:%vn", v, memPercent, time.Now().Format(time.DateTime))
println("---------------分割线------------------")
}
time.Sleep(1 * time.Second)
}
}()
fmt.Printf("最初!程序中goroutine的数量为:%d,allg大小为 %dn", runtime.NumGoroutine(), runtime.PrintAllgSize())
//for i := 0; i
输出:
最初!程序中goroutine的数量为:3,allg大小为 8
当前程序的进程号为: 40990
该进程的cpu占用率:1.7345767936174512,内存占用:0.044059753, 时间:2023-05-12 18:56:11
---------------分割线------------------
该进程的cpu占用率:1.3833037997972075,内存占用:0.046539307, 时间:2023-05-12 18:56:12
---------------分割线------------------
该进程的cpu占用率:0.9426338194391203,内存占用:0.046920776, 时间:2023-05-12 18:56:13
---------------分割线------------------
该进程的cpu占用率:0.7145472045365172,内存占用:0.047397614, 时间:2023-05-12 18:56:14
---------------分割线------------------
该进程的cpu占用率:0.7671273650057209,内存占用:0.047683716, 时间:2023-05-12 18:56:15
---------------分割线------------------
最后!程序中goroutine的数量为:3,allg大小为 14
该进程的cpu占用率:0.6422326060530744,内存占用:0.048160553, 时间:2023-05-12 18:56:16
---------------分割线------------------
该进程的cpu占用率:0.6902944326649534,内存占用:0.048732758, 时间:2023-05-12 18:56:17
---------------分割线------------------
该进程的cpu占用率:0.6052315488807393,内存占用:0.049114227, 时间:2023-05-12 18:56:18
---------------分割线------------------
该进程的cpu占用率:0.5390835579514824,内存占用:0.049591064, 时间:2023-05-12 18:56:19
---------------分割线------------------
该进程的cpu占用率:0.5830942889704509,内存占用:0.0500679, 时间:2023-05-12 18:56:20
---------------分割线------------------
5s后程序中goroutine的数量为:3,allg大小为 18
该进程的cpu占用率:0.5306985682548677,内存占用:0.05044937, 时间:2023-05-12 18:56:21
---------------分割线------------------
该进程的cpu占用率:0.6493627721946108,内存占用:0.05083084, 时间:2023-05-12 18:56:22
---------------分割线------------------
该进程的cpu占用率:0.5996871132486625,内存占用:0.05121231, 时间:2023-05-12 18:56:23
---------------分割线------------------
该进程的cpu占用率:0.5572058522494853,内存占用:0.051403046, 时间:2023-05-12 18:56:24
---------------分割线------------------
该进程的cpu占用率:0.5854899584894127,内存占用:0.052261353, 时间:2023-05-12 18:56:25
---------------分割线------------------
10s后程序中goroutine的数量为:3,allg大小为 21
该进程的cpu占用率:0.5490830861544309,内存占用:0.05273819, 时间:2023-05-12 18:56:26
---------------分割线------------------
该进程的cpu占用率:0.5744579673126523,内存占用:0.05311966, 时间:2023-05-12 18:56:27
---------------分割线------------------
该进程的cpu占用率:0.5427606369144101,内存占用:0.05350113, 时间:2023-05-12 18:56:28
---------------分割线------------------
该进程的cpu占用率:0.5658751753441396,内存占用:0.05378723, 时间:2023-05-12 18:56:29
---------------分割线------------------
该进程的cpu占用率:0.5377159332759053,内存占用:0.054359436, 时间:2023-05-12 18:56:30
---------------分割线------------------
15s后程序中goroutine的数量为:3,allg大小为 22
该进程的cpu占用率:0.5124016095745688,内存占用:0.05455017, 时间:2023-05-12 18:56:31
---------------分割线------------------
该进程的cpu占用率:0.5337136458170394,内存占用:0.055408478, 时间:2023-05-12 18:56:32
---------------分割线------------------
该进程的cpu占用率:0.5106376025360306,内存占用:0.055789948, 时间:2023-05-12 18:56:33
---------------分割线------------------
该进程的cpu占用率:0.5302615796688247,内存占用:0.056171417, 时间:2023-05-12 18:56:34
---------------分割线------------------
该进程的cpu占用率:0.5483911301025054,内存占用:0.056648254, 时间:2023-05-12 18:56:35
---------------分割线------------------
20s后程序中goroutine的数量为:3,allg大小为 29
该进程的cpu占用率:0.5274668569968027,内存占用:0.057029724, 时间:2023-05-12 18:56:36
---------------分割线------------------
该进程的cpu占用率:0.5442865856107826,内存占用:0.057411194, 时间:2023-05-12 18:56:37
---------------分割线------------------
该进程的cpu占用率:0.524964879849538,内存占用:0.0579834, 时间:2023-05-12 18:56:38
---------------分割线------------------
该进程的cpu占用率:0.5069267142132382,内存占用:0.05836487, 时间:2023-05-12 18:56:39
---------------分割线------------------
该进程的cpu占用率:0.5227532433163139,内存占用:0.058937073, 时间:2023-05-12 18:56:40
---------------分割线------------------
25s后程序中goroutine的数量为:3,allg大小为 29
该进程的cpu占用率:0.5059914927017842,内存占用:0.059223175, 时间:2023-05-12 18:56:41
---------------分割线------------------
该进程的cpu占用率:0.49014727393871627,内存占用:0.05941391, 时间:2023-05-12 18:56:42
---------------分割线------------------
该进程的cpu占用率:0.5051594610126843,内存占用:0.059700012, 时间:2023-05-12 18:56:43
---------------分割线------------------
该进程的cpu占用率:0.49038278587960654,内存占用:0.06017685, 时间:2023-05-12 18:56:44
---------------分割线------------------
该进程的cpu占用率:0.47644295091723954,内存占用:0.060653687, 时间:2023-05-12 18:56:45
---------------分割线------------------
30s后程序中goroutine的数量为:3,allg大小为 31
该进程的cpu占用率:0.517790279294169,内存占用:0.06093979, 时间:2023-05-12 18:56:46
---------------分割线------------------
该进程的cpu占用率:0.5038525093233929,内存占用:0.061511993, 时间:2023-05-12 18:56:47
---------------分割线------------------
该进程的cpu占用率:0.516403412383421,内存占用:0.0626564, 时间:2023-05-12 18:56:48
---------------分割线------------------
该进程的cpu占用率:0.5032129771179247,内存占用:0.06313324, 时间:2023-05-12 18:56:49
---------------分割线------------------
该进程的cpu占用率:0.4906540582966204,内存占用:0.06341934, 时间:2023-05-12 18:56:50
---------------分割线------------------
该进程的cpu占用率:0.5026863919849385,内存占用:0.06380081, 时间:2023-05-12 18:56:51
---------------分割线------------------
该进程的cpu占用率:0.4907492710795917,内存占用:0.06418228, 时间:2023-05-12 18:56:52
---------------分割线------------------
该进程的cpu占用率:0.47936986146895827,内存占用:0.06465912, 时间:2023-05-12 18:56:53
---------------分割线------------------
该进程的cpu占用率:0.4908517395484445,内存占用:0.065135956, 时间:2023-05-12 18:56:54
---------------分割线------------------
该进程的cpu占用率:0.47997178114997224,内存占用:0.06532669, 时间:2023-05-12 18:56:55
---------------分割线------------------
该进程的cpu占用率:0.49093380797098485,内存占用:0.070381165, 时间:2023-05-12 18:56:56
---------------分割线------------------
该进程的cpu占用率:0.5014240861901205,内存占用:0.070381165, 时间:2023-05-12 18:56:57
---------------分割线------------------
该进程的cpu占用率:0.4909660407381527,内存占用:0.070381165, 时间:2023-05-12 18:56:58
---------------分割线------------------
该进程的cpu占用率:0.5010152071141755,内存占用:0.07123947, 时间:2023-05-12 18:56:59
---------------分割线------------------
该进程的cpu占用率:0.49105254146305255,内存占用:0.071811676, 时间:2023-05-12 18:57:00
---------------分割线------------------
该进程的cpu占用率:0.5006662712686883,内存占用:0.07190704, 时间:2023-05-12 18:57:01
---------------分割线------------------
该进程的cpu占用率:0.4910441572402714,内存占用:0.07238388, 时间:2023-05-12 18:57:02
---------------分割线------------------
该进程的cpu占用率:0.48179546937329976,内存占用:0.07247925, 时间:2023-05-12 18:57:03
---------------分割线------------------
该进程的cpu占用率:0.4910992356040398,内存占用:0.072574615, 时间:2023-05-12 18:57:04
---------------分割线------------------
该进程的cpu占用率:0.4821774792079267,内存占用:0.072574615, 时间:2023-05-12 18:57:05
---------------分割线------------------
该进程的cpu占用率:0.4911388293884917,内存占用:0.07276535, 时间:2023-05-12 18:57:07
---------------分割线------------------
该进程的cpu占用率:0.48256160243541957,内存占用:0.07276535, 时间:2023-05-12 18:57:08
---------------分割线------------------
该进程的cpu占用率:0.47425299944273586,内存占用:0.07276535, 时间:2023-05-12 18:57:09
---------------分割线------------------
该进程的cpu占用率:0.49955661852322975,内存占用:0.07276535, 时间:2023-05-12 18:57:10
---------------分割线------------------
该进程的cpu占用率:0.49127618766141185,内存占用:0.07276535, 时间:2023-05-12 18:57:11
---------------分割线------------------
该进程的cpu占用率:0.48322963628030124,内存占用:0.07276535, 时间:2023-05-12 18:57:12
---------------分割线------------------
该进程的cpu占用率:0.49127264447960023,内存占用:0.07286072, 时间:2023-05-12 18:57:13
---------------分割线------------------
该进程的cpu占用率:0.4835066221066964,内存占用:0.07286072, 时间:2023-05-12 18:57:14
---------------分割线------------------
该进程的cpu占用率:0.491327825886193,内存占用:0.07286072, 时间:2023-05-12 18:57:15
---------------分割线------------------
该进程的cpu占用率:0.4837757999712849,内存占用:0.07286072, 时间:2023-05-12 18:57:16
---------------分割线------------------
该进程的cpu占用率:0.4764742407081455,内存占用:0.07286072, 时间:2023-05-12 18:57:17
---------------分割线------------------
^Csignal: interrupt
正常运行状态下cpu占用率0.5%,内存0.07%
开启100w协程,并在10s后退出:
(改为10s打印一次cpu/内存使用率,因为要持续要执行很久,观察其能降到的最低水位,1s打印一次输出信息太多)
即
go func() {
pid := os.Getpid()
fmt.Println("当前程序的进程号为:", pid)
p, _ := process.NewProcess(int32(pid))
for {
v, _ := p.CPUPercent()
//if v != 0.0 {
if v > 0 {
memPercent, _ := p.MemoryPercent()
fmt.Printf("该进程的cpu占用率:%v,内存占用:%v, 时间:%vn", v, memPercent, time.Now().Format(time.DateTime))
println("---------------分割线------------------")
}
time.Sleep(10 * time.Second) //改为10s打印一次
}
}()
最初!程序中goroutine的数量为:3,allg大小为 8
当前程序的进程号为: 42424
该进程的cpu占用率:11.971746677840297,内存占用:0.25568008, 时间:2023-05-12 19:03:20
---------------分割线------------------
最后!程序中goroutine的数量为:1000003,allg大小为 1000016
该进程的cpu占用率:34.861478672353634,内存占用:9.252453, 时间:2023-05-12 19:03:30
---------------分割线------------------
5s后程序中goroutine的数量为:112316,allg大小为 1000016
10s后程序中goroutine的数量为:3,allg大小为 1000016
该进程的cpu占用率:29.03536881788808,内存占用:7.668495, 时间:2023-05-12 19:03:40
---------------分割线------------------
15s后程序中goroutine的数量为:3,allg大小为 1000016
20s后程序中goroutine的数量为:3,allg大小为 1000016
该进程的cpu占用率:19.596219249163674,内存占用:4.980278, 时间:2023-05-12 19:03:50
---------------分割线------------------
25s后程序中goroutine的数量为:3,allg大小为 1000016
30s后程序中goroutine的数量为:3,allg大小为 1000016
该进程的cpu占用率:14.765560187265695,内存占用:3.2074928, 时间:2023-05-12 19:04:00
---------------分割线------------------
该进程的cpu占用率:11.864651607929765,内存占用:3.2078743, 时间:2023-05-12 19:04:10
---------------分割线------------------
该进程的cpu占用率:9.92047143662269,内存占用:2.5784492, 时间:2023-05-12 19:04:20
---------------分割线------------------
该进程的cpu占用率:8.514160477329295,内存占用:2.0552635, 时间:2023-05-12 19:04:30
---------------分割线------------------
该进程的cpu占用率:7.470054280536214,内存占用:0.313282, 时间:2023-05-12 19:04:40
---------------分割线------------------
该进程的cpu占用率:6.6560274549231,内存占用:0.31404495, 时间:2023-05-12 19:04:50
---------------分割线------------------
该进程的cpu占用率:5.994422368627717,内存占用:0.31461716, 时间:2023-05-12 19:05:00
---------------分割线------------------
该进程的cpu占用率:5.461318917906727,内存占用:0.315094, 时间:2023-05-12 19:05:10
---------------分割线------------------
该进程的cpu占用率:5.008342574208281,内存占用:0.31614304, 时间:2023-05-12 19:05:20
---------------分割线------------------
该进程的cpu占用率:4.654969744301823,内存占用:0.8195877, 时间:2023-05-12 19:05:30
---------------分割线------------------
该进程的cpu占用率:4.820140366604827,内存占用:14.359665, 时间:2023-05-12 19:05:40
---------------分割线------------------
该进程的cpu占用率:4.500030058742756,内存占用:13.126755, 时间:2023-05-12 19:05:50
---------------分割线------------------
该进程的cpu占用率:4.2259707867464344,内存占用:12.516117, 时间:2023-05-12 19:06:00
---------------分割线------------------
该进程的cpu占用率:3.9781804524533233,内存占用:12.020016, 时间:2023-05-12 19:06:10
---------------分割线------------------
该进程的cpu占用率:3.763355102804472,内存占用:11.795521, 时间:2023-05-12 19:06:20
---------------分割线------------------
该进程的cpu占用率:3.5711050662623522,内存占用:11.4871025, 时间:2023-05-12 19:06:30
---------------分割线------------------
该进程的cpu占用率:3.3930419833323433,内存占用:10.962296, 时间:2023-05-12 19:06:41
---------------分割线------------------
该进程的cpu占用率:3.24134631024968,内存占用:10.740185, 时间:2023-05-12 19:06:51
---------------分割线------------------
该进程的cpu占用率:3.094450487143189,内存占用:10.542583, 时间:2023-05-12 19:07:01
---------------分割线------------------
该进程的cpu占用率:2.9646177374065994,内存占用:4.2229652, 时间:2023-05-12 19:07:11
---------------分割线------------------
该进程的cpu占用率:2.8455099006903772,内存占用:4.224205, 时间:2023-05-12 19:07:21
---------------分割线------------------
该进程的cpu占用率:2.731950644261066,内存占用:4.186821, 时间:2023-05-12 19:07:31
---------------分割线------------------
该进程的cpu占用率:2.6384527809604403,内存占用:1.7879486, 时间:2023-05-12 19:07:41
---------------分割线------------------
该进程的cpu占用率:2.687898384609942,内存占用:5.225086, 时间:2023-05-12 19:07:51
---------------分割线------------------
该进程的cpu占用率:2.716562379472545,内存占用:5.219364, 时间:2023-05-12 19:08:01
---------------分割线------------------
该进程的cpu占用率:2.6264727031567454,内存占用:5.22089, 时间:2023-05-12 19:08:11
---------------分割线------------------
该进程的cpu占用率:2.5424541634929,内存占用:5.221081, 时间:2023-05-12 19:08:21
---------------分割线------------------
该进程的cpu占用率:2.4638048279049034,内存占用:5.2215576, 时间:2023-05-12 19:08:31
---------------分割线------------------
该进程的cpu占用率:2.3869673474972863,内存占用:5.2212715, 时间:2023-05-12 19:08:41
---------------分割线------------------
该进程的cpu占用率:2.3207941879635903,内存占用:5.220318, 时间:2023-05-12 19:08:51
---------------分割线------------------
该进程的cpu占用率:2.255579978246484,内存占用:5.2199364, 时间:2023-05-12 19:09:01
---------------分割线------------------
^Csignal: interrupt
即便运行很久(协程都已经结束了),cpu和内存占用率,还是降不到case1这种水位
取消注释再启5w个协程的这段代码,
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"runtime"
"time"
)
func main() {
go func() {
fmt.Println(http.ListenAndServe(fmt.Sprintf("127.0.0.1:%s", "6060"), nil))
}()
//go func() {
//
// pid := os.Getpid()
// fmt.Println("当前程序的进程号为:", pid)
//
// p, _ := process.NewProcess(int32(pid))
// for {
// v, _ := p.CPUPercent()
// //if v != 0.0 {
// if v > 0 {
//
// memPercent, _ := p.MemoryPercent()
// fmt.Printf("该进程的cpu占用率:%v,内存占用:%v, 时间:%vn", v, memPercent, time.Now().Format(time.DateTime))
// println("---------------分割线------------------")
// }
// time.Sleep(10 * time.Second)
// }
//}()
fmt.Printf("最初!程序中goroutine的数量为:%d,allg大小为 %dn", runtime.NumGoroutine(), runtime.PrintAllgSize())
for i := 0; i
输出为:
最初!程序中goroutine的数量为:2,allg大小为 6
最后!程序中goroutine的数量为:1000002,allg大小为 1000014
5s后程序中goroutine的数量为:2304,allg大小为 1000014
10s后程序中goroutine的数量为:2,allg大小为 1000014
15s后程序中goroutine的数量为:2,allg大小为 1000014
20s后程序中goroutine的数量为:2,allg大小为 1000014
25s后程序中goroutine的数量为:50002,allg大小为 1000014
30s后程序中goroutine的数量为:2,allg大小为 1000014
即allg的元素大小没有继续增大
可以理解为撑大了,缩减不回去了
或者想象有这样一个模型:
我是一个导游,带游客住酒店。我最开始带10个人,酒店经在我名下安排10个房间;第二次带了12个人,原来我名下有10个房间,又要再开两个房间(开房间/退房间成本很高);第三次带了15个人,而我名下最多能住12人,所以还要继续开房间,挂在我名下的房间数量达到了15个; 第四次我带了8个人,就不需要进行昂贵的开房/退房操作了。。。倾向于这种只扩张,不回缩的策略。另外,保洁阿姨需要每天清扫我名下的房间,等同于程序的GC
但有一天黄金周,带了10000人来…那要继续开9900多个房,按照这个策略,游客走了之后不会退。但平时实际只有10几位游客,而空余的,allgs元素都是指针类型,gc需要遍历清扫,CPU压力大
总是按最高的来接待
开100w个不退出的协程 (可以把协程里的time.Sleep改为100000s)
输出:
最初!程序中goroutine的数量为:3,allg大小为 8
当前程序的进程号为: 44057
该进程的cpu占用率:5.475696577050808,内存占用:0.25539398, 时间:2023-05-12 19:27:29
---------------分割线------------------
最后!程序中goroutine的数量为:1000003,allg大小为 1000016
该进程的cpu占用率:38.08525996243931,内存占用:15.448475, 时间:2023-05-12 19:27:39
---------------分割线------------------
5s后程序中goroutine的数量为:1000003,allg大小为 1000019
10s后程序中goroutine的数量为:1000003,allg大小为 1000019
该进程的cpu占用率:20.09341974543954,内存占用:10.235214, 时间:2023-05-12 19:27:49
---------------分割线------------------
15s后程序中goroutine的数量为:1000003,allg大小为 1000020
20s后程序中goroutine的数量为:1000003,allg大小为 1000020
该进程的cpu占用率:13.63253311326255,内存占用:8.337402, 时间:2023-05-12 19:27:59
---------------分割线------------------
25s后程序中goroutine的数量为:1000003,allg大小为 1000020
30s后程序中goroutine的数量为:1000003,allg大小为 1000020
该进程的cpu占用率:10.340321837419848,内存占用:6.0424805, 时间:2023-05-12 19:28:09
---------------分割线------------------
该进程的cpu占用率:8.335432645556027,内存占用:4.1745186, 时间:2023-05-12 19:28:19
---------------分割线------------------
该进程的cpu占用率:6.971018163404126,内存占用:3.056717, 时间:2023-05-12 19:28:29
---------------分割线------------------
该进程的cpu占用率:6.004975767818229,内存占用:0.9484291, 时间:2023-05-12 19:28:39
---------------分割线------------------
该进程的cpu占用率:5.277065756593829,内存占用:0.7973671, 时间:2023-05-12 19:28:49
---------------分割线------------------
该进程的cpu占用率:4.698122263473828,内存占用:0.099658966, 时间:2023-05-12 19:28:59
---------------分割线------------------
该进程的cpu占用率:4.2436491766935704,内存占用:0.10023117, 时间:2023-05-12 19:29:09
---------------分割线------------------
该进程的cpu占用率:3.8619599362252104,内存占用:0.10147095, 时间:2023-05-12 19:29:19
---------------分割线------------------
该进程的cpu占用率:3.559485285903543,内存占用:0.101947784, 时间:2023-05-12 19:29:29
---------------分割线------------------
^Csignal: interrupt
本文由mdnice多平台发布
服务器托管,北京服务器托管,服务器租用 http://www.fwqtg.net