Systemtap examples, Profiling - 3 Determining Time Spent in Kernel and User Space

1 minute read

背景

例子来自thread-times.stp 脚本, 该脚本通过对CPU时钟的跟踪, 使用user_mode()函数判断探针是否为用户模式触发的, 从而区分用户CPU开销还是内核CPU开销. 周期输出用户和系统CPU开销占比以及整个系统的cpu时钟周期统计.  
比如我们想知道系统中那个进程最吃CPU资源, 是内核吃还是用户的操作吃资源.  
脚本内容以及注解 :   
[root@db-172-16-3-150 network]# cd /usr/share/systemtap/testsuite/systemtap.examples/profiling  
[root@db-172-16-3-150 profiling]# cat thread-times.stp  
#!/usr/bin/stap  
  
probe perf.sw.cpu_clock!, timer.profile {    // perf.sw.cpu_clock!匹配的话, 则不触发timer.profile, 如果未匹配则触发timer.profile. 都代表一个CPU时钟周期触发.  
  // NB: To avoid contention on SMP machines, no global scalars/arrays used,  
  // only contention-free statistics aggregates.  // 这里使用统计类型, 而非数组自增(锁).   
  tid=tid(); e=execname()  // 获得线程id, 命令名  
  if (!user_mode())  // user_mode()判断是否用户模式, 否则内核模式  
    kticks[e,tid] <<< 1   // 内核模式  
  else  
    uticks[e,tid] <<< 1  // 用户模式  
  ticks <<< 1  // 记录全局CPU周期数  
  tids[e,tid] <<< 1  // 记录线程相关CPU周期数, 含用户模式和内核模式.  
}  
  
global uticks, kticks, ticks  
  
global tids  
  
probe timer.s(5), end {   // 每5秒输出一次, 或者stap脚本结束时输出  
  allticks = @count(ticks)    // 全局CPU周期数  
  printf ("%16s %5s %7s %7s (of %d ticks)\n",  
          "comm", "tid", "%user", "%kernel", allticks)    // 输出头信息: 命令名, 线程id, 用户CPU开销百分比, 内核开销百分比.   
  foreach ([e,tid] in tids- limit 20) {  
    uscaled = @count(uticks[e,tid])*10000/allticks  // 因为systemtap仅仅支持整型, 放大10000倍, 取2位小数  
    kscaled = @count(kticks[e,tid])*10000/allticks  
    printf ("%16s %5d %3d.%02d%% %3d.%02d%%\n",  
      e, tid, uscaled/100, uscaled%100, kscaled/100, kscaled%100)    // %符号取余数, 得到两位小数.  
  }  
  printf("\n")  
  
  delete uticks  
  delete kticks  
  delete ticks  
  delete tids  
}  
  
执行输出举例 :   
[root@db-172-16-3-150 profiling]# stap thread-times.stp  
            comm   tid   %user %kernel (of 26085 ticks)   // 5秒耗费的时钟周期26085.  
         swapper     0   0.00%  82.46%   // 按照CPU开销的排名.  
        postgres  4540  12.64%   2.20%  
         pgbench  4538   0.88%   1.14%  
        postgres  4533   0.03%   0.45%  
        postgres  4532   0.00%   0.05%  
        postgres  4536   0.00%   0.04%  
       kblockd/0    58   0.00%   0.00%  
    avahi-daemon  1778   0.00%   0.00%  
            date  4559   0.00%   0.00%  
          kipmi0   129   0.00%   0.00%  
              sh  4559   0.00%   0.00%  
              sh  4560   0.00%   0.00%  
     ksoftirqd/0     4   0.00%   0.00%  
     ksoftirqd/4    21   0.00%   0.00%  
            date  4560   0.00%   0.00%  
  
本文事件源代码 :   
[root@db-172-16-3-150 ~]# stap -L 'timer.**'  
timer.profile  
timer.profile.tick  
[root@db-172-16-3-150 ~]# stap -L 'perf.**'  
perf.hw.branch_instructions  
perf.hw.branch_misses  
perf.hw.bus_cycles  
perf.hw.cache_misses  
perf.hw.cache_references  
perf.hw.cpu_cycles  
perf.hw.instructions  
perf.hw_cache.bpu.read.access  
perf.hw_cache.bpu.read.miss  
perf.hw_cache.dtlb.prefetch.access  
perf.hw_cache.dtlb.prefetch.miss  
perf.hw_cache.dtlb.read.access  
perf.hw_cache.dtlb.read.miss  
perf.hw_cache.dtlb.write.access  
perf.hw_cache.dtlb.write.miss  
perf.hw_cache.itlb.read.access  
perf.hw_cache.itlb.read.miss  
perf.hw_cache.l1d.prefetch.access  
perf.hw_cache.l1d.prefetch.miss  
perf.hw_cache.l1d.read.access  
perf.hw_cache.l1d.read.miss  
perf.hw_cache.l1d.write.access  
perf.hw_cache.l1d.write.miss  
perf.hw_cache.l1i.prefetch.access  
perf.hw_cache.l1i.prefetch.miss  
perf.hw_cache.l1i.read.access  
perf.hw_cache.l1i.read.miss  
perf.hw_cache.ll.prefetch.access  
perf.hw_cache.ll.prefetch.miss  
perf.hw_cache.ll.read.access  
perf.hw_cache.ll.read.miss  
perf.hw_cache.ll.write.access  
perf.hw_cache.ll.write.miss  
perf.sw.alignment_faults  
perf.sw.context_switches  
perf.sw.cpu_clock  
perf.sw.cpu_migrations  
perf.sw.emulation_faults  
perf.sw.page_faults  
perf.sw.page_faults_maj  
perf.sw.page_faults_min  
perf.sw.task_clock  
perf.type(0).config(0).sample(1000000).process("").counter("")  
perf.type(0).config(1).sample(1000000).process("").counter("")  
perf.type(0).config(2).sample(1000000).process("").counter("")  
perf.type(0).config(3).sample(1000000).process("").counter("")  
perf.type(0).config(4).sample(1000000).process("").counter("")  
perf.type(0).config(5).sample(1000000).process("").counter("")  
perf.type(0).config(6).sample(1000000).process("").counter("")  
perf.type(1).config(0).sample(1000000).process("").counter("")  
perf.type(1).config(1).sample(1000000).process("").counter("")  
perf.type(1).config(2).sample(1000000).process("").counter("")  
perf.type(1).config(3).sample(1000000).process("").counter("")  
perf.type(1).config(4).sample(1000000).process("").counter("")  
perf.type(1).config(5).sample(1000000).process("").counter("")  
perf.type(1).config(6).sample(1000000).process("").counter("")  
perf.type(1).config(7).sample(1000000).process("").counter("")  
perf.type(1).config(8).sample(1000000).process("").counter("")  
perf.type(3).config(0).sample(1000000).process("").counter("")  
perf.type(3).config(1).sample(1000000).process("").counter("")  
perf.type(3).config(2).sample(1000000).process("").counter("")  
perf.type(3).config(256).sample(1000000).process("").counter("")  
perf.type(3).config(258).sample(1000000).process("").counter("")  
perf.type(3).config(259).sample(1000000).process("").counter("")  
perf.type(3).config(3).sample(1000000).process("").counter("")  
perf.type(3).config(4).sample(1000000).process("").counter("")  
perf.type(3).config(5).sample(1000000).process("").counter("")  
perf.type(3).config(512).sample(1000000).process("").counter("")  
perf.type(3).config(513).sample(1000000).process("").counter("")  
perf.type(3).config(514).sample(1000000).process("").counter("")  
perf.type(3).config(515).sample(1000000).process("").counter("")  
perf.type(3).config(65536).sample(1000000).process("").counter("")  
perf.type(3).config(65537).sample(1000000).process("").counter("")  
perf.type(3).config(65538).sample(1000000).process("").counter("")  
perf.type(3).config(65539).sample(1000000).process("").counter("")  
perf.type(3).config(65540).sample(1000000).process("").counter("")  
perf.type(3).config(65541).sample(1000000).process("").counter("")  
perf.type(3).config(65792).sample(1000000).process("").counter("")  
perf.type(3).config(65794).sample(1000000).process("").counter("")  
perf.type(3).config(65795).sample(1000000).process("").counter("")  
perf.type(3).config(66048).sample(1000000).process("").counter("")  
perf.type(3).config(66049).sample(1000000).process("").counter("")  
perf.type(3).config(66050).sample(1000000).process("").counter("")  
perf.type(3).config(66051).sample(1000000).process("").counter("")  

参考

1. https://sourceware.org/systemtap/SystemTap_Beginners_Guide/mainsect-profiling.html

2. https://sourceware.org/systemtap/examples/

3. /usr/share/systemtap/testsuite/systemtap.examples

4. systemtap-testsuite

5. /usr/share/systemtap/testsuite/systemtap.examples/index.txt

6. /usr/share/systemtap/testsuite/systemtap.examples/keyword-index.txt

7. /usr/share/systemtap/tapset

8. http://blog.163.com/digoal@126/blog/static/16387704020139752612312/

Flag Counter

digoal’s 大量PostgreSQL文章入口