这是在系统运行了大约一个小时后,加上用户的少许配合,生成的一个简约报告的开始部分:
代码: 全选
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls us/call us/call name
93.97 139.13 139.13 idle
5.87 147.82 8.69 23 377826.09 377842.52 check_exec
0.01 147.84 0.02 243 82.30 82.30 pmap_copy_page
0.01 147.86 0.02 131 152.67 152.67 _wdc_ata_bio_start
0.01 147.88 0.02 131 152.67 271.85 wdc_ata_bio_intr
0.01 147.89 0.01 4428 2.26 2.66 uvn_findpage
0.01 147.90 0.01 4145 2.41 2.41 uvm_pageactivate
0.01 147.91 0.01 2473 4.04 3532.40 syscall_plain
0.01 147.92 0.01 1717 5.82 5.82 i486_copyout
0.01 147.93 0.01 1430 6.99 56.52 uvm_fault
0.01 147.94 0.01 1309 7.64 7.64 pool_get
0.01 147.95 0.01 673 14.86 38.43 genfs_getpages
0.01 147.96 0.01 498 20.08 20.08 pmap_zero_page
0.01 147.97 0.01 219 45.66 46.28 uvm_unmap_remove
0.01 147.98 0.01 111 90.09 90.09 selscan
...
代码: 全选
...
0.00 164.14 0.00 37 0.00 62747.49 check_exec
...
代码: 全选
...
-----------------------------------------------
0.00 8.69 23/23 syscall_plain [3]
[4] 5.9 0.00 8.69 23 sys_execve [4]
8.69 0.00 23/23 check_exec [5]
0.00 0.00 20/20 elf32_copyargs [67]
...[code]
注意 time值为8.69 这个函数是怎样影响前面的两个函数的。 它们之中有地方出问题了, 但是, 后面的例子中 check_exec 看起来似乎不同:
-----------------------------------------------
8.69 0.00 23/23 sys_execve [4]
[5] 5.9 8.69 0.00 23 check_exec [5]
...
现在我们找到这个问题所在了, 很有可能就在 check_exec 里. 当然了, 问题不可能总是如此简单,而事实上, 这里有一个"傻瓜"代码正好被插入到 check_exec (这个函数在 sys/kern/kern_exec.c)后面:
...
/* A Cheap fault insertion */
for (x = 0; x < 100000000; x++) {
y = x;
}
..
[/code]
并不起眼, 但是足以在分析报告中产生很大的变化。