4.3. プロファイリング

以下のセクションでは、関数コールを監視することでカーネルアクティビティーのプロファイルを実行するスクリプトを説明します。

4.3.1. 関数コールのカウント

このセクションでは、30 秒間のサンプルで特定のカーネル関数をシステムが呼び出した回数を特定する方法を説明します。ワイルドカードの使用によっては、このスクリプトを使用して複数のカーネル関数を対象とすることもできます。

例4.21 functioncallcount.stp

#! /usr/bin/env stap
# The following line command will probe all the functions
# in kernel's memory management code:
#
# stap  functioncallcount.stp "*@mm/*.c"

probe kernel.function(@1).call {  # probe functions listed on commandline
  called[probefunc()] <<< 1  # add a count efficiently
}

global called

probe end {
  foreach (fn in called-)  # Sort by call count (in decreasing order)
  #       (fn+ in called)  # Sort by function name
    printf("%s %d\n", fn, @count(called[fn]))
  exit()
}
例4.21「functioncallcount.stp」 は、ターゲットカーネルの関数を引数として取ります。この引数はワイルドカードに対応しているので、ある程度までの複数のカーネル関数をターゲットにできます。
例4.21「functioncallcount.stp」 の出力には、サンプル時間中に呼び出された関数の名前とその回数がアルファベット順に表示されます。例4.22「例4.21「functioncallcount.stp」 のサンプル出力」 は、stap functioncallcount.stp "*@mm/*.c" の出力抜粋になります。

例4.22 例4.21「functioncallcount.stp」 のサンプル出力

[...]
__vma_link 97
__vma_link_file 66
__vma_link_list 97
__vma_link_rb 97
__xchg 103
add_page_to_active_list 102
add_page_to_inactive_list 19
add_to_page_cache 19
add_to_page_cache_lru 7
all_vm_events 6
alloc_pages_node 4630
alloc_slabmgmt 67
anon_vma_alloc 62
anon_vma_free 62
anon_vma_lock 66
anon_vma_prepare 98
anon_vma_unlink 97
anon_vma_unlock 66
arch_get_unmapped_area_topdown 94
arch_get_unmapped_exec_area 3
arch_unmap_area_topdown 97
atomic_add 2
atomic_add_negative 97
atomic_dec_and_test 5153
atomic_inc 470
atomic_inc_and_test 1
[...]

4.3.2. 呼び出し先の追跡

このセクションでは、着信および発信関数コールを追跡する方法を説明します。

例4.23 para-callgraph.stp

#! /usr/bin/env stap

function trace(entry_p, extra) {
  %( $# > 1 %? if (tid() in trace) %)
  printf("%s%s%s %s\n",
         thread_indent (entry_p),
         (entry_p>0?"->":"<-"),
         probefunc (),
         extra)
}


%( $# > 1 %?
global trace
probe $2.call {
  trace[tid()] = 1
}
probe $2.return {
  delete trace[tid()]
}
%)

probe $1.call   { trace(1, $$parms) }
probe $1.return { trace(-1, $$return) }
例4.23「para-callgraph.stp」 は、以下の 2 つのコマンドライン引数を取っています。
  • その開始と終了が追跡対象となっている関数 ($1)。
  • 2 つ目のオプションとなる trigger function ($2)。これは、スレッドごとの追跡を有効、無効にします。trigger function が終了していなければ、各スレッドにおける追跡は継続されます。
例4.23「para-callgraph.stp」 では thread_indent() を使用しているので、その出力には、$1 (追跡しているプローブ関数) のタイムスタンプ、プロセス名、およびスレッド ID が含まれます。thread_indent() に関する詳細情報は、SystemTap 関数 のエントリーを参照してください。
以下は、stap para-callgraph.stp 'kernel.function("*@fs/*.c")' 'kernel.function("sys_read")' の出力抜粋例になります。

例4.24 例4.23「para-callgraph.stp」 のサンプル出力

[...]
   267 gnome-terminal(2921): <-do_sync_read return=0xfffffffffffffff5
   269 gnome-terminal(2921):<-vfs_read return=0xfffffffffffffff5
     0 gnome-terminal(2921):->fput file=0xffff880111eebbc0
     2 gnome-terminal(2921):<-fput 
     0 gnome-terminal(2921):->fget_light fd=0x3 fput_needed=0xffff88010544df54
     3 gnome-terminal(2921):<-fget_light return=0xffff8801116ce980
     0 gnome-terminal(2921):->vfs_read file=0xffff8801116ce980 buf=0xc86504 count=0x1000 pos=0xffff88010544df48
     4 gnome-terminal(2921): ->rw_verify_area read_write=0x0 file=0xffff8801116ce980 ppos=0xffff88010544df48 count=0x1000
     7 gnome-terminal(2921): <-rw_verify_area return=0x1000
    12 gnome-terminal(2921): ->do_sync_read filp=0xffff8801116ce980 buf=0xc86504 len=0x1000 ppos=0xffff88010544df48
    15 gnome-terminal(2921): <-do_sync_read return=0xfffffffffffffff5
    18 gnome-terminal(2921):<-vfs_read return=0xfffffffffffffff5
     0 gnome-terminal(2921):->fput file=0xffff8801116ce980

4.3.3. カーネルおよびユーザースペースで費やした時間の判定

このセクションでは、スレッドがカーネルまたはユーザースペースで費やした時間を判定する方法を説明します。

例4.25 thread-times.stp

#! /usr/bin/env stap

probe perf.sw.cpu_clock!, timer.profile {
  // NB: To avoid contention on SMP machines, no global scalars/arrays used,
  // only contention-free statistics aggregates.
  tid=tid(); e=execname()
  if (!user_mode())
    kticks[e,tid] <<< 1
  else
    uticks[e,tid] <<< 1
  ticks <<< 1
  tids[e,tid] <<< 1
}

global uticks, kticks, ticks

global tids

probe timer.s(5), end {
  allticks = @count(ticks)
  printf ("%16s %5s %7s %7s (of %d ticks)\n",
          "comm", "tid", "%user", "%kernel", allticks)
  foreach ([e,tid] in tids- limit 20) {
    uscaled = @count(uticks[e,tid])*10000/allticks
    // SystemTap only performs integer arithmetic.
    // To avoid losing precision the decimal point is shifted
    // to the right four places (*100000). Think of this as
    // the original result value x.xxyy becoming xxxyy.0.
    // The integer percentage xxx is obtained
    // by dividing by 100 and the fractional percentage
    // is obtained with a modulo 100 operation.
    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
}
例4.25「thread-times.stp」 は、5 秒間のサンプル内で CPU 時間を占めている上位 20 位のプロセスと、CPU ティックの総数を一覧表示します。このスクリプトの出力は、各プロセスが使用した CPU 時間のパーセント表示と、その時間がカーネルスペースかユーザースペースで費やされたかも示します。
例4.26「例4.25「thread-times.stp」 のサンプル出力」 は、例4.25「thread-times.stp」 の 5 秒間サンプルの出力です。

例4.26 例4.25「thread-times.stp」 のサンプル出力

  tid   %user %kernel (of 20002 ticks)
    0   0.00%  87.88%
32169   5.24%   0.03%
 9815   3.33%   0.36%
 9859   0.95%   0.00%
 3611   0.56%   0.12%
 9861   0.62%   0.01%
11106   0.37%   0.02%
32167   0.08%   0.08%
 3897   0.01%   0.08%
 3800   0.03%   0.00%
 2886   0.02%   0.00%
 3243   0.00%   0.01%
 3862   0.01%   0.00%
 3782   0.00%   0.00%
21767   0.00%   0.00%
 2522   0.00%   0.00%
 3883   0.00%   0.00%
 3775   0.00%   0.00%
 3943   0.00%   0.00%
 3873   0.00%   0.00%

4.3.4. ポーリングアプリケーションの監視

このセクションでは、どのアプリケーションがポーリングを行なっているかを特定、監視する方法を説明します。これを行うことで、不必要または過剰なポーリングが追跡でき、CPU の使用量および省電力を改善するエリアを特定できるようになります。

例4.27 timeout.stp

#! /usr/bin/env stap
# Copyright (C) 2009 Red Hat, Inc.
# Written by Ulrich Drepper <drepper@redhat.com>
# Modified by William Cohen <wcohen@redhat.com>

global process, timeout_count, to
global poll_timeout, epoll_timeout, select_timeout, itimer_timeout
global nanosleep_timeout, futex_timeout, signal_timeout

probe syscall.poll, syscall.epoll_wait {
  if (timeout) to[pid()]=timeout
}

probe syscall.poll.return {
  p = pid()
  if ($return == 0 && to[p] > 0 ) {
    poll_timeout[p]++
    timeout_count[p]++
    process[p] = execname()
    delete to[p]
  }
}

probe syscall.epoll_wait.return {
  p = pid()
  if ($return == 0 && to[p] > 0 ) {
    epoll_timeout[p]++
    timeout_count[p]++
    process[p] = execname()
    delete to[p]
  }
}

probe syscall.select.return {
  if ($return == 0) {
    p = pid()
    select_timeout[p]++
    timeout_count[p]++
    process[p] = execname()
  }
}

probe syscall.futex.return {
  if (errno_str($return) == "ETIMEDOUT") {
    p = pid()
    futex_timeout[p]++
    timeout_count[p]++
    process[p] = execname()
  }
}

probe syscall.nanosleep.return {
  if ($return == 0) {
    p = pid()
    nanosleep_timeout[p]++
    timeout_count[p]++
    process[p] = execname()
  }
}

probe kernel.function("it_real_fn") {
  p = pid()
  itimer_timeout[p]++
  timeout_count[p]++
  process[p] = execname()
}

probe syscall.rt_sigtimedwait.return {
  if (errno_str($return) == "EAGAIN") {
    p = pid()
    signal_timeout[p]++
    timeout_count[p]++
    process[p] = execname()
  }
}

probe syscall.exit {
  p = pid()
  if (p in process) {
    delete process[p]
    delete timeout_count[p]
    delete poll_timeout[p]
    delete epoll_timeout[p]
    delete select_timeout[p]
    delete itimer_timeout[p]
    delete futex_timeout[p]
    delete nanosleep_timeout[p]
    delete signal_timeout[p]
  }
}

probe timer.s(1) {
  ansi_clear_screen()
  printf ("  pid |   poll  select   epoll  itimer   futex nanosle  signal| process\n")
  foreach (p in timeout_count- limit 20) {
     printf ("%5d |%7d %7d %7d %7d %7d %7d %7d| %-.38s\n", p,
              poll_timeout[p], select_timeout[p],
              epoll_timeout[p], itimer_timeout[p],
              futex_timeout[p], nanosleep_timeout[p],
              signal_timeout[p], process[p])
  }
}
例4.27「timeout.stp」 は、各アプリケーションが以下のシステムコールを使用した回数を追跡します。
  • poll
  • select
  • epoll
  • itimer
  • futex
  • nanosleep
  • signal
いくつかのアプリケーションでは、これらのシステムコールは過剰に使用されています。このため、これらは通常、ポーリングアプリケーションの「有力な容疑者」として特定されます。ただし、アプリケーションが異なるシステムコールを使用して過剰にポーリングしている場合もあります。場合によっては、システムが使用している上位のシステムコールを見つけることが便利なこともあります (手順は 「最もよく使われるシステムコールの追跡」 を参照してください)。これを行うことで新たな容疑者を特定でき、例4.27「timeout.stp」 に追加して追跡することができます。

例4.28 例4.27「timeout.stp」 のサンプル出力

  uid |   poll  select   epoll  itimer   futex nanosle  signal| process
28937 | 148793       0       0    4727   37288       0       0| firefox
22945 |      0   56949       0       1       0       0       0| scim-bridge
    0 |      0       0       0   36414       0       0       0| swapper
 4275 |  23140       0       0       1       0       0       0| mixer_applet2
 4191 |      0   14405       0       0       0       0       0| scim-launcher
22941 |   7908       1       0      62       0       0       0| gnome-terminal
 4261 |      0       0       0       2       0    7622       0| escd
 3695 |      0       0       0       0       0    7622       0| gdm-binary
 3483 |      0    7206       0       0       0       0       0| dhcdbd
 4189 |   6916       0       0       2       0       0       0| scim-panel-gtk
 1863 |   5767       0       0       0       0       0       0| iscsid
 2562 |      0    2881       0       1       0    1438       0| pcscd
 4257 |   4255       0       0       1       0       0       0| gnome-power-man
 4278 |   3876       0       0      60       0       0       0| multiload-apple
 4083 |      0    1331       0    1728       0       0       0| Xorg
 3921 |   1603       0       0       0       0       0       0| gam_server
 4248 |   1591       0       0       0       0       0       0| nm-applet
 3165 |      0    1441       0       0       0       0       0| xterm
29548 |      0    1440       0       0       0       0       0| httpd
 1862 |      0       0       0       0       0    1438       0| iscsid
2 つ目のプローブのタイマー (timer.s()) を編集すると、サンプル時間を長くすることができます。例4.21「functioncallcount.stp」 の出力には、上位 20 位のポーリングアプリケーションの名前と UID、各アプリケーションがシステムコールのポーリングを行った回数が含まれています。例4.28「例4.27「timeout.stp」 のサンプル出力」 はスクリプトの抜粋になります。

4.3.5. 最もよく使われるシステムコールの追跡

「ポーリングアプリケーションの監視」 の 例4.27「timeout.stp」 では、以下のシステムコールを最もよく使用したものを挙げることで、どのアプリケーションがポーリングを行なっているかを特定します。
  • poll
  • select
  • epoll
  • itimer
  • futex
  • nanosleep
  • signal
ただしシステムによっては、別のシステムコールが過剰なポーリングを行なっている可能性もあります。ポーリングしているアプリケーションがポーリングに異なるシステムコールを使用していることが疑われる場合は、まずシステムが使用している上位のシステムコールを特定する必要があります。これには、例4.29「topsys.stp」 を使用します。

例4.29 topsys.stp

#! /usr/bin/env stap
#
# This script continuously lists the top 20 systemcalls in the interval 
# 5 seconds
#

global syscalls_count

probe syscall.* {
  syscalls_count[name]++
}

function print_systop () {
  printf ("%25s %10s\n", "SYSCALL", "COUNT")
  foreach (syscall in syscalls_count- limit 20) {
    printf("%25s %10d\n", syscall, syscalls_count[syscall])
  }
  delete syscalls_count
}

probe timer.s(5) {
  print_systop ()
  printf("--------------------------------------------------------------\n")
}
例4.29「topsys.stp」 は、5 秒あたりにシステムが使用している上位 20 位のシステムコールを一覧表示します。また、同期間に各システムコールが使用された回数も表示されます。例4.30「例4.29「topsys.stp」 のサンプル出力」 がサンプル出力になります。

例4.30 例4.29「topsys.stp」 のサンプル出力

--------------------------------------------------------------
                  SYSCALL      COUNT
             gettimeofday       1857
                     read       1821
                    ioctl       1568
                     poll       1033
                    close        638
                     open        503
                   select        455
                    write        391
                   writev        335
                    futex        303
                  recvmsg        251
                   socket        137
            clock_gettime        124
           rt_sigprocmask        121
                   sendto        120
                setitimer        106
                     stat         90
                     time         81
                sigreturn         72
                    fstat         66
--------------------------------------------------------------

4.3.6. プロセスごとのシステムコールボリュームの追跡

このセクションでは、最もボリュームの大きいシステムコールを実行しているプロセスを判定する方法を説明します。ここまでのセクションでは、システムが使用している上位のシステムコールを監視する方法を説明しました (「最もよく使われるシステムコールの追跡」)。また、どのアプリケーションが 1 番多く特定の「ポーリング容疑者」のシステムコールを使用しているかを特定する方法も説明しました (「ポーリングアプリケーションの監視」)。プロセスごとのシステムコールのボリュームを監視することで、ポーリングプロセスと他の古いリソースについてシステムを調査する際により多くのデータが提供できます。

例4.31 syscalls_by_proc.stp

#! /usr/bin/env stap

# Copyright (C) 2006 IBM Corp.
#
# This file is part of systemtap, and is free software.  You can
# redistribute it and/or modify it under the terms of the GNU General
# Public License (GPL); either version 2, or (at your option) any
# later version.

#
# Print the system call count by process name in descending order.
#

global syscalls

probe begin {
  print ("Collecting data... Type Ctrl-C to exit and display results\n")
}

probe syscall.* {
  syscalls[execname()]++
}

probe end {
  printf ("%-10s %-s\n", "#SysCalls", "Process Name")
  foreach (proc in syscalls-)
    printf("%-10d %-s\n", syscalls[proc], proc)
}
例4.31「syscalls_by_proc.stp」 は、システムコールを多く実行している上位 20 位のプロセスを一覧表示します。また、一定期間内に各プロセスが実行したシステムコールの数も表示されます。例4.32「例4.29「topsys.stp」 のサンプル出力」 はサンプル出力になります。

例4.32 例4.29「topsys.stp」 のサンプル出力

Collecting data... Type Ctrl-C to exit and display results
#SysCalls  Process Name
1577       multiload-apple
692        synergyc
408        pcscd
376        mixer_applet2
299        gnome-terminal
293        Xorg
206        scim-panel-gtk
95         gnome-power-man
90         artsd
85         dhcdbd
84         scim-bridge
78         gnome-screensav
66         scim-launcher
[...]
プロセス名の代わりにプロセス ID を表示するには、以下のスクリプトを使用します。

例4.33 syscalls_by_pid.stp

#! /usr/bin/env stap

# Copyright (C) 2006 IBM Corp.
#
# This file is part of systemtap, and is free software.  You can
# redistribute it and/or modify it under the terms of the GNU General
# Public License (GPL); either version 2, or (at your option) any
# later version.

#
# Print the system call count by process ID in descending order.
#

global syscalls

probe begin {
  print ("Collecting data... Type Ctrl-C to exit and display results\n")
}

probe syscall.* {
  syscalls[pid()]++
}

probe end {
  printf ("%-10s %-s\n", "#SysCalls", "PID")
  foreach (pid in syscalls-)
    printf("%-10d %-d\n", syscalls[pid], pid)
}
出力で表示されているように、結果を表示するにはスクリプトを手動で終了する必要があります。どちらのスクリプトにも timer.s() プローブを追加して、一定時間後に終了させることもできます。たとえば、5 秒後にスクリプトを終了させるには、以下のプローブをスクリプトに追加します。 
probe timer.s(5)
{
	exit()
}