Java 应用在线性能分析和火焰图

在碰到线上性能问题的时候,如果能在线通过采样方式获取热点函数/方法就可以更方便地定位问题所在,进行优化。采用在线采样的方式,由于性能影响小,可以比较放心地在线上进行,获取第一手数据。Linux 平台上,对于多数 C/C++ 编写的应用,可以通过 perf 来方便的采样,还可以进一步生成火焰图来更直观地观察。Java 是没法直接用 perf 的。虽然有一个 perf-map-agent,但是并不方便,尝试过程中还弄出了 kernel panic,所以这玩意是不敢在线上用了。不过 JDK 自己其实已经带了一个采样工具 FlightRecorder ,算是 JMC 的一部分。在 Java 11 以及之后版本的 OpenJDK 中以及可以随意使用。但是在之前版本中,是只有 Oracle JDK 才有的,还算商业版本的功能,虽说启用的时候并没检查 license,但是理论上要在生产环境用,还是要花钱的。

首先,应用启动的时候,要给 java 加上参数:

-XX:+UnlockCommercialFeatures -XX:+FlightRecorder -XX:FlightRecorderOptions=loglevel=info

因为 JVM 默认在 safepoint 的地方才可以返回栈,所以最好加上

-XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints

让 JVM 在非 safepoint 的时候也提供原数据。

然后在想开始采样的时候

sudo -u <java_user> -i jcmd <pid> JFR.start filename=/tmp/app.jfr duration=60s  settings=profile

这里可以指定输出的文件路径,和采样时间。之后可以用

sudo -u <java_user> -i jcmd <pid> JFR.check

来检查采样是不是已经完成了。

此处的 settings=profile 会增加一些性能指标的采样,比如堆内对象,IO 等。默认是 default。这里的 profile、default 实际是配置文件名,位于 $JAVA_HOME/jre/lib/jfr 下。也可以创建自己的配置。

更详细的用法可以参考官方文档:https://docs.oracle.com/javacomponents/jmc-5-4/jfr-runtime-guide/toc.htm

确认完成后,就可以把 jfr 文件传回本地,用 jmc 来分析了。如果想要生成火焰图,还有这么个工具:https://github.com/chrishantha/jfr-flame-graph。具体用法可以看文档。大致上,代码拖回来后,

cd jfr-flame-graph
install-mc-jars.sh
mvn clean install -U

就编译好了。另外还需要 https://github.com/brendangregg/FlameGraph

工具准备好以后,

path/to/jfr-flame-graph/run.sh -f app.jfr -o app.txt
cat app.txt | path/to/FlameGraph/flamegraph.pl >app.svg

就能生成一个漂亮的火焰图了。

参考链接

  1. https://docs.oracle.com/javacomponents/jmc-5-5/jfr-command-reference/JFRCR.pdf
  2. https://docs.oracle.com/javacomponents/jmc-5-5/jfr-command-reference/diagnostic-command-reference.htm

一次连接超时问题排查的历程

我们有一个 java 应用,启动的时候要初始化连接池,在连接一堆 sharding 过的 DB 时,经常会有一部分连接超时失败的,集中在一两台后端机器上,但每次失败的后端服务器却又不固定,也并不是每次启动都能遇到。超时时间设为了 50ms,看起来有点短但是对局域网,和压力并不算大的 DB 来说,这个时间已经长得匪夷所思了。后来尝试调大成 100ms,还是有失败的。但是如果启动成功后,却没再记录到过连接超时的情况。

排查网络问题首先是抓包,本来打算看看是不是对端响应慢有啥重传的,结果发现了更神奇的事情:发起 TCP 连接的 SYN 包不够数!也就是说,有几个连接根本连 SYN 包都没发出去过。还发现有一两个连接收到了 DB 服务器的 SYN/ACK 后,居然发了 RST !所有服务器有响应的 SYN/ACK,包括被 RST 的,延迟都不到 0.2ms,速度挺正常的。那些个丢了的 SYN 和被 RST 的是怎么回事呢?

然后再用 strace 套着启动试试。这回也顺带了解了 java 在 linux 上连接超时的实现方式。首先发起一个非阻塞的 connect,然后用 poll 来等待直到超时,如果超时,则把 socket shutdown 了。然而在 strace 的记录里,所有的 connect 系统调用一个不少,只是在 poll 的时候超时了。这倒是可以解释前面抓包里 RST 的原因。在服务端 SYN/ACK 返回的时候,客户端已经超时 shutdown 了 socket,这时候自然就会返回 RST。但是奇怪的是为啥 connect 了却没看到 SYN 包,从被 RST 的现象推断,是从 connect 到发出 SYN 有了延迟。有的延迟发出后,返回的时候超时,于是就被 RST,绝大部分一直延迟到超时都没发出,于是就再也没了。但是为啥从 connect 到发出 SYN 包会有那么大的延迟呢?

于是去看了一下内核 connect 的实现,connect 系统调用对 TCP 来说,就是一路从数据构造 TCP 包、IP 包、Ethernet 包进入网卡的 QDisc。对非阻塞的 connect 来说就到此为止,返回 EINPROGRESS。对阻塞 connect,还会继续等待三次握手完成。进入 QDisc 后就是网卡驱动通过 DMA Engine 来发包了。因为是非阻塞 connect,这一路构造包的过程中没想出可以阻塞的点,于是怀疑是不是在 QDisc 或者 DMA Engine 发生了什么事情,研究实验了很久而无所得。

再一次碰到问题时,又抓了次包。这回凑巧没过滤 ARP 包,于是在结果里看到了一些查询 DB 服务器 MAC 地址的 ARP 请求。突然想起来,如果本地 ARP 缓存没命中的话,ARP 请求也是一个可能会有延迟的点。这个过程是发生在从 IP 包到构造 Ethernet 包的过程中的。于是把所有 ARP 包过滤出来看,真的发现对连接失败的 IP,ARP 请求第一次没有响应,隔 1s 重试以后才成功。就是这 1s 足以让超时时间是 50ms 的连接失败好多回了。

至于为啥 ARP 请求会超时倒不是啥难题。网络上有广播限流,之前也碰到过 ARP、VRRP 包被干的情况。至于启动成功后,应用和后端 DB 一直会有数据来往,ARP 缓存也就不会再被清掉,这也就解释了为啥问题只会出现在启动的时候。搞清楚原因以后,就不担心运行当中会出故障了。至于启动失败,重试就行了,或者 ping 一把后端 IP,产生一次 ARP 缓存就能绕过。彻底解决问题反倒不是个很紧迫的事了。

中间费了这么大劲,最后发现的问题却如此操蛋没技术含量,感觉挺失望的。不过大部分时候总是这样。隔壁老王有句名言,每个匪夷所思的问题背后,都有一个啼笑皆非的原因。

go http client 设置连接超时

go 语言的 http 客户端可以在初始化话的时候通过

client := http.Client{
	Timeout: 5 * time.Second,
}

来设置请求超时,即整个 http 请求到完成响应的时间限制。那么如果想另外设置 tcp 连接阶段的超时可以这样玩:

client := http.Client{
	Transport: &http.Transport{
		Proxy: http.ProxyFromEnvironment,
		Dial: (&net.Dialer{
			Timeout:   2  * time.Second,
			Deadline:  time.Now().Add(3  * time.Second),
			KeepAlive: 2 * time.Second,
		}).Dial,
		TLSHandshakeTimeout: 2 * time.Second,
	},
	Timeout: 5 * time.Second,
}

通过设置 Transport 结构中的 Dial 的属性来实现。如上面的代码中,Dial 的 Timetout 是在 tcp 连接时设置的连接超时,Deadline 则会在超过这个时间后强制关闭连接,在连接无响应的时候回有用。KeepAlive 则会发起心跳,检测连接是否存活。此外,可以设置 TLSHandshakeTimeout 作为 https 握手的超时。具体可以参考 net.Dialer 的文档。由于直接构造了 Transport 结构,不会自动设置 Proxy 属性,这里还得再这里补上。可以用 http.ProxyFromEnvironment 表示根据环境变量来设置,即 http_proxy 和 https_proxy 两个变量设置的 http 代理。如果想强制不使用代理,可以设置为

...
	Proxy: func(*http.Request) (*url.URL, error) {return nil, nil},
...

等待一个独立进程退出并获取 exit code

linux 里,对于进程的子进程,父进程可以用 wait、waitpid 来等待结果。但是对于一个独立的进程就不行了。

有时候想监控一个进程,或者在父进程异常退出后想找回子进程状态,就只能另辟蹊径。于是,想了个通过 ptrace 来跟踪进程退出的办法,做了个小程序:

https://github.com/xiezhenye/waitpid/

可以通过 waitpid 来等待一个独立进程退出并获取 exit code。

不通过 web server 获取 php-fpm 运行状态

php-fpm 可以配置一个 pm.status_path ,如 /status,然后通过 web server 访问这个地址来获取运行状态。但这样会侵入 web server 的配置,在一个 web server 后端有多个 php-fpm 的时候也不方便分别监控每一个后端的状态,为了安全,还要配置访问控制。

好在有个现成的工具 cgi-fcgi,可以把 fcgi 请求包装成 cgi 方式,这样就可以直接在命令行中调用 fastcgi。

cgi-fcgi 在 redhat/centos 中可以用 yum install fcgi 安装,在 ubuntu 中可以用 apt-get install libfcgi-dev 安装。

用以下方式就能获取 php-fpm 的状态了。

path=/status

export REQUEST_METHOD=GET
export SCRIPT_NAME="$path"
export SCRIPT_FILENAME="$path"
export QUERY_STRING=''
# export QUERY_STRING='full'
# export QUERY_STRING='json'
# export QUERY_STRING='full&xml'

addr=/var/run/php-fpm.socket
# addr=127.0.0.1:9000

cgi-fcgi -bind -connect "$addr"

QUERY_STRING 设置为 full 会显示每一个 worker 进程的状态。添加 json、xml、html 可以以不同格式显示结果。

下面是单行脚本的写法和运行结果:

# env REQUEST_METHOD=GET SCRIPT_NAME=/status SCRIPT_FILENAME=/status QUERY_STRING='' cgi-fcgi -bind -connect /var/run/php-fpm.socket
Expires: Thu, 01 Jan 1970 00:00:00 GMT
Cache-Control: no-cache, no-store, must-revalidate, max-age=0
Content-type: text/plain;charset=UTF-8

pool:                 www
process manager:      dynamic
start time:           15/Jan/2016:10:48:15 +0800
start since:          4604
accepted conn:        693119
listen queue:         0
max listen queue:     0
listen queue len:     0
idle processes:       157
active processes:     3
total processes:      160
max active processes: 50
max children reached: 0
slow requests:        17

此种方法也可以用于临时在 php-fpm 环境下执行一个 php 脚本,比如执行一个 phpinfo() 来检查配置是否正确。只需要把脚本中 path=/status 替换成 php 文件路径即可。

MySQL relay_log_purge=0 时的风险

有时候,我们希望将 MySQL 的 relay log 多保留一段时间,比如用于高可用切换后的数据补齐,于是就会设置 relay_log_purge=0,禁止 SQL 线程在执行完一个 relay log 后自动将其删除。但是在官方文档关于这个设置有这么一句话:

Disabling purging of relay logs when using the --relay-log-recovery option risks data consistency and is therefore not crash-safe.

究竟是什么样的风险呢?查找了一番后,基本上明白了原因。

首先,为了让从库是 crash safe 的,必须设置 relay_log_recovery=1,这个选项的作用是,在 MySQL 崩溃或人工重启后,由于 IO 线程无法保证记录的从主库读取的 binlog 位置的正确性,因此,就不管 master_info 中记录的位置,而是根据 relay_log_info 中记录的已执行的 binlog 位置从主库下载,并让 SQL 线程也从这个位置开始执行。MySQL 启动时,相当于执行了 flush logs ,会新开一个 relay log 文件,新的 relay log 会记录在新的文件中。如果默认情况 relay_log_purge=1 时,SQL 线程就会自动将之前的 relay log 全部删除。而当 relay_log_purge=0 时,旧的 relay log 则会被保留。虽然这并不会影响从库复制本身,但还是会有地雷:

  1. 由于崩溃或停止 MySQL 时,SQL 线程可能没有执行完全部的 relay log,最后一个 relay log 中的一部分数据会被重新下载到新的文件中。也就是说,这部分数据重复了两次。
  2. 如果 SQL 跟得很紧,则可能在 IO 线程写入 relay log ,但还没有将同步到磁盘时,就已经读取执行了。这时,就会造成新的文件和旧的文件中少了一段数据。

如果我们读取 relay log 来获取数据,必须注意这一点,否则就会造成数据不一致。而保留 relay log 的目的也在于此。因此,在处理 relay log 时必须格外小心,通过其中 binlog 头信息来确保正确性。

关于如何配置 crash safe 的复制本身的配置,可以参照:
http://blog.itpub.net/22664653/viewspace-1752588/
http://www.innomysql.net/article/34.html

参考资料:
http://blog.booking.com/better_crash_safe_replication_for_mysql.html
https://bugs.mysql.com/bug.php?id=73038
http://bugs.mysql.com/bug.php?id=74324

supervisord 的 fd 泄露问题

线上发现有几个 supervisord 启动的 php 后台进程没有正常工作。上去 strace 了一下,发现卡在了写 stdout 上:

# strace -p 2509
Process 2509 attached - interrupt to quit
write(1, "[2015-05-22 18:48:19]  **************"..., 82

为啥写 stdout 会卡住呢?看了进程 2509 的 fd 1,原来是个管道,那就是管道对面的进程没有读取数据了。于是就查找了一下管道对面是哪个进程。结果却很神奇,管道对面居然也是进程 2509 自己!

# lsof | awk '$8=="124628537" && $9=="pipe"'
php        2509       www    1w     FIFO                0,8       0t0  124628537 pipe
php        2509       www    2w     FIFO                0,8       0t0  124628537 pipe
php        2509       www 1066r     FIFO                0,8       0t0  124628537 pipe
php        2509       www 1067w     FIFO                0,8       0t0  124628537 pipe

这就难怪了,显然 php 自己不会干自己读自己写的事,于是就卡住了。但是这又是怎么造成的呢?看到一个进程自己和自己管道,就想到了这应该是父子进程间用管道 ipc,然后没关干净造成的吧。php 是由 supervisord 启动的,又了解到写往 stdout 的是传给 supervisord 记日志用的,同时发现,这个 php 的父进程已经变成了 1,也就是说,supervisord 曾经挂过。那么这问题很可能就是 supervisord 造成的。那么究竟是怎么形成的,又如何避免呢?

于是就去翻了 supervisors 的代码,终于明白了原因。supervisors 启动子进程的流程是这样的。

  1. 调用 pipe 生成一对管道
  2. fork 生成子进程
    父进程
    1. 关闭管道自己不用的端
    子进程
    1. dup2 将管道的 fd 覆盖掉自己的 0 1 2 即 stdin, stdout, stderr
    2. 关闭 3 ~ minfds 的所有 fd,只保留 0 1 2
    3. 初始化,execve 执行程序替换自身
  3. 这里的 minfds 是通过 supervisord 的启动参数设置的,默认为 1024。在 supervisord 的初始过程中,如果发现环境中的 rlimit 小于设置的值,会试图用 minfd 和 minproc 去设置相应的 rlimit 来满足需求,但是当环境中的 rlimit 大于设置时却没有处理,造成实际使用的 RLIMIT_NOFILE 大于 minfd。

    出问题的 supervisord 并没有设置这个参数,而系统的 rlimit 的默认 max open files 是 10240。pipe 生成的 fd 是 1066,大于 1024,于是就没有被清理掉。原本正常的管道应该是

    php:1 ----------- supervisord: 1066
    

    结果成了

    php:1 ----------- supervisord: 1066
    php:1066 --/
    

    最后在 supervisord 异常退出时,
    原本应该是

    php:1 ----------- XXX
    

    结果成了

    php:1 ----------- XXX
    php:1066 --/
    

    正常情况下,supervisord 挂了,管道也就坏了。php 往坏了的管道写数据就会触发 Broken pipe,默认就也会被干掉,不会造成现在的后果。但是由于有一头没清理掉,管道就还没坏,只是存活两头都是 php 自己,再往里写数据,就由于没人去读而卡死了。

    要解决问题,就必须在启动 supervisord 时设置 `-a/–minfds` 不小于环境中 max open file 值。一个更好的习惯是,让系统的 soft RLIMIT_NOFILE 保持默认的 1024,调大 hard RLIMIT_NOFILE。然后通过 supervisord 的参数来设置需要的 rlimit。这个值也并不是越大越好,在所有进程退出时,和类似 supervisord 启动子进程时都需要遍历关闭 RLIMIT_NOFILE 的所有 fd。值太大会影响系统性能,同时每个进程的 fd 表也会增大,进程数量多的情况下,还是会多费些内存的。

    最后还是去给 supervisord 提交了一个 issue:https://github.com/Supervisor/supervisor/issues/690

设置 linux 命令缓冲模式

默认情况下,*nix 命令的 stdout 和 stdin 如果是在终端中是行缓冲,stderr 则是无缓冲。而这些标准输入输出如果是在管道中或重定向文件则是全缓冲。有时候使用管道处理数据的时候,并不希望管道后面的命令一直阻塞等待前一个的输出填满缓冲区刷新的时候才能处理,而是希望能即时看到数据。

有些命令提供了参数来设置缓冲模式,比如 tcpdump 可以使用 -l 参数来强制设置为行缓冲,awk、grep、sed 等也有这样的参数。但是也还是有很多命令行工具并没有提供这样的功能,这时候可以利用 stdbuf 命令来设置。

比如

stdbuf -oL tcpdump ... | grep ...

就可以把 tcpdump 的 stdout 设置为行缓冲,起到同样的效果。同样可以用 -i, -e 来设置 stdin 和 stderr 的缓冲模式。可以设置为 L 表示行缓冲,0 表示无缓冲,或者设置一个指定的缓冲区大小,如 4K 。这样无论命令是否支持设置缓冲模式都可以解决这些问题了。

使用 row 格式 binlog 撤销操作

MySQL 在使用 row 格式,并使用默认的 binlog_row_image=full 的时候,binlog 中记录了完整的更新前后的数据镜像。因此,根据 row 格式 binlog 进行撤销操作是可行的。我就试着做了这么个工具

[GitHub 页面] [linux 二进制文件]

例如

./binlog_undo -f /data/mysql/log-bin.000004 -p 3958 -o binlog.out

会扫描 /data/mysql/log-bin.000004 从位置 3958 到末尾的所有事务,倒转其中所有事务顺序和每个事务中的语句顺序,并反向所有的操作,把 WRITE 和 DELETE 反转,把 UPDATE 的前后镜像互换,然后将生成后的 binlog 文件写入 binlog.out 中。之后就可以用 mysqlbinlog 工具来回放这个 binlog 来撤销操作了。

这个工具可以用于在主备切换后,撤销掉原主上未同步到备的操作,避免完全重建;也可以作为误操作的后悔药。

记一次 MySQL 循环复制

有朋友的一对 MySQL 出现远大于其他类似实例的大量更新。因为开启了主备双向复制和 log_slave_updates,所以首先猜测是不是有循环复制,主 stop slave 后暂时正常。看了下主上的 relay_log,验证了这一点。幸而来回复制的只是监控用的心跳更新,不会搞坏数据。

但是 MySQL 会比较 server_id ,一般情况下是不会出问题的。于是又仔细看了下主上不正常的 relay_log ,发现其中 event 的 server_id 和当前的都不同。 问下来确实曾经在线改过 server_id。

想了下怎么触发这个问题,在自己的实例上复现了一把

  1. 开启 主->备 的复制
  2. 主上插入若干记录
  3. 更改主的server_id
  4. 开启 备->主 的复制
  5. 轰!

实际操作中,由于存在复制延时,即使没有先停止备->的复制也有可能触发问题。

然后就是怎么拆掉这个雷了。由于来回复制的只是心跳更新,所以只需要跳过就行,其实如果不是的话也已经完蛋没法救了。首先想到的是 binlog_ignore_db 和 replicate_ignore_db 。但是这两个不是动态变量,重启一次服务代价太大。同事 @Tachikoma 提醒我 change master 还有个 ignore_server_ids 选项。于是就只需要 change master to ignore_server_ids (1,2) 忽略之前的 server_id 就行。待复制正常,change master to ignore_server_ids () 就可以解除掉了。