Sep 21
最近线上服务压力很大,api的p99有点扛不住。

广告业务对延时的要求普遍比较严格,有些adx设置的超时时间低至100ms,因此亟需找出性能热点。

根据对目前系统情况的估计(和metrics埋点数据),大致估计问题出在广告的正排环节。

使用 pprof  也证明了这一块确实是热点:

引用
$ go tool pprof http://$IP:$PORT/debug/pprof/profile
...
(pprof) top 10
Showing nodes accounting for 25.50s, 32.63% of 78.14s total
Dropped 1533 nodes (cum <= 0.39s)
Showing top 10 nodes out of 284
      flat  flat%  sum%        cum  cum%
    4.56s  5.84%  5.84%      4.87s  6.23%  syscall.Syscall
    4.03s  5.16% 10.99%      4.03s  5.16%  runtime.aeshashbody
    3.50s  4.48% 15.47%      6.01s  7.69%  git.xxx.org/xxx/target.NewFilter
    2.78s  3.56% 19.03%      3.73s  4.77%  runtime.mapaccess2_fast64
    2.63s  3.37% 22.40%      4.52s  5.78%  runtime.mapiternext
    2.08s  2.66% 25.06%      2.16s  2.76%  runtime.heapBitsForObject
    1.65s  2.11% 27.17%      1.93s  2.47%  runtime.mapaccess1_fast64
    1.57s  2.01% 29.18%      2.96s  3.79%  runtime.mapaccess2
    1.43s  1.83% 31.01%      2.06s  2.64%  runtime.runqgrab
    1.27s  1.63% 32.63%      1.27s  1.63%  runtime.epollwait
(pprof) png
Generating report in profile001.png (使用生成的线框图查看耗时)


其中第三行 NewFilter 就是正排过滤函数。因为一些历史原因,系统里不是所有定向条件都使用了倒排,正排实现起来毕竟简单、容易理解,而一旦开了这个口子,就会有越来越多正排加进来,推测是这个原因导致了性能的逐渐衰退。

经过讨论,D同学花了一周多的时间,逐个梳理重写。在Libra(字节跳动内部的ABTest平台,参考谷歌分层实验框架方案)上开实验,平均耗时 -9%,从统计数据上来说,实验组比对照组有了显著的改进,但从最终结果上,整体的p95、p99超时都出现了进一步恶化。

这说明真正的问题不在于正排的计算,优化的思路出现了偏差。

考虑到晚高峰期间的cpu占用率也只是刚超过50%,也就是说有可能性能问题在于锁,但pprof的 block 和 mutex 都是空的,没有线索。

猜测问题有可能在日志,代码里确实用得不少。日志用的是 github.com/ngaut/logging 库,每一次调用都会用到两个全局mutex。但通过调整log level 为error级别,大幅减少了日志量,并没有看到性能的改善。

经过搜索,发现 uber 基于 pprof 开发了一个神器 go-torch,可以生成火焰图。安装好 go-torch 及依赖 FlameGraph 以后执行

引用
$ go-torch  -u http://$IP:$PORT -f cpu.svg
INFO[14:52:23] Run pprof command: go tool pprof -raw -seconds 30 http://$IP:$PORT/debug/pprof/profile
INFO[14:52:54] Writing svg to cpu.svg


用 Chrome 打开 cpu.svg,人肉排查:

点击在新窗口中浏览此图片

可以看到,在NewFilter旁边竟然还有一个耗时接近的 runtime.growslice ,结合实际代码(略作简化),可以推测是 slice 的初始化长度不足。

matchAds := make([]*ad, 0, 4096)
adsBitMap.GetList(func(seq int) {
    if NewFilter(ctx, ad) {
        matchAds = append(matchAds, adlist[seq])
    }
})

// 顺便提一下,bitmap是一个uint64数组,GetList(f) 是将每一个等于1的bit索引传给 f
// GetList方法里面用了cpu的BSF指令来提高性能。



实际上最终定向后得到的广告往往在数万甚至数十万的级别,而 go 的 slice 扩容在超过1024个元素以后是1.25倍,可想而知会出现大量的内存分配和拷贝,导致性能随着广告数量的增加逐渐恶化。最近的广告数量也确实有了大幅的上升 —— 逻辑上形成了闭环。

经过优化,使用更大的初始化长度,并且使用 sync.Pool 来进一步减少内存分配,最终上线后p95和p99都下降了超过50%,效果显著。

参考:
golang 使用pprof和go-torch做性能分析 https://www.cnblogs.com/li-peng/p/9391543.html
Aug 10

记 python 超时的一个坑 不指定

felix021 @ 2019-8-10 13:34 [IT » 其他] 评论(0) , 引用(0) , 阅读(149) | Via 本站原创
# 背景

有一个 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


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()


# 吐槽

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的执行。
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)
        }
}


有一位同学根据现象搜到了这篇文章: 如何定位 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()
                }
        }
}


综合以上分析可知,当 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 ,但是注意不要被最后一段话洗脑。
Jul 4

英语流利说 TED 课程 不指定

felix021 @ 2019-7-4 00:04 [随想] 评论(0) , 引用(0) , 阅读(234) | Via 本站原创
Jul 2
线上服务Panic,部分日志如下
引用
err: runtime error: index out of range
Traceback:
goroutine 19209941 [running]:
...
panic(0x191d0e0, 0x2e078d0)
  /usr/local/go/src/runtime/panic.go:502 +0x229
math/rand.(*rngSource).Uint64(...)
  /usr/local/go/src/math/rand/rng.go:246
math/rand.(*rngSource).Int63(0xc438bb2a00, 0x0)
  /usr/local/go/src/math/rand/rng.go:231 +0x8a
math/rand.(*Rand).Int63(0xc4279b3a70, 0x0)
  /usr/local/go/src/math/rand/rand.go:82 +0x33
math/rand.(*Rand).Int(0xc4279b3a70, 0x0)
  /usr/local/go/src/math/rand/rand.go:100 +0x2b
...


放狗搜了一下:math.Rand is not safe for concurrent use

from: https://github.com/golang/go/issues/3611

这个 issue 的 4 楼还提到 "top-level functions like strings.Split or fmt.Printf or rand.Int63 may be called from any goroutine at any time"

翻了一下源码,rand.Int() 用是自带 lock 的 globalRand 对象

func Int() int { return globalRand.Int() }

...

var globalRand = New(&lockedSource{src: NewSource(1).(Source64)})

...

type lockedSource struct {
  lk  sync.Mutex
  src Source64
}

...

func (r *lockedSource) Uint64() (n uint64) {
  r.lk.Lock()
  n = r.src.Uint64()
  r.lk.Unlock()
  return
}


看了下调用代码,之前的实现为了避免多个 goroutine 竞争同一个锁,所以 new 了一个 rand.Rand 对象,但没考虑到这个对象不支持并发。

最终的解决方案,是实现了一个 safeRander 。

具体代码不适合贴,核心逻辑是初始化 N 个 rand.Rand 对象和对应的 N 个锁,以及一个 index,每次调用 Int() 时,先 atomic.AddUint32(&index, 1) % N,加上对应的锁,再用对应的 rand.Rand 对象。

这样只要并发使用的goroutine不超过N个,就不会出现竞争;就算超过,竞争出现的频率也大幅减少了,而且也可以通过增加 N 来优化。
Jun 3

vscode 的 tab 不指定

felix021 @ 2019-6-3 11:38 [IT » 软件] 评论(3) , 引用(0) , 阅读(402) | Via 本站原创
1. vscode 有一个特性, workbench.editor.enablePreview

当一个文件被(单击)打开、且没有被修改的情况下, tab上的 filename 是斜体, 意味着这是一个临时tab, 会被下一个打开的文件覆盖.

在打开前双击文件, 或者打开后双击 tab 上的文件名, 可以把这个 tab 固定住.

另外就是修改 workbench.editor.enablePreview 这个属性, 关闭掉.

2. vscode 还有另一个特性, workbench.editor.showTabs

当这个选项为 false 的时候, 永远只有一个 tab

这个情况我遇到过两次, 上一次倒腾了半天, 直接reset vscode了

这次又遇到, 搜 "vscode only showing one tab" 找到这个 issue

https://github.com/Microsoft/vscode/issues/51649

这才知道了解决方案

但我不知道是怎么触发的, 我并没有刻意去设置, 初步怀疑是有一个很奇怪的快捷键, 不小心打开了吧

不能理解这个选项存在的意义, 会有人需要吗?
Apr 24
工作这几年,面试了很多人,也结合了自己工作的经验,有一些心得,但是没有深入地思考过。

正好看到两位大佬的总结,很有共鸣,做个梳理,作为一面镜子,照照自己。



~ 张一鸣:我面了两千个年轻人,发现混的好的都有这5种特质

  @ https://www.toutiao.com/i6681549238490366472

点击在新窗口中浏览此图片


~ 谢熊猫君:如何辨认身边的聪明人?

  @ https://mp.weixin.qq.com/s/jvqMxdHRRBhhWl29fj3RHg

点击在新窗口中浏览此图片
分页: 1/98 第一页 1 2 3 4 5 6 7 8 9 10 下页 最后页 [ 显示模式: 摘要 | 列表 ]