一种定位服务超时的方法

背景：

服务器端的后端服务通常会基于某个框架（比如spring）开发业务逻辑，在进入某个服务的业务逻辑前通常由框架接收请求并进行参数封装，然后调用业务代码，如果直接在业务代码里通过打印日志记录请求进入时间，当请求量大到一定程度时打印出的时间是会产生误差的，因为服务本身由于高并发的性能瓶颈会出现卡顿，这样服务自身记录时间就会存在延迟，数据不准确导致无法作为问题定位的依据，这样就无法判断请求真正进入后端服务的时间。对于这种问题目前比较常见的排查方法主要是通过网卡抓包的形式，通过抓包工具（比如tcpdump）监听服务所在服务器的网卡，记录请求到达网卡的时间来确认请求是否发出。例如客户端A发出请求，当请求到达服务B时，抓包工具会记录请求到达服务B的时间，服务B继续请求服务C，此时抓包工具会继续记录服务C收到请求的时间，以及服务C返回请求后服务B收到请求返回的时间，最后根据对比服务B收到客户端A发出请求的时间，以及服务C收到服务B发出请求的时间，和服务B收到服务C返回请求的时间，通过三个时间可以确定以下3种情况：1、因为服务B发生了请求积压导致没有及时请求服务C导致超时；2、服务B发出了请求，并且请求到达了C，但是服务C没有来得及处理请求导致的超时；3、服务B请求了C，并且C在规定时间内返回了请求，但是B收到请求后，在后续处理结果数据超时，导致没有及时将结果返回给客户端导致超时。但是抓包方法效率非常低，因为抓包工具会记录经过网卡的所有数据，当请求量极大时，抓包工具抓到的数据包会非常大，此时需要解析数据包，通过对比每个请求发出的时间和返回的时间效率会很低，也极为不便。

通过在服务间增加代理服务器，由于代理服务器只做请求转发功能，没有其他业务逻辑，几乎可以认为不存在延迟，通过代理服务器记录的请求发出和返回时间，可以准确知道请求何时发出以及返回，能快速定位超时问题发生位置。

在一个应用系统中通常有多个服务，且服务之间存在依赖关系。 该发明整体结构如下图：首先客户端A发出请求，服务B接收到请求，此时B需要请求服务C，这时B不是直接请求C，而是请求nginx服务器，由nginx服务器将请求转发到C，C收到请求后执行业务逻辑，执行完毕返回结果数据给nginx，nginx服务器将数据重新返回给B，B拿到结果后再进行其他的逻辑处理，最后将结果返回给客户端A。 此时服务器记录了B发出请求的时间， 五、本发明创造的效果和优点：结合发明创造的结构特征写明其与现有技术相比具有的优点：比如产率、质量、精度和效率的提高，能耗、原材料、工序的节省；加工、操作、控制、使用的简便，环境污染的治理或根治等。    可以根据服务B，nginx代理服务，服务C三方记录的请求到达和返回时间，通过脚本进行数据分析处理，可以快速定位每次请求的超时瓶颈属于哪种类型，找到问题原因，然后能针对性的对服务进行性能优化，提升服务质量，降低超时情况。

例如客户端A请求服务B时，希望服务B能在规定时间（假设1s）内返回，服务B又依赖了服务C，此时服务B调用服务C时期望服务C能在规定时间（假设100ms）内返回。当同一时刻客户端A大量请求服务B时，会出现超时返回的情况，此时超时原因可能有以下几种： 1.客户端A发出的请求在服务端B发生了积压，积压时间已经超过1s，此时1s后服务B再去请求服务C时，即使该请求到达了服务C，但是实际上该次请求已经超时。 2.客户端A发出的请求已经到达了服务端B，服务B继续请求服务C，服务C收到了请求，但是处理时间过长，导致请求返回B的时间已经超过了100ms，该次请求整体还是超时。 3.客户端A发出的请求已经到达了服务端B，服务B继续请求服务C，服务C收到了请求并在规定时间100ms内返回了请求，服务B收到了请求但是由于B还有业务处理逻辑，导致没有在整体时间1s内返回请求给客户端A，该次请求整体超时。 对于这3种情况，可以通过增设代理层(例如使用nginx服务)，配置请求转发，并记录请求的到达时间和返回时间，可以快速定位超时原因是哪种。 对于这3种情况，分别绘制了流程图，可参见附图： 同时对nginx做如下配置： log_format main ‘$http_requestid $remote_addr $upstream_addr [$time_local.$msec] ’ $status $upstream_status $request_time $upstream_response_time’; Server { listen 8888; location  / { proxy_pass http://127.0.0.1:6666 }

解释： time_local：是nginx收到请求的时间 request_time：是ngxin将请求转发给服务C的时间，可以近似认为是服务C收到请求的时间 upstream_response_time：是指从nginx向服务C建立连接开始到接收完数据然后关闭连接为止的时间 可以利用upstream_response_time来记录服务C响应所花费的时间，从日志时间开始，经过upstream_response_time，表明这是服务C响应的时间，再和服务B打印的耗时，做对比，来区分问题原因是哪种。