Krikri::TimingProfile

Perf item #0 - --timing-profile.

Every other item in that document is an estimate until the run's wall-clock time can actually be attributed to something. This is the attribution: a process-wide set of named buckets, each holding a call count and an accumulated duration, printed as a trailing block after the PLAY RECAP when --timing-profile was passed.

Off by default and, when off, #measure degrades to a bare yield (it is a yielding method, so the compiler inlines the block) - no Time.monotonic call, no Hash lookup, nothing. That matters because the finest-grained bucket here wraps VarSubstitutor#substitute, which a real role calls tens of thousands of times.

Double counting, and how it is avoided

Buckets nest: SSHManager.upload runs a chmod through SSHManager.exec, ConditionalEvaluator.evaluate renders through VarSubstitutor#substitute. Naively summing both would count the inner time twice and make the percentages meaningless.

So every bucket declares a group. Entering a bucket while the same group is already active on this fiber attributes no additional time (and no additional call) - the outermost measurement in a group owns the whole span. Buckets that deliberately want to report a slice of another bucket (the local ssh process spawn inside an ssh exec, say) simply use a different group, and are printed indented as "nested detail, already included above".

Fibers

The re-entrancy guard is keyed per fiber, not globally: with --forks > 1, run_task_for_hosts_in_parallel has one fiber per host, and host B entering transport while host A is parked inside it is genuine concurrency, not re-entrancy. The flip side is that concurrent hosts' spans overlap in wall-clock terms, so bucket totals can legitimately sum to more than the run's wall clock. The report says so rather than pretending otherwise; --forks 1 gives a strictly additive profile.