Aug
10
# 背景
有一个 python 脚本调用 A 服务的 x 接口获取若干 GB 的数据(大量对象),读取和解析大约需要 5 分钟。
由于 x 接口的改造,需要改成调用 B 服务的 y 接口。
A、B 服务都是基于字节跳动的 KITE 框架开发的(今日头条Go建千亿级微服务的实践),通信协议是 thrift 0.9.2 。
# 现象
改成调用 B 服务,在测试过程中发现,每次大约到 3 分钟以后就会出现报错 TTransportException(TSocket read 0 bytes);之后会重试,但第一次报错后,之后每次大约1分钟内就会再次报同样的错误,重试 3 次后放弃、进程退出。
# 排查
1. 由于测试的时间是晚高峰,初步判断可能是晚高峰服务端压力太大导致。次日平峰期测试仍然复现。
2. 搜索,发现有人遇到类似问题,是从 thrift 0.9 升级到 1.0,服务端没有进行 utf8 编码导致客户端的解析问题,他通过修改服务端代码解决。然而服务端显然不存在问题,因为其他的服务调用该接口表现稳定。此外我遇到的问题并没有升级thrift版本。
3. 还是从报错信息入手,在代码里搜索 "TSocket read 0 bytes",来自于 python2.7/site-packages/thrift/transport/TSocket.py
4. 通过插入调试代码,发现并没有抛出异常,说明确实只读到了 0 字节,因此可以大致判断问题发生在 server 端。
5. 查看 B 服务的 log,发现确实有“客户端超时” 的报错信息。通过查看 KITE 框架的文档,发现默认的超时时间是 3 秒,A服务在配置文件里指定了 20s 的超时时间,而 B 服务没有指定。
6. 通过修改 B 服务的超时时间,调用成功。但为什么 python 作为一个客户端,会出现长达 3s 的停顿导致超时呢,尤其是在局域网甚至本机环境,不可能是网络原因。
7. 联想到曾经踩过的一个坑(详见:https://www.felix021.com/blog/read.php?2142),猜测是python的gc导致。虽然python是引用计数,但为了避免循环引用导致的内存泄漏,还是有一个 stw 的 gc 扫描。通过关闭这个扫描,就解决了这个超过 3s 的停顿
# 吐槽
python真是慢。同样一个api,golang只要17s就完成了调用、反序列化,而python需要长达5分钟。
# 吐槽 #2
大概过了半个月,python把内存用爆了,最后只好用 go 重写了。
有一个 python 脚本调用 A 服务的 x 接口获取若干 GB 的数据(大量对象),读取和解析大约需要 5 分钟。
由于 x 接口的改造,需要改成调用 B 服务的 y 接口。
A、B 服务都是基于字节跳动的 KITE 框架开发的(今日头条Go建千亿级微服务的实践),通信协议是 thrift 0.9.2 。
# 现象
改成调用 B 服务,在测试过程中发现,每次大约到 3 分钟以后就会出现报错 TTransportException(TSocket read 0 bytes);之后会重试,但第一次报错后,之后每次大约1分钟内就会再次报同样的错误,重试 3 次后放弃、进程退出。
# 排查
1. 由于测试的时间是晚高峰,初步判断可能是晚高峰服务端压力太大导致。次日平峰期测试仍然复现。
2. 搜索,发现有人遇到类似问题,是从 thrift 0.9 升级到 1.0,服务端没有进行 utf8 编码导致客户端的解析问题,他通过修改服务端代码解决。然而服务端显然不存在问题,因为其他的服务调用该接口表现稳定。此外我遇到的问题并没有升级thrift版本。
3. 还是从报错信息入手,在代码里搜索 "TSocket read 0 bytes",来自于 python2.7/site-packages/thrift/transport/TSocket.py
def read(self, sz):
try:
buff = self.handle.recv(sz)
except socket.error, e:
if (e.args[0] == errno.ECONNRESET and
(sys.platform == 'darwin' or sys.platform.startswith('freebsd'))):
self.close()
buff = ''
elif e.args[0] == errno.EINTR:
buff = self.handle.recv(sz)
if len(buff) > 0:
return buff
else:
raise
if len(buff) == 0:
raise TTransportException(type=TTransportException.END_OF_FILE, message='TSocket read 0 bytes')
return buff
try:
buff = self.handle.recv(sz)
except socket.error, e:
if (e.args[0] == errno.ECONNRESET and
(sys.platform == 'darwin' or sys.platform.startswith('freebsd'))):
self.close()
buff = ''
elif e.args[0] == errno.EINTR:
buff = self.handle.recv(sz)
if len(buff) > 0:
return buff
else:
raise
if len(buff) == 0:
raise TTransportException(type=TTransportException.END_OF_FILE, message='TSocket read 0 bytes')
return buff
4. 通过插入调试代码,发现并没有抛出异常,说明确实只读到了 0 字节,因此可以大致判断问题发生在 server 端。
5. 查看 B 服务的 log,发现确实有“客户端超时” 的报错信息。通过查看 KITE 框架的文档,发现默认的超时时间是 3 秒,A服务在配置文件里指定了 20s 的超时时间,而 B 服务没有指定。
6. 通过修改 B 服务的超时时间,调用成功。但为什么 python 作为一个客户端,会出现长达 3s 的停顿导致超时呢,尤其是在局域网甚至本机环境,不可能是网络原因。
7. 联想到曾经踩过的一个坑(详见:https://www.felix021.com/blog/read.php?2142),猜测是python的gc导致。虽然python是引用计数,但为了避免循环引用导致的内存泄漏,还是有一个 stw 的 gc 扫描。通过关闭这个扫描,就解决了这个超过 3s 的停顿
import gc
gc.disable()
gc.disable()
# 吐槽
python真是慢。同样一个api,golang只要17s就完成了调用、反序列化,而python需要长达5分钟。
# 吐槽 #2
大概过了半个月,python把内存用爆了,最后只好用 go 重写了。
Aug
10
1. 现象
某日线上服务报警(基于时序数据库做的),请求量大幅下滑。
观察ganglia监控图表,发现有部分机器CPU占用率断崖式下跌,从原先的1000%+下降到100%(20核40线程的CPU),通过内存监控可以确认服务本身并未重启。
登录异常机器,用 lsof -i :PORT1 也可以看到端口号仍被占用,但是却无法接受请求;同样,该服务的 pprof 监听端口 PORT2 能接受请求,但无响应请求。
2. 排查
在异常机器上通过 "netstat -antpl | grep CLOSE_WAIT | grep PORT1 | wc -l" 可以看到有大量连接等待关闭,达到连接上限,所以无法接受请求,PORT2 则正常。
挑一台机器重启后服务恢复正常。为了恢复业务,重启了大部分异常机器上的服务,保留两台持续排查。
使用 top 查看cpu占用率,如上所述,始终保持在 100% 左右,说明有一个线程在全速运行。
通过 perf top (注:也可以使用pstack,能看到更详细的调用栈),发现是某一个二分查找的函数在占用cpu。
经过对代码的分析,发现是传入的值小于有效查找范围,代码实现不完善,导致出现了死循环。
进一步排查发现某个api未做好数据有效性保护,导致出现无效数据。
3. 分析
问题的直接原因已经定位,但是不明确的是,为什么一个 goroutine 死循环会导致进程整体hang住?
cpu 占用率只有100%,说明只有一个 goroutine 死循环,根据 Go 的 GMP 模型,理论上应该可以schedule其他的 goroutine 继续接受请求。
查看该进程的线程数(cat /proc/PID/status),看到开启了80+系统线程,说明不是线程数量的问题。
尝试查看该进程的 goroutine 数,但 pprof 不可用,而负责这个 metrics 打点的 goroutine 自从异常以后也未再上报数据。
写了一个简单的样例代码,开启一个简单死循环的goroutine,并不会阻碍其他goroutine的执行。
有一位同学根据现象搜到了这篇文章: 如何定位 golang 进程 hang 死的 bug
根据这篇文章的分析,在有死循环goroutine的情况下,其他goroutine主动调用 runtime.GC() 会出现 hang 住的情况。
验证代码如下,确实符合预期,和前述事故的表现一致。
综合以上分析可知,当 golang 中出现一个死循环的 goroutine、该 goroutine 就会一直占用 cpu,无法被调度;而需要 STW 的 gc 又无法暂停该 goroutine,因此出现了一个调度上的死锁。
另外,根据那篇文章的说法,在 for 循环中没有函数调用的话,编译器不会插入调度代码,所以无法完成抢占式调用。《深入解析Go - 抢占式调度》中也有具体的说明 https://tiancaiamao.gitbooks.io/go-internals/content/zh/05.5.html
实际测试发现,如果是调用自己写的另外一个简单函数,仍然会出现死锁,而调用注入 fmt.Println 之类的函数,则不会出现死锁,说明Go并不是在函数调用的时候插入调度检测代码(这也不符合直觉,每次函数调用都有额外性能开销,不太划算),而是在某些库函数中增加了调度检测。
完。
某日线上服务报警(基于时序数据库做的),请求量大幅下滑。
观察ganglia监控图表,发现有部分机器CPU占用率断崖式下跌,从原先的1000%+下降到100%(20核40线程的CPU),通过内存监控可以确认服务本身并未重启。
登录异常机器,用 lsof -i :PORT1 也可以看到端口号仍被占用,但是却无法接受请求;同样,该服务的 pprof 监听端口 PORT2 能接受请求,但无响应请求。
2. 排查
在异常机器上通过 "netstat -antpl | grep CLOSE_WAIT | grep PORT1 | wc -l" 可以看到有大量连接等待关闭,达到连接上限,所以无法接受请求,PORT2 则正常。
挑一台机器重启后服务恢复正常。为了恢复业务,重启了大部分异常机器上的服务,保留两台持续排查。
使用 top 查看cpu占用率,如上所述,始终保持在 100% 左右,说明有一个线程在全速运行。
通过 perf top (注:也可以使用pstack,能看到更详细的调用栈),发现是某一个二分查找的函数在占用cpu。
经过对代码的分析,发现是传入的值小于有效查找范围,代码实现不完善,导致出现了死循环。
进一步排查发现某个api未做好数据有效性保护,导致出现无效数据。
3. 分析
问题的直接原因已经定位,但是不明确的是,为什么一个 goroutine 死循环会导致进程整体hang住?
cpu 占用率只有100%,说明只有一个 goroutine 死循环,根据 Go 的 GMP 模型,理论上应该可以schedule其他的 goroutine 继续接受请求。
查看该进程的线程数(cat /proc/PID/status),看到开启了80+系统线程,说明不是线程数量的问题。
尝试查看该进程的 goroutine 数,但 pprof 不可用,而负责这个 metrics 打点的 goroutine 自从异常以后也未再上报数据。
写了一个简单的样例代码,开启一个简单死循环的goroutine,并不会阻碍其他goroutine的执行。
func test1() {
fmt.Println("test1")
i := 0
for {
i++
}
}
func main() {
go test1()
for i := 0; i < 100; i++ {
time.Sleep(1 * time.Second)
fmt.Printf("i = %d\n", i)
}
}
fmt.Println("test1")
i := 0
for {
i++
}
}
func main() {
go test1()
for i := 0; i < 100; i++ {
time.Sleep(1 * time.Second)
fmt.Printf("i = %d\n", i)
}
}
有一位同学根据现象搜到了这篇文章: 如何定位 golang 进程 hang 死的 bug
根据这篇文章的分析,在有死循环goroutine的情况下,其他goroutine主动调用 runtime.GC() 会出现 hang 住的情况。
验证代码如下,确实符合预期,和前述事故的表现一致。
func test1() {
fmt.Println("test1")
i := 0
for {
i++
}
}
func main() {
go test1()
for i := 0; i < 100; i++ {
time.Sleep(1 * time.Second)
fmt.Printf("i = %d\n", i)
if i == 3 {
runtime.GC()
}
}
}
fmt.Println("test1")
i := 0
for {
i++
}
}
func main() {
go test1()
for i := 0; i < 100; i++ {
time.Sleep(1 * time.Second)
fmt.Printf("i = %d\n", i)
if i == 3 {
runtime.GC()
}
}
}
综合以上分析可知,当 golang 中出现一个死循环的 goroutine、该 goroutine 就会一直占用 cpu,无法被调度;而需要 STW 的 gc 又无法暂停该 goroutine,因此出现了一个调度上的死锁。
另外,根据那篇文章的说法,在 for 循环中没有函数调用的话,编译器不会插入调度代码,所以无法完成抢占式调用。《深入解析Go - 抢占式调度》中也有具体的说明 https://tiancaiamao.gitbooks.io/go-internals/content/zh/05.5.html
实际测试发现,如果是调用自己写的另外一个简单函数,仍然会出现死锁,而调用注入 fmt.Println 之类的函数,则不会出现死锁,说明Go并不是在函数调用的时候插入调度检测代码(这也不符合直觉,每次函数调用都有额外性能开销,不太划算),而是在某些库函数中增加了调度检测。
完。
Aug
2
- 堆和栈有什么区别?
- 什么分配在堆上,什么分配在栈上?
- 为什么有了堆还需要栈/有了栈还需要堆?
- 效率差别在哪儿?如何优化?
- 有哪些常见的内存分配算法?
- 内存分配算法的主要挑战是什么?如何解决?
继续引申还有gc的一系列问题
这一篇写得还蛮好的:https://blog.csdn.net/jiahehao/article/details/1842234 ,但是注意不要被最后一段话洗脑。
- 什么分配在堆上,什么分配在栈上?
- 为什么有了堆还需要栈/有了栈还需要堆?
- 效率差别在哪儿?如何优化?
- 有哪些常见的内存分配算法?
- 内存分配算法的主要挑战是什么?如何解决?
继续引申还有gc的一系列问题
这一篇写得还蛮好的:https://blog.csdn.net/jiahehao/article/details/1842234 ,但是注意不要被最后一段话洗脑。