本地IIS托管Web API的IIS日志TimeTakenMS远长于Insights记录时长原因排查

数据老陈

2026-10-6

可能的原因如下：

请求排队开销：IIS应用池请求队列、ASP.NET请求队列的排队时间会被计入TimeTakenMS，但不会被控制器内的StopWatch、仅统计应用内执行时长的Insights采集逻辑捕获。如果请求到达时服务器资源（CPU/内存/磁盘IO）被占满，或瞬间并发量超过队列处理上限，请求会在队列中等待几十秒才进入控制器执行，就会出现你遇到的1秒业务处理+40秒排队的时长差。
IIS管道后续环节开销：你在控制器内统计的是业务代码执行时长，但IIS的TimeTakenMS统计的是从收到第一个请求字节到发送完最后一个响应字节的全周期时长，控制器返回结果后，还要经过HTTP模块后置处理、响应压缩、静态资源处理、响应发送等环节，这些环节的耗时不会被业务代码内的计时捕获。如果开启了IIS动态内容压缩，且服务器CPU高时压缩任务排队，或自定义HTTP模块有后置审计、日志上报等逻辑出现阻塞，都会产生额外耗时。
客户端侧网络/接收延迟：IIS的TimeTakenMS包含响应发送到客户端的全链路网络耗时，如果客户端带宽不足、主动做了流量控制、中途出现临时网络波动导致TCP重传，甚至客户端发起请求后中断连接导致IIS等待超时，都会导致响应发送环节耗时大幅拉长，这部分耗时完全不会被服务端应用层的计时逻辑捕获。
安全防护类模块的主动延迟：如果IIS部署了WAF、动态IP限制、防慢HTTP攻击类模块，这类模块运行在IIS管道最前端，若判定当前请求存在风险，会主动将请求挂起数十秒再执行后续逻辑，或故意降低响应发送速度，这类延迟不会被上层应用感知。
IIS日志相关逻辑阻塞：TimeTakenMS的计时终止点包含IIS本身日志写入的完成时间，如果开启了IIS远程日志写入，且日志存储服务器当时出现网络抖动、写入阻塞，这部分等待时间也会被计入TimeTakenMS，但不会影响应用层的请求处理时长统计。