一般的排查方法

  • 检查error_log

  • 检查access_log

  • strace查看系统调用

  • tcpdump分析网络状况


根据不同问题，要选择合适的方法，最简单的方法还是查看error_log,有些怪异的问题，从error_log中能找到蛛丝马迹。慢请求相关的问题，可以通过access_log记录请求时间。如果log中没有什么可用信息，可以尝试分析一下系统调用或者网络本身。程序本身的问题，可能需要gdb调试。


error_log排查

error_log提供了异常丰富的信息，比如nginx处理请求出错，网络连接出错，后端返回出错，系统调用出错等错误信息，如果是线下调试，则可以开启debug信息，便于调试排查。

  • connect，write，read timeout等网络超时错误

  • Permission denied，File not found等系统调用错误

  • HTTP状态码400，499，500等对应的错误

案例：addops反应了一个很怪异的问题，更新nginx后，http请求不能返回完整的数据，返回部分数据后请求就结束了，每次都能复现。

参看error_log

WEB常见问题排查_java 

access_log排查

access_log提供了客户端访问日子，nginx的access_log可灵活定义日志格式，日志内容，比如后端相应时间，后端返回码，后端的failover过程等，另外，也可以对access_log进行统计，比如根据接口统计，根据客户端IP统计，根据服务端IP统计，根据后端响应时间统计。

  • 统计HTTP状态码比例，从而知道nginx服务状况

  • 统计响应时间，判断超时请求

    • 根据经验，如果响应时间分布集中在某个数字，并且标准差很小，则很可能是因为超时。

    • 统计QPS，对比负载是否均衡

案例：一次nginx灰度过程中，我们选取一台nginx上线，在接下来的半小时内，我们发现nginx占用内存不断增大，直到耗尽系统资源。

  • 排查

    • Error_log中没有发现错误信息

    • 监控发现新上线nginx流量大增

    • 分析access_log,发现新上线nginx的QPS是原机器的6-8倍

  • KEEPalive导致流量负债不均衡

    • LVS作为负载均衡Server时，后端nginx设置的keepalive_timeout时间不能差异过大

LVS负载均衡示意图

  • LVS是TCP层面的负载均衡，只能做到连接的均衡

  • 连接保持的时间越长，导致路由到这个连接额请求越多

WEB常见问题排查_java_02

案例：Nginx反向代理，有时发现某些接口较慢，通常在3s左右

  • Nginx access_log可以记录 upstream_resonse_time

    • 分析access_log的upstream_response_time,发现响应大约3s多

    • 分析后端access_log，处理时间在毫秒级别

    • 最终发现，问题是由于nginx跟后端connect较慢导致

strace排查

strace用来跟踪系统调用，并可以打印丰富的信息，比如系统调用发生的时间，调用耗时，传参内容，调用返回结果等等

  • strace常用参数

    • -tt打印系统调用发生的时间

    • -T打印系统调用耗时

    • -e <name> trace特定系统调用，比如-e open,read,write,close追踪文件的相关调度

    • -s <size> 打印的最大长度

案例：PHP进程hang住

WEB常见问题排查_java_03

futex表示很可能发生死锁

WEB常见问题排查_java_04

strace可以打印出参数值

  • uaddr 0x398ad53594

  • op FUTEX_WAIT_PRIVATEhttp://blogimages.oss.aliyuncs.com/web_problem_strace_2.pngval 2

  • timeout null

可以用strace来验证系统调用耗时，在一次排查PHP问题时，发现PHP处理请求过慢，strace -T 发现是flock调用过慢

WEB常见问题排查_java_05

 

案例：系统负载特别高，能到200多，CPU使用率也特别高，到90%左右，strace没看到什么问题 

  • 分析

    • strace只能追踪系统调用，普通函数是无法trace的

    • CPU很高，说明程序一直在跑，但strace没有异常，说明是用户态代码在消耗CPU

    • 问题必定出现在自己的程序逻辑上

  • 结论

    • 系统上线更换配置文件，导致程序逻辑出错

tcpdump网络抓包

tcpdump是一款强大的网络抓包工具，有时需要确认客户端到nginx或者nginx到后端PHP之间传递的数据是否正确，可以通过抓包对比。同时，对于慢响应，慢连接等网络问题，更需要要tcpdump

  • tcpdump具有强大的表达式机制

    • tcpdump host 10.16.15.41 and port 80 and tcp

    • tcpdump ’tcp[tcpflags] & (tcp-syn|tcp-fin)!=0’

    • tcpdump -w 写文件

    • tcpdump -r 读文件

  • wireshark

案例:还记得刚才提到的慢连接吗？nginx的access_log显示请求响应时间为3s多，而后端却是以毫秒计，那到底哪里慢.

WEB常见问题排查_java_06

其实慢连接的问题，我们线上经常遇到，只是大家没注意或者没在意，通常nginx做反向代理连接后端时，PHP程序在访问后端资源时，或PHP用CURL请求其他接口时，经常出现慢连接的情况

  • 慢连接的根本原因

    • 服务端listen时，设置的backlog太小，导致连接队列很小

    • 连接队列满时，对于新的连接请求，服务端会直接丢失syn包

    • syn包初始重传时间为3s

    • 具体原因可以参考《TCP三次握手之backlog》

综合案例分析

PHP升级的时候，开始运行正常，几天后，系统负载突然上升，达到200-400左右，CPU使用不高，内存使用不高，netstat发现大量PHP进程处于CLOSE_WAIT状态。

  • 排查error_log,access_log没有发现问题

  • nginx不跟PHP在同一台机器上，暂时无法查看其error_log

  • CPU，内容都不高，为什么负载这么高

  • CLOSE_WAIT怎么造成的

从CLOSE_WAIT入手

  • TCP的关闭过程  WEB常见问题排查_java_07

  • 被动关闭的一方，在接收到对方的FIN后，发送自己的FIN前的状态为CLOSE_WAIT

  • 系统调用close，关闭连接，发送FIN

strace分析

  • 从CLOSE_WAIT的状态来看，PHP应该是没有调用close函数导致，程序可能是因为某种原因塞住，从而无法调用CLOSE

  • 通过strace查看PHP进程到底在哪里堵塞，则可查明原因

  • strace发现PHP进程没有堵塞

  • 但是write函数调用失败 WEB常见问题排查_java_08

  • Broken pipe 说明连接已经关闭

  • 调用close了

  • 为什么连接已经关闭？难道是PHP处理太慢导致nginx超时？

  • 从strace上看到，PHP从accept到close，总共耗时1ms左右。nginx不可能超时

tcpdump抓包

  • 用wireshark查看 WEB常见问题排查_java_09

  • 异常1

    • 三次握手nginx发送syn，PHP响应ACK（应该是SYN＋ACK）

  • 异常2

    • NGINX发送FIN关闭连接后，PHP没有发送FIN

  • 异常3

    • 第二个连接的SYN，PHP同样只返回ACK，但ack number确认是上一个连接

结合strace和tcpdump

  • strace WEB常见问题排查_java_10

  • tcpdump WEB常见问题排查_java_11

  • accept 13:30:16,sun:13:27:57

  • accept 调用比接收到SYN晚2分钟多

backlog设置过大

  • SYN三次握手完成以后，socket放到连接队列

  • accept从连接队列获取socket

  • 如果队列过大，等到accept消费到这个socket时，可能已经超时关闭连接

  • 队列中关闭的连接处于CLOSE_WAIT 状态

  • PHP写一个关闭的连接，会报错Broken Pipe

总结

  • 实际问题重视很复杂

  • 找到正确的方向很重要

  • 没有线索时多看看log，系统状态

  • 学会用统计数据来对比

  • 熟悉几个常用的工具

  • 耐心