给自动化脚本的日志加了个「执行耗时」字段，才发现半数任务在空转

上周排查一个备份任务时顺手动了个手脚，把脚本里所有子命令的耗时都记进了日志。本来只是想看看哪个环节慢，结果跑了一周下来，发现真正干活的时间加起来还不到总时长的两成，剩下的全在「等」和「空转」。

具体说下我干了啥：

• 在每个关键步骤前后打了时间戳，算出单步耗时，附到原有日志行后面
• 用 PowerShell 的 Measure-Command 包了一层，避免自己手算时间戳误差
• 加了条判断：单步耗时超过 30 秒就单独记一行 WARN

跑完第一轮拿两台机子对账，问题就冒出来了：

1. 大量任务在「检查条件」而不是「执行」
有个同步任务，日志里 40 多次执行记录，实际有文件变更的只有 6 次。剩下的每次都在跑完整的前置扫描——遍历目录、比对时间戳、算哈希，一套下来 2 分多钟，然后发现没变化直接退出。这类任务适合改成监听文件系统事件，或者至少把扫描间隔拉长。

2. 等待外部进程的耗时被算进了脚本本身
有个调用压缩工具的环节，脚本日志显示耗时 90 秒，但工具自己跑完只要 12 秒。差在哪？脚本用的是同步等待，而那个工具启动时有个几秒的初始化，加上进程退出后的句柄回收，全被算进来了。后来改成异步加轮询检测输出文件，整体压到 15 秒左右。

3. 空转最隐蔽的一种：条件永远为真的判断
这个最坑。有个清理任务，判断条件是「如果临时目录存在就清理」，看着没毛病，但那个目录每次都会被别的程序重新创建，所以每次都在清——清完几秒又回来。日志里看着一直在干活，实际上清的是几秒前刚生成的东西，真正的历史残留反而因为路径规则没覆盖到一直没动。这种靠肉眼看日志根本看不出来，加了耗时字段才发现每轮几乎一样快，快得反常。

判断依据我也说下：耗时字段不能只看单次，我拿两台机子各跑一周，做了个简单统计——单步耗时的标准差。标准差接近零又频繁出现的步骤，基本可以判定为空转或无效执行，因为真实工作耗时不可能每次一模一样。那个「几秒就清完」的步骤标准差只有 0.2 秒，一抓一个准。

手动控制的好处就在这，自动工具只会告诉你「任务已执行」，不会告诉你「执行了个寂寞」。加个耗时字段成本极低，但能把一堆假成功、空转、无效扫描全扒出来。当然前提是你得愿意去看日志、去对账，纯懒人模式就没戏了。

你们平时跑脚本或定时任务，有没有加耗时统计的习惯？如果加了，有没有发现过那种「每次都成功但啥也没干」的步骤，具体是怎么判断出来的？