dtrace 函数时间跟踪，没有也跟踪的调用函数

Question

我想记录每个函数使用了多少 CPU 时间。这里需要注意的是，我只想记录函数本身使用的时间，而不是函数调用并且我的脚本也跟踪的函数使用的 cpu 时间。例如如果函数 foo 和 bar 都被我的脚本跟踪并且函数 foo 的总 cpu 时间是 2000，但是函数 foo 调用函数 bar 3 次，每次花费 500 cpu 时间，那么我希望看到以下结果：

function  cputime   call count
foo           500            1
bar          1500            3

现在我有以下 dtrace 脚本来获取每个函数的总 cpu 时间，但我还没有任何关于如何更改它以便我得到如上所述的 cpu 时间结果的线索。 （注意调用计数和输出格式还没有在脚本中，但是一旦我有了我所追求的 cpu 时间信息，这些很容易添加。）

#!/usr/sbin/dtrace -s

pid$1:$2::entry
{
    ++self->call_depth[probefunc];

    self->start[probefunc, self->call_depth[probefunc]] = timestamp;
    self->vstart[probefunc, self->call_depth[probefunc]] = vtimestamp;
}

pid$1:$2::return
/self->start[probefunc, self->call_depth[probefunc]]/
{
    @function_walltime[probefunc] = sum(timestamp - self->start[probefunc, self->call_depth[probefunc]]);
    self->start[probefunc, self->call_depth[probefunc]] = 0;
    @function_cputime[probefunc] = sum(vtimestamp - self->vstart[probefunc, self->call_depth[probefunc]]);
    self->vstart[probefunc, self->call_depth[probefunc]] = 0;

    --self->call_depth[probefunc];
}

Answer 1

这是我最终使用的程序：

#!/usr/sbin/dtrace -s
#pragma option quiet

pid$1:$2::entry
/self->start[probefunc] == 0/
{
    this->call_depth = self->call_depth++;
    self->func_pcs[this->call_depth] = uregs[R_PC];

    self->start[probefunc] = timestamp;
    self->vstart[probefunc] = vtimestamp;

    @function_entry_count[ufunc(uregs[R_PC])] = count();
}

pid$1:$2::return
/self->start[probefunc]/
{
    this->call_depth = --self->call_depth;

    this->wall_elapsed = timestamp - self->start[probefunc];
    self->start[probefunc] = 0;
    this->cpu_elapsed = vtimestamp - self->vstart[probefunc];
    self->vstart[probefunc] = 0;

    @function_walltime_inc[ufunc(uregs[R_PC])] = sum(this->wall_elapsed);
    @function_walltime_exc[ufunc(uregs[R_PC])] = sum(this->wall_elapsed);
    @function_cputime_inc[ufunc(uregs[R_PC])] = sum(this->cpu_elapsed);
    @function_cputime_exc[ufunc(uregs[R_PC])] = sum(this->cpu_elapsed);
    @function_return_count[ufunc(uregs[R_PC])] = count();
}       

pid$1:$2::return
/this->call_depth > 0/
{
    this->caller_pc = self->func_pcs[this->call_depth - 1];
    @function_walltime_exc[ufunc(this->caller_pc)] = sum(-(this->wall_elapsed));
    @function_cputime_exc[ufunc(this->caller_pc)] = sum(-(this->cpu_elapsed));
}       

dtrace:::END
{       
    /* normalize to millisecons */
    normalize(@function_walltime_inc, 1000000);
    normalize(@function_walltime_exc, 1000000);
    normalize(@function_cputime_inc, 1000000);
    normalize(@function_cputime_exc, 1000000);

    printf("\n");
    printf("%-60s %21s %21s %25s\n", "", "INCLUSIVE", "EXCLUSIVE", "CALL COUNT");
    printf("%-60s %10s %10s %10s %10s %12s %12s\n",
            "MODULE`FUNCTION", "WALL [ms]", "CPU [ms]", "WALL [ms]", "CPU [ms]", "ENTRY", "RETURN");
    printa("%-60A %@10d %@10d %@10d %@10d %@12d %@12d\n",
            @function_walltime_inc, @function_cputime_inc,
            @function_walltime_exc, @function_cputime_exc,
            @function_entry_count, @function_return_count);
}

注意：我正在跟踪函数入口计数和返回计数，因为某些函数 dtrace 无法正确检测函数返回，这完全弄乱了调用堆栈，因此也弄乱了独占时间。通过打印这两个计数，可以识别有问题的功能，并在必要时从跟踪中删除。

Answer 2

希望以下脚本可以提供帮助：

#!/usr/sbin/dtrace -qs

pid$1:$2::entry
{
    self->vstart[probefunc] = vtimestamp;
}

pid$1:$2::return
{
    this->cputime = vtimestamp - self->vstart[probefunc];
    /* Sub the caller function CPU time */
    @function_cputime[ufunc(ucaller)] = sum(-(this->cputime));
    /* Add the callee function (current function) CPU time */
    @function_cputime[ufunc(uregs[R_PC])] = sum(this->cputime); 
    /* Add the callee function (current function) count */
    @function_count[ufunc(uregs[R_PC])] = sum(1);
}