记一个程序员改bug的心路历程，以及具体的方法。方法论上可以模仿，具体的过程谨慎尝试，生命宝贵。
起因
2017年夏天的风静静地吹过，敲着键盘，开开心心地打代码，一切有条不紊地顺利进行，本地调试一遍通过。心想，这只不过是平凡的生命中平凡的一天。嘿，坐等上线。
第二天，下起了淅淅沥沥地的小雨，吃过早饭，打车去某地部署署系统。因为shemi的原因，所有的东西都在无网环境中进行，一切的物理介质除了光盘都被隔离。去接待处上交身份证，换了工卡带上密钥，前往调试间。
望了一眼窗外的小雨，好像有什么悲伤的事情就要发生了。
果然：这个页面的静态资源加载怎么这么慢！！一个CSS文件要40s？？擦了擦眼镜，没看错，不是40ms是40s。
作为一个程序员，第一反应肯定是，偶发的。
于是乎：刷新。
mdzz，怎么还是这么慢。
作为一个程序员，第二反应是，复现问题，查看犯罪现场。
打开chrome的F12，瞅了一眼请求的状态。
很好很强大。
看一眼headers：
一直处于pending的状态。
Provisional headers are shown。
请求没有被发送出去。初步的猜测可能是后端迟迟未返回造成浏览器处于等待状态。这个猜测是很合乎逻辑的，至少能够很合理地解释Chrome Dev Tool 网络面板中我们看到的状态pending。
可能的原因
一般来说，如果看到这个提示，说明这个请求并没有发送出去。具体原因有多种，除了上面提到的情况外，还可能是请求被某些扩展如 Adblock 给拦截了，请求被墙了，走本地缓存或者 dataurl 的请求，也会这样显示。
Chrome插件
经查询，好多人反应这个问题是请求被与网络有关的Chrome插件拦截了。比如Adblock等，可是这个开发环境干净像白莲花一样，完全与外网隔离，我去哪找什么插件。所以chrome插件的犯罪嫌疑很快被派出了。
chrome？
chrome的锅？要不要你来背一下？考虑到前端使用bootstrap以及echarts等，为了兼容性考虑，我选择了chrome作为指定的浏览器。
打开stackoverflow，查到这样一条问题：Ajax request over https hangs for 40 seconds in chrome only 很像啊，我这post请求也是pending的状态。
这锅chrome要不要背呢？作为一个理科生，使用控制变量法，去搞了firefox浏览器。搞这个浏览器也费了很大的劲，去找领导审批刻光盘，再装到生产环境里。
然而，chrome表示这锅我不背，firefox同样GG。
那么问题来了，我们去stackoverflow找一下刚才问题的线索。
- It appears that this issue only happens on the first request for a tab/page in Chrome
- All ajax requests in that same tab/page seem to go through instantly after the first lagging request.
第二条一样，第一条不一样，不过还是有种看到救命稻草的感觉，看看大家有什么要说的。
在追加的问题里看到了这样的一条：
t=1360622033867 [st= 4] HTTP_STREAM_PARSER_READ_HEADERS [dt=38643]
--> net_error = -100 (ERR_CONNECTION_CLOSED)
耗时20秒之久！而且写得非常明显是-100错误，ERR_CACHE_LOCK_TIMEOUT。根据提问者贴出来的链接，了解到Chrome有一个缓存锁的机制。这给我们提供了一点思路。
先看一下这个缓存机制是什么鬼。
至少，症状还是有几分相似的。
仔细追差查 Chromium Code Reviews(http://code.google.com/p/rietveld/wiki/CodeReviewHelp)
这是最近实现的一个补丁，加入了这么个机制，而这个机制的引入又源于2010年的一个issue。具体信息可以通过这个Pages can get blocked in "Waiting for Cache" for a very long time查看，下面引用如下。
Basically here is the situation:
The site author has a long-lived XHR being used to stream a slow response from the server. This XHR response is cachable (it is just really slow). They kick off the XHR asynchronously, and as data slowly arrives on it, update the progressive load of the webpage. Cool.
Now what happens if you try to load this page in multiple tabs of Chrome is: The first page starts to load just fine, but the second one does nothing. What has happened, is the background XHR of the first page load has acquired an exclusive lock to the cache entry, and the background XHR of the second page is stalled at “Waiting for cache…” trying to get a reader access to the cache entry.
Since the first request can takes minutes, this is a problem.
浏览器对一个资源发起请求前，会先检查本地缓存，此时这个请求对该资源对应的缓存的读写是独占的。那么问题来了，试想一下，当我新开一个标签尝试访问同一个资源的时候，这次请求也会去读取这个缓存，假设之前那次请求很慢，耗时很久，那么后来这次请求因为无法获取对该缓存的操作权限就一直处于等待状态。这样很不科学。于是有人建议优化一下。也就是上面所描述的那样。
随着问题的提出，还出了两种可能的实现方案。
(a) [Flexible but complicated] Allow cache readers WHILE writing is in progress. This way the first request could still have exclusive access to the cache entry, but the second request could be streamed the results as they get written to the cache entry. The end result is the second page load would mirror the progress of the first one.
(a) [Naive but simpler] Have a timeout on how long we will block readers waiting for a cache entry before giving up and bypassing the cache.
我猜上面第二个(a)
应该是(b)
。简单说第一种优化方案更加复杂但科学。之前的请求对缓存仍然是独占的，但随着前一次请求不断对缓存进行更新，可以把已经更新的部分拿给后面的请求读取，这样就不会完全阻塞后面的请求了。
第二种方案则更加简单暴力。给后来的请求设定一个读取缓存超时的时限，如果超过了这个时限，我认为缓存不可用或者本地没有缓存，忽略这一步直接发请求。
于是Chromium的开发者们选择了后者简单的实现。也就是Issue 345643003: Http cache: Implement a timeout for the cache lock 这个提交里的实现。
这个提交的描述如下：
The cache has a single writer / multiple reader lock to avoid downloading the same resource n times. However, it is possible to block many tabs on the same resource, for instance behind an auth dialog.
This CL implements a 20 seconds timeout so that the scenario described in the bug results in multiple authentication dialogs (one per blocked tab) so the user can know what to do. It will also help with other cases when the single writer blocks for a long time.
The timeout is somewhat arbitrary but it should allow medium size resources to be downloaded before starting another request for the same item. The general solution of detecting progress and allow readers to start before the writer finishes should be implemented on another CL.
于是就产生了上面题主遇到的情况。
所以他的解决方法就很明朗了，对请求加个时间戳让其变得唯一，或者服务器响应头设置为无缓存。Both will work!
但是，在我这里。我提前已经预想了缓存导致的种种问题，所以在每个post请求中加了随机数。
因此可以排除缓存的干扰。那么似乎这里的缓存锁并不是导致问题的原因，只能另寻他路。不得不说，高兴过后有点失望。
一个值得注意的地方
可喜的是，在细细口味了上面缓存机制引入的过程后，真是耐人寻味。这里不妨八卦一下。相信你也注意到了，上面提到，该缓存问题的提出是在2010年，确切地说是Jun 8, 2010。是的，2010年6月8日由eroman 同学提出。但最后针对该问题进行修复的代码提交却是在今年6月份，2014年6月24日，提交时间摆在那里我会乱说？
于是好奇为什么会拖了这么久，遂跟了一下该问题下面的回复看看发生了什么。简直惊呆了。
同月14号，有了首次对这个问题的回复，那是将该问题指派给了rvargas同学。
一个月过去了，也就是7月15号，rvargas同学指出了与该问题关联的另外一个issue「issue 6697」
接下来是8月5日，rvargas同学为该问题贴上了标签-Mstone-7 Mstone-8 ，表明将会在里程碑7或者8里面进行修复。但在后面的10月7日，这个日程又被推到了-Mstone-8 Mstone-9 。
再接下来11月5日，有人表示以目前的速度及bug数量，还没有时间来修复它，重点在处理优先级为p1的问题上。于是此问题又成功被顺延了，来到-mstone-9 Mstone-10 ，同时优级降为p2。Chromium人手也不够啊，看来。
时间来到12月9日，因为优先级为p2的issue如果没有被标为开始状态的话又自动推到下一个里程碑了，于是顺利来到 -Mstone-10 MovedFrom-10 Mstone-11 。次年2月来到-Mstone-11 Mstone-12 。完成了一次跨年！
…………
上面省略N步。如此反复，最后一次被推到了-Mstone-16 ，那是在2011年10月12日。
时间一晃来到2013年，这一年很平静，前面的几个月都没有人对此问题进行回复。直到11月27日，有人看不下去了，评论道：
This bug has been pushed to the next mstone forever…and is blocking more bugs (e.g https://code.google.com/p/chromium/issues/detail?id=31014)and use-cases same video in 2 tags on one page, and adaptive bit rate html5 video streaming whenever that will kick in. Any chance this will be prioritized?
由于这个bug的无限后延也阻塞了另外一些同类问题，看来是时候解决了。这不，最初的owner 当天就进行了回复：
ecently there was someone looking at giving it another try… I’d have to see if there was any progress there.
If not, I may try to fix it in Q1.
最后一句亮瞎。敢情这之前owner就没有想过要去真正解决似的，因为有其他人在看这个问题了，所以就没管了，如果Q1还没人解决的话，我会出手的！嗯，就是这个意思。
…………
最后，也就是上文提到的，2014年6月，还是rvargas同学对这个问题进行了修复，实现了对缓存读取20秒超时的控制。
该问题就是这样从2010来到2014的。我怀疑Chrome是如何成为版本帝的。
总结
仅有的希望到此似乎都没有了。不过前面的努力也不是没有作何收获，至少我得到了以下有价值的信息：
- 谷歌的神坛光环不再那么耀眼，他们的产品也是有大堆Bug需要处理的
- Chrome 处理issue的效率，当然不排除这种大型项目bug数量跟人力完全不匹配的情况
- 受上面Stackoverflow问题的启发，接下来我将重点转移到了针对出问题请求的日志分析上，并且取得了突破
从直观的报错下手provisional headers are shown
继续上stackoverflow。看到了这个 Caution provisional headers are shown in chrome debugger – esqew May
这个问题有216个赞，心中燃起了希望，作为一个常用的框架，这么大的坑肯定里面装满了前人的尸体，我绝对不是第一个吧 。于是乎兴高采烈的开始看这个问题。
他的描述如下：
Similar to the first question, my resource was blocked, but later automatically loaded the same resource. Unlike the second question, I don't want to fix anything; I want to know what this message means and why I received it.
被赞的最高的一个回答说是插件的锅，这个锅我们已经排除了，所以我决定跳过这里。等等，这个人份给了一点提示：
The way I found about the extension that was blocking my resource was through the net-internals tool in Chrome:
- Type chrome://net-internals in the address bar and hit enter.
- Open the page that is showing problems.
- Go back to net-internals, click on events (###) and use the textfield to find the event related - to your resource (use parts of the URL).
- Finally, click on the event and see if the info shown tells you something
chrome和Firefox为什么受欢迎呢？就是对开发者特别友好。我们开始使用 ** chrome://net-internals** 去看看那个雨天的夜晚到底发生了什么。
1725803: URL_REQUEST
http://10.1.1.56:8081/getIndexnum
Start Time: 2017-06-30 18:04:47.557
t=0 [st=0] +REQUEST_ALIVE [dt=?]
--> has_upload = true
--> is_pending = true
--> load_flags = 33026 (BYPASS_CACHE | MAYBE_USER_GESTURE | VERIFY_EV_CERT)
--> load_state = 15 (WAITING_FOR_RESPONSE)
--> method = "POST"
--> net_error = -1 (ERR_IO_PENDING)
--> status = "IO_PENDING"
--> url = "http://10.1.1.56:8081/getIndexnum"
net_error = -1 (ERR_IO_PENDING)找到了罪犯的凶器，那我们去源代码刘找找这个错在什么条件下触发地。
跳到这个错误描述符地定义的地方，我们找到
// An asynchronous IO operation is not yet complete. This usually does not
// indicate a fatal error. Typically this error will be generated as a
// notification to wait for some external notification that the IO operation
// finally completed.
/异步IO操作尚未完成。 这通常不会
//表示致命错误。 通常这个错误会被生成为一个
//通知等待外部通知IO操作终于完成了
据此，我们可以推断，服务器对这个静态的文件的写操作持续了很久，那为什么会产生这样的问题呢？？？
// ERR_IO_PENDING is returned if the operation could not be completed synchronously, in which case the result will be passed to the callback when available. Returns OK on success.
//如果操作无法同步完成，则返回ERR_IO_PENDING，在这种情况下，结果将被传递给可用的回调。 成功返回OK。
分析到这，我们的好像很明确了，只要解决了服务器回写的问题。目测就OK了。
TCP状态
在linux里面，所有的东西都是文件。我们使用lsof，lsof(list open files)是一个列出当前系统打开文件的工具。在linux环境下，任何事物都以文件的形式存在，通过文件不仅仅可以访问常规数据，还可以访问网络连接和硬件。所以如传输控制协议 (TCP) 和用户数据报协议 (UDP) 套接字等，系统在后台都为该应用程序分配了一个文件描述符，无论这个文件的本质如何，该文件描述符为应用程序与基础操作系统之间的交互提供了通用接口。因为应用程序打开文件的描述符列表提供了大量关于这个应用程序本身的信息，因此通过lsof工具能够查看这个列表对系统监测以及排错将是很有帮助的。
观察一下TCP在请求pending时候的状态。
可以看到很多处于close-wait状态。
这条命令可以用来统计TCP的状态
netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'
从上面的图可以看出来，如果一直保持在CLOSE_WAIT状态，那么只有一种情况，就是在对方关闭连接之后服务器程
序自己没有进一步发出ack信号。换句话说，就是在对方连接关闭之后，程序里没有检测到，或者程序压根就忘记了这个时候需要关闭连接，于是这个资源就一直被程序占着。有一种办法，可以通过配置linux参数来解决。
编辑/etc/sysctl.conf
对于一个新建连接，内核要发送多少个 SYN 连接请求才决定放弃,不应该大于255，默认值是5，对应于180秒左右时间
net.ipv4.tcp_syn_retries=2
net.ipv4.tcp_synack_retries=2
表示当keepalive起用的时候，TCP发送keepalive消息的频度。缺省是2小时，改为300秒
net.ipv4.tcp_keepalive_time=1200
net.ipv4.tcp_orphan_retries=3
表示如果套接字由本端要求关闭，这个参数决定了它保持在FIN-WAIT-2状态的时间
net.ipv4.tcp_fin_timeout=30
表示SYN队列的长度，默认为1024，加大队列长度为8192，可以容纳更多等待连接的网络连接数。
net.ipv4.tcp_max_syn_backlog = 4096
表示开启SYN Cookies。当出现SYN等待队列溢出时，启用cookies来处理，可防范少量SYN攻击，默认为0，表示关闭
net.ipv4.tcp_syncookies = 1
表示开启重用。允许将TIME-WAIT sockets重新用于新的TCP连接，默认为0，表示关闭
net.ipv4.tcp_tw_reuse = 1
表示开启TCP连接中TIME-WAIT sockets的快速回收，默认为0，表示关闭
net.ipv4.tcp_tw_recycle = 1
减少超时前的探测次数
net.ipv4.tcp_keepalive_probes=5
优化网络设备接收队列
net.core.netdev_max_backlog=3000
修改完之后执行/sbin/sysctl -p让参数生效。
此番改动，问题还是依旧存在。
Chrome Dev Tool 中的瀑布流
让我们回到Chrome的dev，看看一个请求pending的时候是卡在哪一个位置了。
Network 面板由五个窗格组成：
- Controls。使用这些选项可以控制 Network 面板的外观和功能。
- Filters。 使用这些选项可以控制在 Requests Table 中显示哪些资源。提示：按住 Cmd (Mac) 或 Ctrl (Windows/Linux) 并点击过滤器可以同时选择多个过滤器。
- Overview。 此图表显示了资源检索时间的时间线。如果您看到多条竖线堆叠在一起，则说明这些资源被同时检索。
- Requests Table。 此表格列出了检索的每一个资源。 默认情况下，此表格按时间顺序排序，最早的资源在顶部。点击资源的名称可以显示更多信息。 提示：右键点击 Timeline 以外的任何一个表格标题可以添加或移除信息列。
- Summary。 此窗格可以一目了然地告诉您请求总数、传输的数据量和加载时间
重点查看单个资源的详细信息
点击资源名称（位于 Requests Table 的 Name 列下）可以查看与该资源有关的更多信息。
可用标签会因您所选择资源类型的不同而不同，但下面四个标签最常见：
- Headers。与资源关联的 HTTP 标头。
- Preview。JSON、图像和文本资源的预览。
- Response。HTTP 响应数据（如果存在）。
- Timing。资源请求生命周期的精细分解。
查看网络耗时
点击 Timing 标签可以查看单个资源请求生命周期的精细分解。
生命周期按照以下类别显示花费的时间：
- Queuing
- Stalled
- 如果适用：DNS lookup、initial connection、SSL handshake
- Request sent
- Waiting (TTFB)
- Content Download
我们发现问题就在这，waiting（TTFB）非常长，在网上查了一下，waiting ttfb是指：等待响应的时间，具体来说是等待返回首个字节的时间。包含了与服务器之间一个来回响应的时间和等待首个字节被返回的时间。
这就意味着对于该请求而言，服务器响应非常慢。
感觉这个地方有点矛盾，既然浏览器开始说请求Provisional headers are shown。没有发出去，waiting TTFB计算的难道是请求发起的时间？暂且认为是这样，唯一的可能是，后端对这个响应很慢。
解读日志文件。
1935612: URL_REQUEST
http://10.1.1.56:8081/static/src/css/global.css
Start Time: 2017-07-01 08:41:02.575
t=11025 [st= 0] +REQUEST_ALIVE [dt=10293] --> priority = "HIGHEST" --> url = "http://10.1.1.56:8081/static/src/css/global.css"t=11025 [st= 0] URL_REQUEST_DELEGATE [dt=0]t=11025 [st= 0] +URL_REQUEST_START_JOB [dt=10292] --> load_flags = 33026 (BYPASS_CACHE | MAYBE_USER_GESTURE | VERIFY_EV_CERT) --> method = "GET" --> url = "http://10.1.1.56:8081/static/src/css/global.css"t=11025 [st= 0] URL_REQUEST_DELEGATE [dt=0]t=11025 [st= 0] HTTP_CACHE_GET_BACKEND [dt=0]t=11025 [st= 0] HTTP_CACHE_DOOM_ENTRY [dt=0] --> net_error = -2 (ERR_FAILED)t=11025 [st= 0] HTTP_CACHE_CREATE_ENTRY [dt=0]t=11025 [st= 0] HTTP_CACHE_ADD_TO_ENTRY [dt=0]t=11025 [st= 0] +HTTP_STREAM_REQUEST [dt=8]t=11025 [st= 0] HTTP_STREAM_JOB_CONTROLLER_BOUND --> source_dependency = 1935614 (HTTP_STREAM_JOB_CONTROLLER)t=11033 [st= 8] HTTP_STREAM_REQUEST_BOUND_TO_JOB --> source_dependency = 1935615 (HTTP_STREAM_JOB)t=11033 [st= 8] -HTTP_STREAM_REQUESTt=11033 [st= 8] +HTTP_TRANSACTION_SEND_REQUEST [dt=0]t=11033 [st= 8] HTTP_TRANSACTION_SEND_REQUEST_HEADERS --> GET /static/src/css/global.css HTTP/1.1 Host: 10.1.1.56:8081 Connection: keep-alive Pragma: no-cache Cache-Control: no-cache User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.109 Safari/537.36 Accept: text/css,/;q=0.1 Referer: http://10.1.1.56:8081/ Accept-Encoding: gzip, deflate Accept-Language: zh-CN,zh;q=0.8,en-US;q=0.6,en;q=0.4t=11033 [st= 8] -HTTP_TRANSACTION_SEND_REQUESTt=11033 [st= 8] +HTTP_TRANSACTION_READ_HEADERS [dt=10284]t=11033 [st= 8] HTTP_STREAM_PARSER_READ_HEADERS [dt=10284]t=21317 [st=10292] HTTP_TRANSACTION_READ_RESPONSE_HEADERS --> HTTP/1.1 200 ETag: "1498817061.99" Content-type: text/css Content-Length: 3435 Last-Modified: Fri, 30 Jun 2017 10:04:21 GMT Date: Sat, 01 Jul 2017 09:08:09 GMT Server: localhostt=21317 [st=10292] -HTTP_TRANSACTION_READ_HEADERSt=21317 [st=10292] HTTP_CACHE_WRITE_INFO [dt=0]t=21317 [st=10292] HTTP_CACHE_WRITE_DATA [dt=0]t=21317 [st=10292] HTTP_CACHE_WRITE_INFO [dt=0]t=21317 [st=10292] URL_REQUEST_DELEGATE [dt=0]t=21317 [st=10292] -URL_REQUEST_START_JOBt=21317 [st=10292] URL_REQUEST_DELEGATE [dt=1]t=21318 [st=10293] HTTP_TRANSACTION_READ_BODY [dt=0]t=21318 [st=10293] HTTP_CACHE_WRITE_DATA [dt=0]t=21318 [st=10293] URL_REQUEST_JOB_FILTERED_BYTES_READ --> byte_count = 1460t=21318 [st=10293] HTTP_TRANSACTION_READ_BODY [dt=0]t=21318 [st=10293] HTTP_CACHE_WRITE_DATA [dt=0]t=21318 [st=10293] URL_REQUEST_JOB_FILTERED_BYTES_READ --> byte_count = 1975t=21318 [st=10293] HTTP_TRANSACTION_READ_BODY [dt=0]t=21318 [st=10293] HTTP_CACHE_WRITE_DATA [dt=0]t=21318 [st=10293] -REQUEST_ALIVE
其中
从请求头发出到解析response的过程的时间是吻合的。问题出在了这里，这一段这么长的时间到底发生了什么？？？？
结论
时间到了这里，然而并没有给出解决方案，但基本排除了前端的问题，很大的可能是框架对静态资源文件的处理。
目前可以得出以下结论：
- 请求在发起的一瞬间被阻塞。至少浏览器认为被阻塞，导致这个请求没有发出去。实际上这个请求已经发出。
- 服务器相应这个请求的时间耗时很长，为什么这么长，排除了最大句柄数的问题。
- 长时间之后，服务器会在某个时刻处理好这些请求，前端页面也就加载出来，只不过这个时间可能非常长。
希望有同学能够跟进这个问题。
