前几天我写了一个Tcl程序，速度非常慢。即使在我修复了所有的bug之后，它仍然很慢，所以是时候优化它的性能了。我程序优化的第一条规则是无所作为；只需等待更快的机器。不幸的是，在这种情况下，我不能等那么久。

我的第二条优化规则是避免花费任何精力来优化无关紧要的代码，要么是因为它永远不会运行（别笑，这种情况比你想象的要多得多），要么是因为它在程序总运行时间中占用的比例不大。

为了辅助程序优化，Tcl提供了一个 time 命令，用于测量和报告执行Tcl脚本所需的时间。它的调用方式如下

time script count

其中 script 是要计时的Tcl脚本，count 是运行脚本的次数，如果未给出计数，则运行一次。 time 以以下形式报告其结果

3000 microseconds per iteration

该时间是每次脚本计时的平均经过时间。

有时，直接使用 time 命令来计时过程在各种输入下的运行情况非常有用。一旦你确定了应用程序中的“时间消耗大户”过程，就可以用 time 命令以这种方式来衡量重编码技术或新算法（或更快的机器）的性能影响。

然而，对于任何认真的程序优化，都需要更系统的方法。我们可以编写一些使用 time 命令的过程，使我们能够计算整个应用程序的执行时间配置文件。

一种分析应用程序的方法是重写每个过程，用 time 命令包围其主体，其结果可以用某种方式制成表格。由于 Tcl 允许我们询问每个过程的参数和主体，因此过程可以由分析器自动重写。

这种方法的缺点是它只适用于过程，而不适用于内置命令。考虑到加速 Tcl 应用程序的主要方法之一是在 C 中重写一些过程并将它们转换为内置命令，如果能够分析命令以及过程，那就太好了。

与其重写过程，不如重命名它们并编写一个具有原始名称的新过程，该过程调用（并 计时）重命名的版本。这样，就可以对命令和过程进行分析。

第一步是编写替换过程。除了其名称以及它将调用的重命名的原始名称之外，它对于所有过程和命令都将是相同的。实现此目的最简单的方法是编写过程主体模板并使用 format 命令来替换适当的名称。

 proc profile_proc {proc} {
    global Template
    rename $proc $proc:OLD
    set body [format $Template $proc]
    proc $proc args $body
 }

过程 profile_proc 接受 Tcl 过程的名称，通过添加后缀 :OLD 来重命名它，然后使用模板（在 Template 中）编写一个新的过程，该过程对原始过程的调用进行计时。尽管不同的命令和过程将需要不同数量的参数，但通过使用 args，我们可以安排将它们传递给原始 (:OLD) 过程而不更改。

全局变量 Template 包含新过程主体的 format 模板，该模板在两个位置替换过程名称，一个用于调用原始过程，另一个用于记录结果。格式说明符中的 1$ 指示格式的第一个参数应使用两次。

set Template {
    global Profile_fd
    set time [lindex [time {set result \
            [uplevel [list %1$s:OLD] $args]}] 0]
    set level [expr [info level] - 1]
    if {$level > 0} {
        set caller [lindex [info level $level] 0]
        regsub -all {(.*):OLD} $caller {\1} \
        caller
    } else {
        set caller TopLevel
    }
    puts $Profile_fd [list %1$s $time $caller]
    return $result
}

计时信息被写入文件，以便可以离线分析。我们将确保变量 Profile_fd 包含一个文件句柄，我们可以将计时信息写入其中。首先，我们使用 time 运行“原始”命令。通过使用 uplevel，我们可以确保原始命令将在其期望的相同堆栈级别运行，因此如果它使用任何 upvar 命令，它们将正常工作。由于 Tcl 中没有任何东西阻止过程名称中包含特殊字符，因此需要通过 list 命令传递 %s:OLD。过程的原始参数（已收集到单个列表 args 中）通过 uplevel 扩展为原始形式。 lindex 0 仅提取 time 命令输出的时间部分并将其保存在变量 time 中。

为了正确计算每个过程中花费的时间，不仅需要计时过程的名称，还需要其调用者的名称，这在计算所有时间时将显而易见。

info level 命令用于确定调用者的名称（或 TopLevel，如果从顶层调用）。 regsub 去除 :OLD 以使簿记更容易。

最后，过程名称、花费的时间和调用者名称都写入日志文件，并且重命名的过程 result 返回的结果返回给调用者。

过程 profile_start 用于开启性能分析。

proc profile_start {{pattern *}} {
    global Profile_fd
    set Profile_fd [open /tmp/prof.out.[pid] w]
    foreach i [info procs $pattern] {
        profile_proc $i
    }
}

首先，它打开将接收计时信息的文件，并为我们希望分析的过程调用 profile_proc。如果要分析命令以及过程，则可以将 info procs 更改为 info commands。此时，应用程序可以像往常一样运行，只是对于每个分析的命令或过程，都会将一行计时信息写入文件。

要关闭性能分析，请调用 profile_stop。

proc profile_stop {} {
    global Profile_fd
    close $Profile_fd
    foreach proc [info procs *:OLD] {
        regsub {(.*):OLD} $proc {\1} restore
        rename $restore {}
        rename $proc $restore
    }
    profile_summarize /tmp/prof.out.[pid]
}

过程 profile_stop 关闭日志文件，删除特殊的性能分析过程，恢复原始过程的名称，并调用 profile_summarize，后者打印性能分析数据的摘要。更高级版本的 profile_start 和 profile_stop 可以检查以确保过程不会被分析两次，或者不会浪费时间分析性能分析例程。

分析性能分析数据有点棘手。归因于特定过程的时间不仅包括在该过程中花费的时间，还包括在其所有子过程（“被调用”过程）中花费的时间，以及性能分析代码 计时 子过程所花费的时间。

我们可以通过在有和没有性能分析代码的情况下运行一个过程并计算差异来近似估计性能分析代码中花费的时间。过程 profile_calibrate 正是这样做的。

proc profile_calibrate {}
    global Profile_fd
    proc profile_dummy {args} {return $args}
    set Profile_fd [open /tmp/[pid] w]
    time profile_dummy 10
    set before [lindex [time profile_dummy 10] 0]
    profile_proc profile_dummy<\n>
    set after [lindex [time profile_dummy 10] 0]
    close $Profile_fd
    rename profile_dummy {}
    rename profile_dummy:OLD {}
    return [expr ($after - $before)]
}

创建并计时一个虚拟过程 profile_dummy。然后调用 profile_proc 来添加性能分析代码，并再次计时 profile_dummy。结果是对计时开销的近似估计。

proc Incr {name {value 1}} {
    upvar $name var
    if {[info exists var]}  {
        set var [expr $var + $value]
    } else {
        set var $value
    }
}

profile_summarize 过程使用 Tcl incr 命令的增强版本（称为 Incr），该版本允许在设置变量之前 incr 变量，方法是在递增变量之前自动将其初始化为零。

proc profile_summarize {file} {
    puts [format "%35s calls   ms   ms/call %%" \
          name]
    set fd [open $file r]
    set total 0
    set overhead [profile_calibrate]
    # read in the data, and accumulate the values
    while {[gets $fd line] > 0} {
        set name [lindex $line 0]
        set time [lindex $line 1]
        set parent [lindex $line 2]
        Incr count($name)
        Incr sum($name) $time
        if {$parent != "TopLevel"} {
            Incr sum($parent) \
                 "- ($time + $overhead)"
        } else {
            Incr total $time
        }
    }
    close $fd
    # sort and print the results
    foreach name [lsort [array names count]] {
        if {$count($name) == 0} continue
        set ms [expr $sum($name)/1000]
        puts [format "%35s %4d %7d %6d %4.1f%%" \
            $name $count($name)  $ms \
            [expr $ms / $count($name)] \
            [expr $sum($name) * 100.0 / $total]]
    }
}

经过一些初始化后，Profile_summarize 分两个阶段工作，读取和制表计时信息，然后排序和打印结果。

每行计时信息都读入三个变量：过程 name，以 µs 为单位的经过 time，以及 parent 或调用过程名称。两个数组 count 和 sum，都以过程名称为索引，用于跟踪每个过程被调用的次数以及每个过程的累积时间。接下来，将归因于每个过程的时间从记入其父过程的时间中减去，以及计时开销。只有从顶层调用的过程的时间才包含在 total 时间计数器中。否则，时间将被计算两次，一次用于过程，另一次用于其调用者。

一旦所有数据都制成表格，就会按过程名称对其进行排序。结果以过程名称、过程被调用的次数、在过程上花费的总经过时间以及在过程上花费的总程序执行时间的百分比的形式打印。时间值除以 1000 以将它们从 µs 转换为 ms。请注意，大约 35 分钟后，µs 的数量会溢出 32 位整数，因此性能分析运行时间不应超过半小时。

本文底部的列表 1 显示了 HTML 库包的性能分析运行结果的子集。对于此测试用例，很明显 HMrender 在程序的总运行时间中占了很大的比例。即使可以将其重编码为无限快地运行，整个应用程序的速度最多也只能提高 27%。归因于 HMtag_a 的负时间可能是由于性能分析开销计算的可变性造成的。

日志文件中的数据如下所示

...
HMrender 152083 HMparse_html
HMmap_esc 553 HMrender
HMzap_white 629 HMrender
HMx_font 3056 HMcurrent_tags
HMset_font 2022 HMcurrent_tags
HMcurrent_tags 14424 HMrender
...

即使过程的经过时间可能存在相当大的可变性，具体取决于处理器上的当前负载，这些简单的性能分析例程也可以快速指出应用程序中占用大部分运行时间的部分，并且这些部分将是优化的良好候选对象。

列表 1：示例运行

% source sample.tcl
Starting sample HTML viewer...
% source ~/column/profile/test
% profile_start
  [Run the application for a bit]
% profile_stop

HMextract_param