记一次线上网络问题排查

之前在和三方贷超rong360接入的时候，一推二推大概2M左右的数据传过来很慢，发现nginx 的access_log有很多400错误，一开始以为是nginx的配置问题，把参数改成client_body_buffer_size 8192k9（原先是4M）还是没用。

然后把nginx error日志的debug打开，error_log                       /var/log/nginx/error.log debug;

在一堆日志中提取了一个请求，

2019/01/11 15:14:04 [debug] 4622#0: *2892975 accept: 124.251.102.8:11693 fd:26
2019/01/11 15:14:04 [debug] 4622#0: *2892975 event timer add: 26: 180000:1547191024308
2019/01/11 15:14:04 [debug] 4622#0: *2892975 reusable connection: 1
2019/01/11 15:14:04 [debug] 4622#0: *2892975 epoll add event: fd:26 op:1 ev:80002001
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http wait request handler
2019/01/11 15:14:04 [debug] 4622#0: *2892975 malloc: 0000563490EBE3C0:131072
2019/01/11 15:14:04 [debug] 4622#0: *2892975 recv: eof:0, avail:1
2019/01/11 15:14:04 [debug] 4622#0: *2892975 recv: fd:26 13275 of 131072
2019/01/11 15:14:04 [debug] 4622#0: *2892975 reusable connection: 0
2019/01/11 15:14:04 [debug] 4622#0: *2892975 posix_memalign: 0000563490EB3370:4096 @16
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http process request line
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http request line: "POST /rongApi/baseInfoPush HTTP/1.1"
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http uri: "/rongApi/baseInfoPush"
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http args: ""
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http exten: ""
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http process request header line
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http header: "Host: axdapi.adpanshi.com"
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http header: "Accept: */*"
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http header: "Content-Type: application/json"
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http header: "Content-Length: 950692"
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http header done
2019/01/11 15:14:04 [debug] 4622#0: *2892975 event timer del: 26: 1547191024308
2019/01/11 15:14:04 [debug] 4622#0: *2892975 generic phase: 0
2019/01/11 15:14:04 [debug] 4622#0: *2892975 rewrite phase: 1
2019/01/11 15:14:04 [debug] 4622#0: *2892975 test location: "/"
2019/01/11 15:14:04 [debug] 4622#0: *2892975 using configuration "/"
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http cl:950692 max:33554432
2019/01/11 15:14:04 [debug] 4622#0: *2892975 rewrite phase: 3
2019/01/11 15:14:04 [debug] 4622#0: *2892975 post rewrite phase: 4
2019/01/11 15:14:04 [debug] 4622#0: *2892975 generic phase: 5
2019/01/11 15:14:04 [debug] 4622#0: *2892975 generic phase: 6
2019/01/11 15:14:04 [debug] 4622#0: *2892975 generic phase: 7
2019/01/11 15:14:04 [debug] 4622#0: *2892975 generic phase: 8
2019/01/11 15:14:04 [debug] 4622#0: *2892975 access phase: 9
2019/01/11 15:14:04 [debug] 4622#0: *2892975 access phase: 10
2019/01/11 15:14:04 [debug] 4622#0: *2892975 access phase: 11
2019/01/11 15:14:04 [debug] 4622#0: *2892975 post access phase: 12
2019/01/11 15:14:04 [debug] 4622#0: *2892975 try files phase: 13
2019/01/11 15:14:04 [debug] 4622#0: *2892975 posix_memalign: 0000563490EB4380:4096 @16
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http client request body preread 13140
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http request body content length filter
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http body new buf t:1 f:0 0000563490EBE447, pos 0000563490EBE447, size: 13140 file: 0, size: 0
2019/01/11 15:14:04 [debug] 4622#0: *2892975 malloc: 0000563490F44410:937552
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http read client request body
2019/01/11 15:14:04 [debug] 4622#0: *2892975 recv: eof:0, avail:0
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http client request body recv -2
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http client request body rest 937552
2019/01/11 15:14:04 [debug] 4622#0: *2892975 event timer add: 26: 180000:1547191024308
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http finalize request: -4, "/rongApi/baseInfoPush?" a:1, c:2
2019/01/11 15:14:04 [debug] 4622#0: *2892975 http request count:2 blk:0
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http run request: "/rongApi/baseInfoPush?"
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http read client request body
2019/01/11 15:14:05 [debug] 4622#0: *2892975 recv: eof:0, avail:1
2019/01/11 15:14:05 [debug] 4622#0: *2892975 recv: fd:26 36012 of 937552
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http client request body recv 36012
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http client request body rest 937552
2019/01/11 15:14:05 [debug] 4622#0: *2892975 event timer del: 26: 1547191024308
2019/01/11 15:14:05 [debug] 4622#0: *2892975 event timer add: 26: 180000:1547191025184
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http run request: "/rongApi/baseInfoPush?"
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http read client request body
2019/01/11 15:14:05 [debug] 4622#0: *2892975 recv: eof:0, avail:1
2019/01/11 15:14:05 [debug] 4622#0: *2892975 recv: fd:26 2920 of 901540
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http client request body recv 2920
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http client request body rest 937552
2019/01/11 15:14:05 [debug] 4622#0: *2892975 event timer: 26, old: 1547191025184, new: 1547191025230
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http run request: "/rongApi/baseInfoPush?"
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http read client request body
2019/01/11 15:14:05 [debug] 4622#0: *2892975 recv: eof:0, avail:1
2019/01/11 15:14:05 [debug] 4622#0: *2892975 recv: fd:26 4380 of 898620
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http client request body recv 4380
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http client request body rest 937552
2019/01/11 15:14:05 [debug] 4622#0: *2892975 event timer: 26, old: 1547191025184, new: 1547191025276
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http run request: "/rongApi/baseInfoPush?"
2019/01/11 15:14:05 [debug] 4622#0: *2892975 http read client request body

。。。。
。。。。

2019/01/11 15:14:43 [debug] 4622#0: *2892975 http client request body recv 13140
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http client request body rest 937552
2019/01/11 15:14:43 [debug] 4622#0: *2892975 event timer: 26, old: 1547191063148, new: 1547191063240
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http run request: "/rongApi/baseInfoPush?"
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http read client request body
2019/01/11 15:14:43 [debug] 4622#0: *2892975 recv: eof:0, avail:1
2019/01/11 15:14:43 [debug] 4622#0: *2892975 recv: fd:26 1460 of 193440
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http client request body recv 1460
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http client request body rest 937552
2019/01/11 15:14:43 [debug] 4622#0: *2892975 event timer: 26, old: 1547191063148, new: 1547191063286
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http run request: "/rongApi/baseInfoPush?"
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http read client request body
2019/01/11 15:14:43 [debug] 4622#0: *2892975 recv: eof:0, avail:1
2019/01/11 15:14:43 [debug] 4622#0: *2892975 recv: fd:26 1460 of 191980
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http client request body recv 1460
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http client request body rest 937552
2019/01/11 15:14:43 [debug] 4622#0: *2892975 event timer del: 26: 1547191063148
2019/01/11 15:14:43 [debug] 4622#0: *2892975 event timer add: 26: 180000:1547191063633
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http run request: "/rongApi/baseInfoPush?"
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http read client request body
2019/01/11 15:14:43 [debug] 4622#0: *2892975 recv: eof:1, avail:1
2019/01/11 15:14:43 [debug] 4622#0: *2892975 recv: fd:26 9876 of 190520
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http client request body recv 9876
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http client request body rest 937552
2019/01/11 15:14:43 [debug] 4622#0: *2892975 recv: eof:1, avail:0
2019/01/11 15:14:43 [debug] 4622#0: *2892975 recv: fd:26 0 of 180644
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http client request body recv 0
2019/01/11 15:14:43 [info] 4622#0: *2892975 client prematurely closed connection, client: 124.251.102.8, server: axdapi.adpanshi.com, request: "POST /rongApi/baseInfoPush HTTP/1.1", host: "axdapi.adpanshi.com"
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http finalize request: 400, "/rongApi/baseInfoPush?" a:1, c:1
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http terminate request count:1
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http terminate cleanup count:1 blk:0
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http posted request: "/rongApi/baseInfoPush?"
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http terminate handler count:1
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http request count:1 blk:0
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http close request
2019/01/11 15:14:43 [debug] 4622#0: *2892975 http log handler
2019/01/11 15:14:43 [debug] 4622#0: *2892975 free: 0000563490F44410
2019/01/11 15:14:43 [debug] 4622#0: *2892975 free: 0000563490EB3370, unused: 0
2019/01/11 15:14:43 [debug] 4622#0: *2892975 free: 0000563490EB4380, unused: 2093
2019/01/11 15:14:43 [debug] 4622#0: *2892975 close http connection: 26
2019/01/11 15:14:43 [debug] 4622#0: *2892975 event timer del: 26: 1547191063633
2019/01/11 15:14:43 [debug] 4622#0: *2892975 reusable connection: 0
2019/01/11 15:14:43 [debug] 4622#0: *2892975 free: 0000563490EBE3C0
2019/01/11 15:14:43 [debug] 4622#0: *2892975 free: 0000563490EBC7C0, unused: 136

可以看到这个请求nginx接收就花了39秒，HTTP request body接收的过程很慢，字节一点点的过来。于是在服务器直接ping了一下，发现延时48ms。后经运维查发现丢包严重，还知道了一个mtr命令。最后运维发现是服务器ip被限速了。