Allenxuxu
commented
3 years ago 提供下 gev 的版本，和 go 的版本。
Closed chunlongyuan closed 3 years ago
Allenxuxu
commented
3 years ago 提供下 gev 的版本，和 go 的版本。
chunlongyuan
commented
3 years ago # 运行系统
alpine:3.11
# gev 版本
github.com/Allenxuxu/gev v0.1.9
# golang 版本
golang:1.15
试一下最新的 master 代码
chunlongyuan
commented
3 years ago 我先试一下，不过这个一般要跑几天后才会出现，也可能是我没找到规律，但一两天就会出现。
Allenxuxu
commented
3 years ago 我先试一下，不过这个一般要跑几天后才会出现。
我这边也跑了一个，看看能不能复现。
chunlongyuan
commented
3 years ago go-im-im-gateway-857f97b9f-n7vkm 976m 26MiFile: app
Build ID: 053ed7dab2cea4aa2ece55e7125b24b2e6c1a958
Type: cpu
Time: Mar 17, 2021 at 9:57am (CST)
Duration: 30.15s, Total samples = 29.23s (96.96%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 25870ms, 88.50% of 29230ms total
Dropped 79 nodes (cum <= 146.15ms)
Showing top 10 nodes out of 29
flat flat% sum% cum cum%
17950ms 61.41% 61.41% 19760ms 67.60% syscall.Syscall6
3500ms 11.97% 73.38% 3670ms 12.56% time.now
1060ms 3.63% 77.01% 5350ms 18.30% github.com/Allenxuxu/gev/eventloop.(*EventLoop).handlerEvent
620ms 2.12% 79.13% 1190ms 4.07% runtime.mapaccess2
570ms 1.95% 81.08% 570ms 1.95% runtime.casgstatus
550ms 1.88% 82.96% 580ms 1.98% runtime.(*itabTableType).find
450ms 1.54% 84.50% 900ms 3.08% github.com/Allenxuxu/gev/eventloop.(*EventLoop).doPendingFunc
430ms 1.47% 85.97% 810ms 2.77% runtime.reentersyscall
420ms 1.44% 87.41% 420ms 1.44% github.com/Allenxuxu/toolkit/sync/spinlock.(*SpinLock).Lock
320ms 1.09% 88.50% 25470ms 87.14% github.com/Allenxuxu/gev/poller.(*Poller).Pollruntime.GOMAXPROCS(-1) 是为了和 _ "go.uber.org/automaxprocs" 解决获取 k8s 分配CPU的问题。func NewGevServer(opts ...Option) (Server, error) {
options := Options{}
for _, opt := range opts {
opt(&options)
}
s, err := gev.NewServer(
&gevHandler{
conns: options.Conns,
handler: options.Handler,
cmdLimit: options.CmdLimit,
},
gev.Network("tcp"),
gev.Address(options.Addr),
gev.NumLoops(runtime.GOMAXPROCS(-1)),
gev.Protocol(&imProtocol{}),
gev.IdleTime(time.Duration(options.IdleTime)*time.Second))
if err != nil {
return nil, err
}
return &gevServer{s: s, conns: options.Conns}, nil
}gevLog.SetLevel(gevLog.LevelDebug)Allenxuxu
commented
3 years ago top一下看下负载？
chunlongyuan
commented
3 years ago top一下看下负载？
很抱歉，我在打印gev日志时才发现前面升级gev版本的部署由于我的编排文件问题并没有更新到，所以我重新部署了继续观察下新版本gev会不会遇到这个问题。谢谢。
Allenxuxu
commented
3 years ago top一下看下负载？
很抱歉，我在打印gev日志时才发现前面升级gev版本的部署由于我的编排文件问题并没有更新到，所以我重新部署了继续观察下新版本gev会不会遇到这个问题。谢谢。
可以使用最新的tag v0.2.0
chunlongyuan
commented
3 years ago top一下看下负载？
很抱歉，我在打印gev日志时才发现前面升级gev版本的部署由于我的编排文件问题并没有更新到，所以我重新部署了继续观察下新版本gev会不会遇到这个问题。谢谢。
可以使用最新的tag v0.2.0
tag v0.2.0，我先说明下昨天用 v0.1.11 测试的情况：我增加了部分日志如下所示，运行了 20 小时左右候开始出现CPU占用上升，测试CPU分配 1000m，目前资源占用如下（今早占用19m左右）:
NAME CPU(cores) MEMORY(bytes)
go-im-im-gateway-58d5c65b7-q6gj6 770m 32MiTCP连接信息：
/data # netstat -nat |awk '{print $6}'|sort|uniq -c|sort -rn
16 ESTABLISHED
4 LISTEN
2 CLOSE_WAIT
1 established)
1 Foreign我根据 pprof 显示的信息在 n, err := unix.EpollWait(ep.fd, events, -1) 前后增加了日志：
fmt.Println("[Gev] EpollWait start") // 增加的第一条日志
n, err := unix.EpollWait(ep.fd, events, -1)
fmt.Printf("[Gev] EpollWait end, n(%d) err(%v)\n", n, err) // 增加的第二条日志- 现在我 tail 到的日志不停的在打印下面信息：[Gev] EpollWait start [Gev] EpollWait end, n(2) err(nil) [Gev] EpollWait start [Gev] EpollWait end, n(2) err(nil) [Gev] EpollWait start [Gev] EpollWait end, n(2) err(nil) [Gev] EpollWait start [Gev] EpollWait end, n(2) err(nil)
### 小结
结合pprof和打印出来的日志能够得出结论： `n, err := unix.EpollWait(ep.fd, events, -1)` 在该k8s上运行20h左右后会出现不断循环调用的情况，导致CPU占用逐渐增高。可以打印下是哪个fd 唤醒了epoll ，看起来似乎是你有一个连接在发数据？ 我感觉go syscall 造成这种现象，你目前让他触发的方式是一直有一两个连接在发送数据吗？ 说下你的场景，我来模拟下，我目前后台起的那个没有这种现象(不过我那个压测后就没有连接了)。
chunlongyuan
commented
3 years ago EventRead 事件，而且是某一两个固定的 fd ，所以我先跟下这一两个连接。v0.1.11 ，只是增加了写日志，打印了 fd 和 event 信息，昨晚跑到现在也出现了问题，关键日志如下：[Gev] EpollWait start
[Gev] EpollWait end, n(2) err(<nil>)
[Gev] Epoll for index(0) fd(40) Events(0x0001)
[Gev] Epoll for index(1) fd(41) Events(0x0001)
[Gev] Epoll wake(false)// ...
for i := 0; i < n; i++ {
fd := int(events[i].Fd)
fmt.Printf("[Gev] Epoll for index(%d) fd(%d) Events(0x%04x)\n", i, events[i].Fd, events[i].Events) // 日志 1
if fd != ep.eventFd {
// ...
fmt.Printf("[Gev] Epoll wake(%t)\n", wake) // 日志 2
if wake {CLOSE_WAIT 并产生新的 ESTABLISHED。
/data # netstat -antp | grep 1800
tcp 0 0 :::1800 :::* LISTEN 1/app
tcp 1 0 ::ffff:172.31.14.56:1800 ::ffff:172.31.19.178:41015 CLOSE_WAIT 1/app
tcp 0 0 ::ffff:172.31.14.56:1800 ::ffff:172.31.19.178:19021 TIME_WAIT -
tcp 1 0 ::ffff:172.31.14.56:1800 ::ffff:172.31.10.23:1198 CLOSE_WAIT 1/app
tcp 1 0 ::ffff:172.31.14.56:1800 ::ffff:172.31.28.106:30989 CLOSE_WAIT 1/app
tcp 0 0 ::ffff:172.31.14.56:1800 ::ffff:172.31.10.23:53707 ESTABLISHED 1/app使用 gev 自带的 example : gev/example/protocol 这个例子可以复现，运行下面测试client三四次大概率就会出现。
在 gev/example/protocol 目录里增加 Dockerfile 和 Makefile 方便测试
Dockerfile
FROM alpine:3.11
WORKDIR /data
COPY protocol ./app
RUN mkdir /lib64 && ln -s /lib/libc.musl-x86_64.so.1 /lib64/ld-linux-x86-64.so.2
CMD ["/data/app"]Makefile
GOPATH:=$(shell go env GOPATH)
.PHONY: build
build:
rm -rf protocol
GO_ENABLED=0 GOOS=linux GOARCH=amd64 go build -o protocol *.go
.PHONY: docker
docker: build
docker build . -t protocol:latest
.PHONY: run-docker
run-docker: docker
docker rm -f protocol | echo "remove ok"
docker run --rm --name protocol -e GEV_LOG_LEVEL="debug" -p1833:1833 protocol
测试程序
package main
import (
"flag"
"fmt"
"net"
"time"
)
var addr = flag.String("a", "", "im address")
var connNum = flag.Int("c", 1, "connection number")
var sendDelay = flag.Duration("w", time.Millisecond*100, "send delay")
var execTime = flag.Duration("d", time.Second*10, "exec duration")
func main() {
flag.Parse()
if *addr == "" || *connNum < 1 {
fmt.Println("invalid parameter")
return
}
closeCh := make(chan struct{}, 1)
for i := 0; i < *connNum; i++ {
go doWork(i, closeCh)
}
<-time.After(*execTime)
close(closeCh)
fmt.Printf("run finish after(%v)\n", execTime)
<-time.After(time.Second)
}
func doWork(index int, closeCh <-chan struct{}) {
for {
if !runClient(index, closeCh) {
break
}
}
}
// 建立连接，收发数据
func runClient(index int, closeCh <-chan struct{}) (goon bool) {
conn, err := net.DialTimeout("tcp", *addr, time.Second*5)
if err != nil {
fmt.Printf("dial err(%v)\n", err)
return false
}
defer conn.Close()
fmt.Printf("client(%d) connect ok, send data now\n", index+1)
go func() {
for {
buf := make([]byte, 1024)
if _, err := conn.Read(buf); err != nil {
fmt.Printf("client(%d) read err(%v) at(%v)\n", index+1, err, time.Now())
break
}
}
}()
for {
select {
case <-closeCh:
fmt.Printf("client(%d) closed at(%v)\n", index+1, time.Now())
return false
case <-time.After(*sendDelay):
if _, err := conn.Write([]byte{0x00, 0x00, 0x00, 0x01}); err != nil {
fmt.Printf("client(%d) write err(%v) at(%v)\n", index+1, err, time.Now())
return true // 写失败则重连
}
fmt.Printf("client(%d) write success at(%v)\n", index+1, time.Now())
}
}
}
protocol git:(tag/v0.1.11) ✗ make run-docker// 一个连接，运行10秒，每秒发一个包，持续 10秒 结束
go run main.go -a="localhost:1833" -d=10s -c=1 -w=1s简单跑了写 v0.2.0 貌似没有这个问题，我现在部署 v0.2.0 到外网上去跟进测试一下。
chunlongyuan
commented
3 years ago @Allenxuxu 我这边目前用 v0.2.0 复测没有复现了，你能不能描述下这个问题，如果确定无误我们就把这个 issue 关闭掉谢谢。
Allenxuxu
commented
3 years ago 我猜测是eventfd 一直唤醒epoll。但是我本地一直没能复现。
之前版本基本每次有异步任务都会 write 一次 eventfd，但是每次处理异步任务都是批量处理的，所以有概率会导致 eventfd 的read 数据比较多，后面频繁唤醒。 v0.2.0 对这边的处理有些优化，尽可能少的 write eventfd。
ywk94
commented
1 year ago github.com/Allenxuxu/gev v0.3.0 我目前使用0.3.0 ,还是有这个问题呢,只有2个链接
目前复现不了, 服务还没有重启,但是没有排查思路
一、问题描述
我在两套 k8s 环境都有出现，我分配多少CPU他运行一辆天后就占用多少CPU。在没有什么用户量的情况下就会出现占满。
1、运行环境
2、部分编排文件
3、没有新的连接，仅有一些连接和断开的日志，基本都是这种日志，大概隔几秒会有一组
4、pod CPU 信息（当前分配1000M，测试了分配2000M也会满）
5、连接占满的情况下的连接信息
6、go profile 信息
二、期望 CPU 随业务量增减