HaskellからGnuplotを呼び出してチャートを描く

gnuplot用のパッケージをインストールして、
import Graphics.Gnuplot.Simple するだけ。とても簡単。

パッケージのインストール

$ cabal install gnuplot

チャートを描く

まずはGraphics.Gnuplot.Simpleをインポートする。

$ ghci
GHCi, version 7.0.4: http://www.haskell.org/ghc/  :? for help
Loading package ghc-prim ... linking ... done.
Loading package integer-gmp ... linking ... done.
Loading package base ... linking ... done.
Prelude> import Graphics.Gnuplot.Simple 
Prelude Graphics.Gnuplot.Simple>

チャートを描く関数はみんなplot〜という名前になっている。
これらを呼び出してチャートを描画していく。

Prelude Graphics.Gnuplot.Simple> plot
plotDots        plotFuncs       plotLists       plotParamFunc   plotPathStyle   plotType
plotFunc        plotList        plotListsStyle  plotParamFuncs  plotPaths
plotFunc3d      plotListStyle   plotMesh3d      plotPath        plotPathsStyle

例えば0~2πまでのsinの値をプロットする場合は以下のように実行する。
linerScaleは、第二引数のタプルで指定された範囲の値を第一引数の数だけリストにして返す関数。
plotPathの第一引数のリストで、プロット属性を指定する。

Prelude Graphics.Gnuplot.Simple> let xs = linearScale 1000 (0, 2*pi)
Prelude Graphics.Gnuplot.Simple> let ys = fmap sin xs
Prelude Graphics.Gnuplot.Simple> let points = zip xs ys
Prelude Graphics.Gnuplot.Simple> plotPath [(Title "hello")] points

これを実行すると以下のようにsinカーブが描画される。

ghcでの相互依存のあるモジュールのimport方法について

1. 相互依存のあるモジュールは、そのままではコンパイル出来ない。

以下のような相互依存のあるコードのコンパイルを試みる。

Foo.hs:

module Foo(Foo, getData, idProduct) where

import qualified Bar as B

data Foo = Foo {
      name :: String,
      id_  :: Int
} deriving (Show, Eq)

getData :: Foo -> (String, Int)
getData foo = (name foo, id_ foo)

idProduct :: Foo -> B.Bar -> Int
idProduct foo bar = (id_ foo) * (B.id_ bar)

Bar.hs:

module Bar (Bar, name, id_, getData) where

import qualified Foo as F

data Bar = Bar {
      name :: String
      ,id_  :: Int
      ,foo  :: F.Foo
} deriving (Show, Eq)

getData :: Bar -> (String, Int)
getData bar = (name bar, id_ bar)

すると、以下のように相互依存エラーが出てコンパイル出来ない。

$ ghc Foo.hs
Module imports form a cycle for modules:
  Foo (Foo.hs)
    imports: Bar
  Bar (./Bar.hs)
    imports: Foo

個別にコンパイルしようとしてもエラーとなる。

$ ghc -c Foo.hs

Foo.hs:3:1:
    Failed to load interface for `Bar':
      Use -v to see a list of the files searched for.
$ ghc -c Bar.hs

Bar.hs:3:1:
    Failed to load interface for `Foo':
      Use -v to see a list of the files searched for.

2. ghcは相互依存解決方法を提供してはいる。

ghcの提供する相互依存解決方法は、http://www.haskell.org/ghc/docs/latest/html/users_guide/separate-compilation.html#mutual-recursionにて説明されている。

これを要約すると、以下の２点になる。

• • 相互依存するモジュールをimportする際には、{-# SOURCE #-}プラグマを付ける。
  • importされるモジュールは、型情報等を提供する.hs-boot拡張子を持ったファイルを用意する。(C言語のヘッダファイルのようなもの)

以下にこれらを素直に適用してみたコードを示す。
これらのコードはコンパイルに失敗する。

Foo.hs-boot:

module Foo(Foo, getData, idProduct) where

import qualified Bar as B

data Foo = Foo {
      name :: String,
      id_  :: Int
} deriving (Show, Eq)

getData :: Foo -> (String, Int)
idProduct :: Foo -> B.Bar -> Int

Bar.hs:

module Bar (Bar, name, id_, getData) where

import {-# SOURCE #-} qualified Foo as F

data Bar = Bar {
      name :: String
      ,id_  :: Int
      ,foo  :: F.Foo
} deriving (Show, Eq)

getData :: Bar -> (String, Int)
getData bar = (name bar, id_ bar)

以下にコンパイル時のエラーを示す。

$ ghc -c Foo.hs-boot 

Foo.hs-boot:3:1:
    Failed to load interface for `Bar':
      Use -v to see a list of the files searched for.
$ ghc -c Bar.hs 

Bar.hs:3:1:
    Failed to load interface for `Foo':
      Use -v to see a list of the files searched for.

どこが悪いのかさっぱりわからない。

3. .hs-bootを修正してコンパイルが通るようにする。

上記のFoo.hs-bootのコンパイルが失敗するのは以下の理由による。

1. 1. Foo.hs-bootがBarに依存している。
   2. .hs-boot内ではデータ型の定義にderivingを使えない。

どうやら.hs-bootファイルには、.hsから依存している型情報を取り除いたものを記述しなければならないようである。
derivingが使えない点は、代わりにinstanceを使って解決する。

Foo.hs-boot:

module Foo(Foo, getData) where

data Foo = Foo {
      name :: String,
      id_  :: Int
} 

instance Show Foo
instance Eq Foo

getData :: Foo -> (String, Int)

.hs-bootファイルを修正後、以下の順番でコンパイルする。
エラーが出なくなり、コンパイルが成功した。

$ ghc -c Foo.hs-boot
$ ghc -c Bar.hs 
$ ghc -c Foo.hs

4. 強い依存関係がある場合

相互に強い依存関係がある場合には、Foo.hs-bootからBarモジュールの要素を取り除けないだろう。
このような場合には、依存関係を解消するように設計し直すか、FooとBar を一つのモジュールにするか、どちらかを選択しなければならない。

linuxのスレッド生成処理に関するメモ

linuxのスレッド生成処理に関するメモ。
sys_cloneから呼び出されるdo_forkあたりについて。

1. スレッドの生成

以下のプログラムを実行すると、スレッドを一つ生成する。

#include <stdlib.h>
#include <stdio.h>
#include <pthread.h>
#include <unistd.h>
#include <sys/types.h>
#include <sys/syscall.h>

#define THREADMAX 1

pid_t gettid(void)
{
    return syscall(SYS_gettid);
}

void *thread_function(void* arg)
{
	int *n = (int*)arg;
	pid_t pid = gettid();
	
	printf("[%d] %d\n", pid, *n);
	return arg;
}

int main(int argc, char **argv)
{
	int i;
	pthread_t thread[THREADMAX];
	int data[THREADMAX];
	pid_t pid = gettid();
	printf("[%d] %p\n", pid, &argc);

	for(i = 0; i < THREADMAX; ++i) {
		data[i] = i;
		pthread_create(&thread[i], NULL, thread_function, &data[i]);
	}

	for(i = 0; i < THREADMAX; ++i) {
		pthread_join(thread[i], NULL);
	}
	return 0;
}

straceで上記プログラムから呼び出すシステムコールを監視すると、pthread_create()が実際にはclone()を呼び出している事がわかる。

$strace ./a.out
...
clone(child_stack=0x7f0c9cf99fb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0x7f0c9cf9a9d0, tls=0x7f0c9cf9a700, child_tidptr=0x7f0c9cf9a9d0) = 9067
...

clone()はsys_clone()を呼び出して子プロセスを作成する。
この後、詳解Linuxカーネル(P125)によると、子プロセスのスタックを書き換えて、引数を積み、
子プロセスの戻り値アドレスをpthread_createで指定した関数ポインタに変更する。

2. do_fork呼び出し

sys_clone()は以下のように実装されており(linux 3.5.0)、さらにdo_fork()を呼び出す。

long sys_clone(unsigned long clone_flags, unsigned long newsp,
	       void __user *parent_tid, void __user *child_tid)
{
	long ret;

	if (!newsp)
		newsp = UPT_SP(&current->thread.regs.regs);
	current->thread.forking = 1;
	ret = do_fork(clone_flags, newsp, &current->thread.regs, 0, parent_tid,
		      child_tid);
	current->thread.forking = 0;
	return ret;
}

以下のsys_clone.stpを用いて、上記スレッド作成プログラムでdo_fork呼び出し時の引数を確認する。

probe kernel.function("do_fork@kernel/fork.c")
{ 	
	printf("do_fork   %s\n", $$vars);
}

probe kernel.function("sys_clone*")
{
	printf("sys_clone %s\n", $$vars);
}

probe kernel.function("do_fork@kernel/fork.c").return
{ 	
	printf("<- do_fork    %d %d\n", kernel_int($parent_tidptr), kernel_int($child_tidptr));
}

probe kernel.function("sys_clone*").return
{
	printf("<- sys_clone  %d %d\n", kernel_int($parent_tid), kernel_int($child_tid));
}

$ sudo stap sys_clone.stp -c ./a.out 
[9602] 0x7fff675580ec
[9605] 0
sys_clone clone_flags=0x3d0f00 newsp=0x7ff643872fb0 parent_tid=0x7ff6438739d0 child_tid=0x7ff6438739d0 regs=0xffff88008141df58
do_fork   clone_flags=0x3d0f00 stack_start=0x7ff643872fb0 regs=0xffff88008141df58 stack_size=0x0 parent_tidptr=0x7ff6438739d0 child_tidptr=0x7ff6438739d0 p=0x3d28620000 trace=? nr=?
<- do_fork    9605 9605
<- sys_clone  9605 9605

3. do_forkの処理

do_forkの処理は以下のような処理を行う。

3.1 do_forkのインタフェースと、変数の宣言

long do_fork(unsigned long clone_flags, /* clone呼び出し時フラグ */
	      unsigned long stack_start, /* 子プロセスに割り当てるスタックの開始位置 */
	      struct pt_regs *regs,
	      unsigned long stack_size,
	      int __user *parent_tidptr,
	      int __user *child_tidptr)
{
	struct task_struct *p;
	int trace = 0;
	long nr;

3.2 do_forkのフラグ有効性確認

	/*
	 * Do some preliminary argument and permissions checking before we
	 * actually start allocating stuff
	 */
	if (clone_flags & CLONE_NEWUSER) {
		if (clone_flags & CLONE_THREAD)
			return -EINVAL;
		/* hopefully this check will go away when userns support is
		 * complete
		 */
		if (!capable(CAP_SYS_ADMIN) || !capable(CAP_SETUID) ||
				!capable(CAP_SETGID))
			return -EPERM;
	}

3.3 トレース状態の確認

ユーザーモードでかつ、非トレースでなければ、trace変数にトレースの状態を設定する。
このtrace変数は、後で呼ばれるcopy_process()で使う。

	/*
	 * Determine whether and which event to report to ptracer.  When
	 * called from kernel_thread or CLONE_UNTRACED is explicitly
	 * requested, no event is reported; otherwise, report if the event
	 * for the type of forking is enabled.
	 */

	if (likely(user_mode(regs)) && !(clone_flags & CLONE_UNTRACED)) {
		if (clone_flags & CLONE_VFORK)
			trace = PTRACE_EVENT_VFORK;
		else if ((clone_flags & CSIGNAL) != SIGCHLD)
			trace = PTRACE_EVENT_CLONE;
		else
			trace = PTRACE_EVENT_FORK;

		if (likely(!ptrace_event_enabled(current, trace)))
			trace = 0;
	}

3.4 プロセスディスクリプタをコピーする

プロセスディスクリプタのコピーを作成する。
戻り値は新しくコピーされたtask_structオブジェクトへのポインタ。

	p = copy_process(clone_flags, stack_start, regs, stack_size,
			 child_tidptr, NULL, trace);

3.5 新しいタスクを起床する

新しいPIDをユーザー空間にコピーして、新しいプロセスを起床する。

	/*
	 * Do this prior waking up the new thread - the thread pointer
	 * might get invalid after that point, if the thread exits quickly.
	 */
	if (!IS_ERR(p)) {
		struct completion vfork;

		trace_sched_process_fork(current, p);

		nr = task_pid_vnr(p);

		if (clone_flags & CLONE_PARENT_SETTID)
			put_user(nr, parent_tidptr);

		if (clone_flags & CLONE_VFORK) {
			p->vfork_done = &vfork;
			init_completion(&vfork);
			get_task_struct(p);
		}

		wake_up_new_task(p);

		/* forking complete and child started to run, tell ptracer */
		if (unlikely(trace))
			ptrace_event(trace, nr);

		if (clone_flags & CLONE_VFORK) {
			if (!wait_for_vfork_done(p, &vfork))
				ptrace_event(PTRACE_EVENT_VFORK_DONE, nr);
		}
	} else {
		nr = PTR_ERR(p);
	}
	return nr;
}

SystemTap Beginners Guide 5.3と5.4のメモ

5.3 プロファイリング

以下のセクションでは、関数呼び出しの監視によりカーネルの活動状況を分析する方法を説明する。

5.3.1 関数呼び出しを数える

このセクションでは、カーネルが30秒間に何回カーネルの関数を呼び出すのか特定する方法について説明する。

functioncallcount.stp

#!/usr/bin/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()
}

functioncallcount.stpは対象のカーネル関数を引数に取る。
ワイルドカードでも使えるので、別の環境でも確実に使えるはずである。

以下に、'stap functioncallcount.stp "*@mm/*.c"'を実行した結果を示す。

__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

5.3.2 コールグラフのトレース

このセクションでは、関数呼び出しにおける関数に入る箇所と出る箇所をトレースする。

#!/usr/bin/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) }

para-callgraph.stp は２つのコマンドライン引数をとる。

• トレースしたい関数 ($1)
• ２つ目はオプションのトリガー関数($2)。トリガー関数が指定されている場合、この関数に入った後から、この関数から出るまでの間でトレースを実行する。

以下に、"stap para-callgraph.stp 'kernel.function("*@fs/*.c")' 'kernel.function("sys_read")'"の実行例を示す。

...
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

5.3.3 カーネル空間とユーザ空間での消費時間の決定

このセクションでは、スレッドに与えられた時間がどのくらいカーネルで消費されたか、
またはユーザー空間で消費されたか決定する方法について説明する。

#!/usr/bin/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
    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
}

thread-times.stpは5秒間にCPUを最も消費した上位20プロセスを列挙する。
また、CPUの消費時間をユーザー空間とカーネル空間に分けて、パーセント表示する。
このスクリプトの実行にかかる時間も計測結果に含まれてしまっている。

以下に実行例を示す。

            comm   tid   %user %kernel (of 9999 ticks)
       swapper/1     0   0.00%  45.17%
       swapper/0     0   0.00%  44.32%
           gedit  1709   1.87%   0.10%
     gnome-shell  1133   1.18%   0.26%
            Xorg   823   0.75%   0.68%
           gdbus  1566   1.10%   0.22%
     mozc_server  1744   1.23%   0.04%
     ibus-daemon  1475   0.59%   0.05%
 ibus-engine-moz  1738   0.25%   0.25%
           gdbus  1713   0.34%   0.06%
   mozc_renderer  1748   0.27%   0.01%
           gdbus  1740   0.22%   0.04%
    ibus-ui-gtk3  1568   0.23%   0.01%
     kworker/0:2  2344   0.00%   0.12%
     kworker/1:1  2182   0.00%   0.10%
           gdbus  1574   0.06%   0.02%
     kworker/u:0     5   0.00%   0.07%
  gnome-terminal  1780   0.04%   0.02%
           gdbus  1579   0.06%   0.00%
 ibus-engine-sim  1578   0.05%   0.00%

5.3.4 ポーリング中のアプリケーションの監視

このセクションでは、ポーリング中のアプリケーションの監視と特定について説明する。
不要であったり高価であったりするポーリングを追跡できるので、性能改善に役立つだろう。

#!/usr/bin/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])
  }
}

timeout.stpでは、以下のシステムコールが、実イベントの発生ではなく時間経過によって完了した回数を追跡する。

• poll
• select
• epoll
• itimer
• futex
• nanosleep
• signal

サンプル時間を増やしたい場合には、timer.s(1)の引数を増やせばよい。
timeout.stpの出力結果には、ポーリングシステムコールを実行して時間超過した数の順番に、上位の20個ポーリング中のアプリケーションのUIDと名前が表示される。
以下に実行例を示す。

pid |   poll  select   epoll  itimer   futex nanosle  signal| process
 3397 |      3       0       0       0     156       0       0| firefox
 1748 |      0       0       0       0       0     143       0| mozc_renderer
 1780 |    120       0       0       0       0       3       0| gnome-terminal
  822 |      0      64       0       0       0       0       0| wpa_supplicant
  823 |      0      55       0       0       0       0       0| Xorg
 1133 |     46       0       0       0       0       0       0| gnome-shell
  697 |     10       0       0       0       0       0       0| NetworkManager
  805 |      0       6       0       0       0       0       0| sendmail
 1092 |      4       0       0       0       0       0       0| gnome-settings-
  909 |      3       0       0       0       0       0       0| rtkit-daemon
  670 |      0       0       0       0       0       3       0| abrt-watch-log
  862 |      1       0       0       0       0       0       0| upowerd
    0 |      0       0       0       1       0       0       0| swapper/0
 1475 |      1       0       0       0       0       0       0| gdbus
 1144 |      0       1       0       0       0       0       0| syndaemon
  741 |      0       1       0       0       0       0       0| crond
 1111 |      0       0       1       0       0       0       0| cupsd

5.3.5 最高頻度で使われるシステムコールの追跡

timeout.stpは、一部のシステムコール(poll等)を実行してポーリングしているアプリケーションを特定した。
しかし、その一部のシステムコール以外のシステムコールがカーネル内で時間を消費しているケースもあり得る。
もし、あるアプリケーションが無駄にシステムコールを使っていると考えているのであれば、
最高頻度で使われるシステムコールを特定する必要がある。そして、それにはtopsys.stpを使うことが出来る。

#!/usr/bin/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")
}

topsys.stpは5秒間隔にシステムコールが使われた回数を数えて、上位20のシステムコールを列挙する。
以下に実行例を示す。

                  SYSCALL      COUNT
                    ioctl        904
                    write        593
                     poll        574
                  sendmsg        478
                     read        450
                  recvmsg        398
                 recvfrom        260
                   select        152
                setitimer        128
                   writev        102
                    lseek         90
           rt_sigprocmask         82
                    close         53
                   munmap         51
                    mmap2         50
                    fstat         50
                     open         49
                    ppoll         25
                nanosleep         22
               epoll_wait          7

5.3.6 プロセス毎のシステコールの総量の追跡

このセクションでは、システムコールを元も実行しているプロセスを特定する方法を説明する。
前節では、ある時間で最も呼ばれるシステムコールを関しする方法について説明した。
また、どのアプリケーションがポーリング関連のシステムコールを最も呼び出しているのか特定する方法も説明した。
それぞれのプロセスがシステムコールを呼ぶ量を監視することで、ポーリング中のプロセスやリソース喰いを調査するのに役立つ情報を、さらに提供することが出来る。

syscalls_by_proc.stp

#!/usr/bin/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)
}

syscalls_by_proc.stpは、システムコールを呼び出した回数が多いプロセスの上位20を表示する。
また、システムコールを呼び出した回数も同時に表示する。
以下に実行例を示す。

SysCalls  Process Name
30120      Xorg
5405       gnome-shell
3957       evince
1742       gnome-terminal
1412       gdbus
1188       NetworkManager
985        gnome-settings-
493        dbus-daemon
433        stapio
278        wpa_supplicant
183        upowerd
168        mozc_renderer
151        nm-applet
148        mission-control
123        ibus-ui-gtk3
116        ibus-daemon
109        systemd-journal
64         firefox
60         pool
56         sendmail
46         gnome-session
37         syndaemon
36         mozc_server
35         tracker-miner-f
31         systemd
24         rtkit-daemon
24         crond
20         modem-manager
20         gdm-binary
18         ibus-engine-sim
18         avahi-daemon
15         abrt-watch-log
7          cupsd
7          sudo
5          gnome-screensav
5          stap
4          fprintd
4          polkitd
4          gnome-shell-cal
4          evolution-alarm
4          gedit
3          rsyslogd
3          rs:main Q:Reg
2          audispd
1          kthreadd
1          gconfd-2

プロセス名の代わりにプロセスIDを表示する場合には以下のスクリプトを使用する。

#!/usr/bin/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()を追加してexit関数を実行せよ。

5.4 競合したユーザー空間のロックを特定する

このセクションでは、ある期間にシステム全体に渡って、競合したユーザー空間のロックを特定する方法について説明する。
これはfutexの競合を原因とする貧弱な性能のプログラムを改善するのに役立つだろう。

単純に言って、futexの競合は複数のプロセスが同じ時期に同じロックにアクセスしようとするために発生する。
このためロック機構による並列実行は貧弱な性能の原因となる。
ロック機構の並列実行とは、あるプロセスがロックを得ると、他のプロセスはロックを使えるようになるまで待つといったものである。

futexes.stpスクリプトはfutexシステムコールをプローブして、ロックの競合を表示する。

#!/usr/bin/stap

# This script tries to identify contended user-space locks by hooking
# into the futex system call.

global FUTEX_WAIT = 0 /*, FUTEX_WAKE = 1 */
global FUTEX_PRIVATE_FLAG = 128 /* linux 2.6.22+ */
global FUTEX_CLOCK_REALTIME = 256 /* linux 2.6.29+ */

global lock_waits # long-lived stats on (tid,lock) blockage elapsed time
global process_names # long-lived pid-to-execname mapping

probe syscall.futex.return {  
  if (($op & ~(FUTEX_PRIVATE_FLAG|FUTEX_CLOCK_REALTIME)) != FUTEX_WAIT) next
  process_names[pid()] = execname()
  elapsed = gettimeofday_us() - @entry(gettimeofday_us())
  lock_waits[pid(), $uaddr] <<< elapsed
}

probe end {
  foreach ([pid+, lock] in lock_waits) 
    printf ("%s[%d] lock %p contended %d times, %d avg us\n",
            process_names[pid], pid, lock, @count(lock_waits[pid,lock]),
            @avg(lock_waits[pid,lock]))
}

futexes.stp は手動で停止させる必要がある。exitすると、以下の情報を出力する。

• ある競合に関して責任を持つプロセスIDと名前
• 対象となるロック変数の位置
• ロック変数が競合された回数
• プローブ中の競合に関する時間の平均

以下に実行例を示す。

rs:main Q:Reg[694] lock 0x7f6489d2ff04 contended 1 times, 25790639 avg us
pool[1120] lock 0x14f59f0 contended 1 times, 595 avg us
gnome-shell[1133] lock 0x1d86b50 contended 1 times, 252 avg us
gnome-shell[1133] lock 0x1d97bb0 contended 1 times, 9 avg us
gnome-shell[1133] lock 0x2c2af1c contended 1 times, 29665866 avg us
ibus-daemon[1475] lock 0x25ef7d0 contended 3 times, 23 avg us
gdbus[1780] lock 0x7f22e400a1d0 contended 2 times, 13 avg us
gdbus[1780] lock 0x19762f0 contended 2 times, 11 avg us
gdbus[1780] lock 0x7f22e4009560 contended 2 times, 22 avg us

SystemTap Begginers Guide 5.2 のメモ

5.2 ディスク

以下のセスクションではディスクとIOの状況について監視するスクリプトを説明する。

5.2.1 ディスク読み書きトラフィックの集計

disktop.stpは実行中のプロセスで最も重いディスク読み書きをしているプロセスを特定する。

#!/usr/bin/stap 
#
# Copyright (C) 2007 Oracle Corp.
#
# Get the status of reading/writing disk every 5 seconds,
# output top ten entries 
#
# This is free software,GNU General Public License (GPL);
# either version 2, or (at your option) any later version.
#
# Usage:
#  ./disktop.stp
#

global io_stat,device
global read_bytes,write_bytes

probe vfs.read.return {
  if ($return>0) {
    if (devname!="N/A") {/*skip read from cache*/
      io_stat[pid(),execname(),uid(),ppid(),"R"] += $return
      device[pid(),execname(),uid(),ppid(),"R"] = devname
      read_bytes += $return
    }
  }
}

probe vfs.write.return {
  if ($return>0) {
    if (devname!="N/A") { /*skip update cache*/
      io_stat[pid(),execname(),uid(),ppid(),"W"] += $return
      device[pid(),execname(),uid(),ppid(),"W"] = devname
      write_bytes += $return
    }
  }
}

probe timer.ms(5000) {
  /* skip non-read/write disk */
  if (read_bytes+write_bytes) {

    printf("\n%-25s, %-8s%4dKb/sec, %-7s%6dKb, %-7s%6dKb\n\n",
           ctime(gettimeofday_s()),
           "Average:", ((read_bytes+write_bytes)/1024)/5,
           "Read:",read_bytes/1024,
           "Write:",write_bytes/1024)

    /* print header */
    printf("%8s %8s %8s %25s %8s %4s %12s\n",
           "UID","PID","PPID","CMD","DEVICE","T","BYTES")
  }
  /* print top ten I/O */
  foreach ([process,cmd,userid,parent,action] in io_stat- limit 10)
    printf("%8d %8d %8d %25s %8s %4s %12d\n",
           userid,process,parent,cmd,
           device[process,cmd,userid,parent,action],
           action,io_stat[process,cmd,userid,parent,action])

  /* clear data */
  delete io_stat
  delete device
  read_bytes = 0
  write_bytes = 0  
}

probe end{
  delete io_stat
  delete device
  delete read_bytes
  delete write_bytes
  printf("END!\n");
}

disktop.stpは最もディスク読み書きが重い順に、
以下のデータを出力する。

• UID ユーザID ID0はroot
• PID プロセスID
• PPID 親プロセスのプロセスID
• CMD プロセス名
• DEVICE プロセスが読み書きを行なっているデバイス
• T Wであれば書き込みを、Rであれば読み込みを行なっている
• BYTES 読み書きしたサイズ

ctime関数は、gettimeofday_s関数で得たUNIXエポックでの秒数をカレンダー時刻に変換する。
このスクリプト中の$returnはプロセスが仮想ファイルシステムから読み書きしたバイト数が格納されている。

以下は実行例。

sudo stap ./disktop.stp 

Sun Jul 29 05:03:33 2012 , Average:   0Kb/sec, Read:       0Kb, Write:      0Kb

     UID      PID     PPID                       CMD   DEVICE    T        BYTES
    1000     1108      989               thunderbird     dm-1    R          166

Sun Jul 29 05:03:38 2012 , Average:   0Kb/sec, Read:       0Kb, Write:      0Kb

     UID      PID     PPID                       CMD   DEVICE    T        BYTES
    1000     1326      989            gnome-terminal     dm-1    W          560

5.2.2 各ファイル読み書きにおけるIOの時間

このセクションでは、プロセスがファイルに対して読み書きに要する時間を計測する方法を説明する。

iotime.stp

#!/usr/bin/stap

/*
 * Copyright (C) 2006-2007 Red Hat Inc.
 * 
 * This copyrighted material is made available to anyone wishing to use,
 * modify, copy, or redistribute it subject to the terms and conditions
 * of the GNU General Public License v.2.
 *
 * You should have received a copy of the GNU General Public License
 * along with this program.  If not, see <http://www.gnu.org/licenses/>.
 *
 * Print out the amount of time spent in the read and write systemcall
 * when each file opened by the process is closed. Note that the systemtap 
 * script needs to be running before the open operations occur for
 * the script to record data.
 *
 * This script could be used to to find out which files are slow to load
 * on a machine. e.g.
 *
 * stap iotime.stp -c 'firefox'
 *
 * Output format is:
 * timestamp pid (executabable) info_type path ...
 *
 * 200283135 2573 (cupsd) access /etc/printcap read: 0 write: 7063
 * 200283143 2573 (cupsd) iotime /etc/printcap time: 69
 *
 */

global start
global time_io

function timestamp:long() { return gettimeofday_us() - start }

function proc:string() { return sprintf("%d (%s)", pid(), execname()) }

probe begin { start = gettimeofday_us() }

global filehandles, fileread, filewrite

probe syscall.open.return {
  filename = user_string($filename)
  if ($return != -1) {
    filehandles[pid(), $return] = filename
  } else {
    printf("%d %s access %s fail\n", timestamp(), proc(), filename)
  }
}

probe syscall.read.return {
  p = pid()
  fd = $fd
  bytes = $return
  time = gettimeofday_us() - @entry(gettimeofday_us())
  if (bytes > 0)
    fileread[p, fd] += bytes
  time_io[p, fd] <<< time
}

probe syscall.write.return {
  p = pid()
  fd = $fd
  bytes = $return
  time = gettimeofday_us() - @entry(gettimeofday_us())
  if (bytes > 0)
    filewrite[p, fd] += bytes
  time_io[p, fd] <<< time
}

probe syscall.close {
  if ([pid(), $fd] in filehandles) {
    printf("%d %s access %s read: %d write: %d\n",
           timestamp(), proc(), filehandles[pid(), $fd],
           fileread[pid(), $fd], filewrite[pid(), $fd])
    if (@count(time_io[pid(), $fd]))
      printf("%d %s iotime %s time: %d\n",  timestamp(), proc(),
             filehandles[pid(), $fd], @sum(time_io[pid(), $fd]))
   }
  delete fileread[pid(), $fd]
  delete filewrite[pid(), $fd]
  delete filehandles[pid(), $fd]
  delete time_io[pid(),$fd]
}

iotime.stpは、あるファイルへのシステムコールopen, close, read, writeのそれぞれの時間を追跡する。
それぞれのファイルに関して、システムコールへのアクセスがあると、iotime.stpは読み書きが完了するまでの時間をマイクロ秒単位で数えて、
データ量をバイト単位で追跡する。

iotime.stpは、$countに読み書きしたデータ量をバイト単位で保存する。$returnには、読み書きしたデータ量が保存されている。
$countはデータの読み書きが起こった際にのみ使われる。

sudo stap ./iotime.stp 

1043730 900 (sendmail) access /proc/loadavg read: 26 write: 0
1043736 900 (sendmail) iotime /proc/loadavg time: 7
6048731 900 (sendmail) access /proc/loadavg read: 26 write: 0
6048737 900 (sendmail) iotime /proc/loadavg time: 7
11053729 900 (sendmail) access /proc/loadavg read: 26 write: 0
11053735 900 (sendmail) iotime /proc/loadavg time: 6
16058728 900 (sendmail) access /proc/loadavg read: 26 write: 0
16058734 900 (sendmail) iotime /proc/loadavg time: 7
18589249 679 (crond) access /etc/passwd read: 1800 write: 0
18589255 679 (crond) iotime /etc/passwd time: 12
18589299 679 (crond) access /etc/passwd read: 1800 write: 0
18589302 679 (crond) iotime /etc/passwd time: 5
18589328 679 (crond) access /etc/passwd read: 1800 write: 0
18589331 679 (crond) iotime /etc/passwd time: 5
21063733 900 (sendmail) access /proc/loadavg read: 26 write: 0
21063739 900 (sendmail) iotime /proc/loadavg time: 7

iotime.stpは、以下の情報を出力する。

• タイムスタンプ マイクロ秒単位
• プロセスIDとプロセス名
• access と iotime フラグ
• アクセスしたファイル

プロセスがファイルに読み書きを行えるようになると、accessかiotimeの行が出力される。
accessは、ファイルにアクセスを始めた事を示し、行末の数値は読み書きを試みたデータサイズをバイト単位で示す。
iotimeは、プロセスが読み書きを実行する過程の時間をマイクロ秒単位で示す。

accessの後にiotimeが現れない場合、それは単純にデータを読み書きしていない事を示す。

5.2.3 累積するIOの追跡

このセクションでは、累積したIOの量を追跡する方法について示す。

traceio.stp

#!/usr/bin/stap
# traceio.stp
# Copyright (C) 2007 Red Hat, Inc., Eugene Teo <eteo@redhat.com>
# Copyright (C) 2009 Kai Meyer <kai@unixlords.com>
#   Fixed a bug that allows this to run longer
#   And added the humanreadable function
#
# This program is free software; you can redistribute it and/or modify
# it under the terms of the GNU General Public License version 2 as
# published by the Free Software Foundation.
#

global reads, writes, total_io

probe vfs.read.return {
  reads[pid(),execname()] += $return
  total_io[pid(),execname()] += $return
}

probe vfs.write.return {
  writes[pid(),execname()] += $return
  total_io[pid(),execname()] += $return
}

function humanreadable(bytes) {
  if (bytes > 1024*1024*1024) {
    return sprintf("%d GiB", bytes/1024/1024/1024)
  } else if (bytes > 1024*1024) {
    return sprintf("%d MiB", bytes/1024/1024)
  } else if (bytes > 1024) {
    return sprintf("%d KiB", bytes/1024)
  } else {
    return sprintf("%d   B", bytes)
  }
}

probe timer.s(1) {
  foreach([p,e] in total_io- limit 10)
    printf("%8d %15s r: %12s w: %12s\n",
           p, e, humanreadable(reads[p,e]),
           humanreadable(writes[p,e]))
  printf("\n")
  # Note we don't zero out reads, writes and total_io,
  # so the values are cumulative since the script started.
}

traceio.stpは、IOトラフィックを生成する実行ファイルのトップ10を表示する。
加えて、それら実行ファイルがIO読み書きを実施した量の合計を追跡する。
この情報は1秒毎に出力される。

traceio.stpのローカル変数$returnは、disktop.stpと同様に、読み書きしたバイト数を示す。

以下に実行例を示す。

sudo stap ./traceio.stp

    793            Xorg r:        1 MiB w:        0   B
    1246         firefox r:      223 KiB w:      326 KiB
    1494       alsa-sink r:        1 KiB w:        1 KiB
    1494      pulseaudio r:        1 KiB w:        1 KiB
    1326  gnome-terminal r:      940   B w:        1 KiB
    8069          stapio r:      972   B w:      971   B
    4166     threaded-ml r:      115   B w:       60   B
    8007           gdbus r:       -6   B w:      176   B
    1326           gdbus r:       10   B w:      128   B
    8007     ibus-daemon r:       48   B w:       16   B

    1246         firefox r:        6 MiB w:        1 MiB
     793            Xorg r:        1 MiB w:        0   B
    4166 plugin-containe r:        2 KiB w:      999   B
    1326  gnome-terminal r:        1 KiB w:        1 KiB
    8069          stapio r:        1 KiB w:        1 KiB
    1494       alsa-sink r:        1 KiB w:        1 KiB
    1494      pulseaudio r:        1 KiB w:        1 KiB
    4166     threaded-ml r:      147   B w:       67   B
    8007           gdbus r:       -6   B w:      176   B
    1326           gdbus r:       10   B w:      128   B

5.2.4 IO監視(デバイス毎に)

このセクションでは、特定のデバイスに対するIOの状況を監視する方法を説明する。

traceio2.stp

#!/usr/bin/stap

global device_of_interest

probe begin {
  /* The following is not the most efficient way to do this.
      One could directly put the result of usrdev2kerndev()
      into device_of_interest.  However, want to test out
      the other device functions */
  dev = usrdev2kerndev($1)
  device_of_interest = MKDEV(MAJOR(dev), MINOR(dev))
}

probe vfs.write, vfs.read
{
  if (dev == device_of_interest)
    printf ("%s(%d) %s 0x%x\n",
            execname(), pid(), probefunc(), dev)
}

traceio2.stpは、デバイス番号をコマンドライン引数として取る。この値は、'stat -c "0x%D" ディレクトリ名'で得られる。
usrdev2kerndev関数は、デバイス番号をカーネルが理解出来る形式に変換するものである。
usrdef2kerndev関数はMKDEV(),MINOR(),MAJOR()と合わせて、各デバイスのメジャー番号とマイナー番号を決定するために使う。

traceio2.stpの出力は、各プロセスの名前とプロセスID、実行した関数名、カーネルのデバイス番号から成る。

以下は、'stap traceio2.stp 0x805'を実行した例である。
0x805は、/homeのデバイス番号である。/homeは/dev/sda5に含まれおり、そのデバイスが我々が監視したい対象である。

synergyc(3722) vfs_read 0x800005
synergyc(3722) vfs_read 0x800005
cupsd(2889) vfs_write 0x800005
cupsd(2889) vfs_write 0x800005
cupsd(2889) vfs_write 0x800005

5.2.5 ファイルへの読み書きを監視する

このセクションではファイルに対する読み書きをリアルタイムに監視する方法を説明する。

inodewatch.stp

#!/usr/bin/stap

global device_of_interest

probe begin {
  /* The following is not the most efficient way to do this.
      One could directly put the result of usrdev2kerndev()
      into device_of_interest.  However, want to test out
      the other device functions */
  dev = usrdev2kerndev($1)
  device_of_interest = MKDEV(MAJOR(dev), MINOR(dev))
}

probe vfs.write, vfs.read
{
  if (dev == device_of_interest)
    printf ("%s(%d) %s 0x%x\n",
            execname(), pid(), probefunc(), dev)
}
[ito@earth stap]$ cat inodewatch.stp 
#!/usr/bin/stap

probe vfs.write, vfs.read
{
  # dev and ino are defined by vfs.write and vfs.read
  if (dev == MKDEV($1,$2) # major/minor device
      && ino == $3)
    printf ("%s(%d) %s 0x%x/%u\n",
      execname(), pid(), probefunc(), dev, ino)
}

inodewatch.stpは、以下の３つのコマンドライン引数に取る。

• ファイルのメジャーデバイス番号
• ファイルのマイナーデバイス番号
• ファイルのiノード番号

これらの情報は'stat -c "%D %i" ファイル名'で得ることが出来る。
例えば、/etc/crontabを監視したい場合、'stat -c "%D %i" /etc/crontab'を実行する。
このコマンドの実行例は以下の通りである。

805 1078319

805は16進数のデバイス番号である。下位2桁の数字がマイナーデバイス番号で、上位の数字がメジャーデバイス番号である。
1078319はiノード番号である。/etc/crontabの監視を開始するためには、'stap inodewatch.stp 0x8 0x05 1078319
'と実行する。接頭辞0xは16進数を示す。

このコマンドの実行結果は、読み書きを実行しているプロセスの名前とID、実行中の関数(例えばvfs_read, vfs_write)、
デバイス番号(16進数)、iノード番号から成る。
以下の実行例は、cat /etc/crontabを実行中に'stap inodewatch.stp 0x8 0x05 1078319'を実行した結果である。

cat(16437) vfs_read 0x800005/1078319
cat(16437) vfs_read 0x800005/1078319
||< 

** 5.2.6 ファイル属性変更の監視

このセクションでは対象ファイルの属性変更をリアルタイムに監視する。

>||
#!/usr/bin/stap

global ATTR_MODE = 1

probe kernel.function("setattr_copy")!,
      kernel.function("generic_setattr")!,
      kernel.function("inode_setattr") {
  dev_nr = $inode->i_sb->s_dev
  inode_nr = $inode->i_ino

  if (dev_nr == MKDEV($1,$2) # major/minor device
      && inode_nr == $3
      && $attr->ia_valid & ATTR_MODE)
    printf ("%s(%d) %s 0x%x/%u %o %d\n",
      execname(), pid(), probefunc(), dev_nr, inode_nr, $attr->ia_mode, uid())
}

inodewatch2.stpは、コマンドライン引数に対象となるファイルのデバイス番号とiノード番号を取る。
この情報について詳しく知りたい場合は、5.2.5を参照せよ。

inodewatch2.stpの出力はinodewatch.stpと似ており、違いは監視対象のファイルの変更された属性と、
変更したユーザーのIDである。

/home/joe/bigfileに対してユーザーjoeが'chmod 777 /home/joe/bigfile'と'chmod 666 /home/joe/bigfile'を実行した場合の例を示す。

chmod(17448) inode_setattr 0x800005/6011835 100777 500
chmod(17449) inode_setattr 0x800005/6011835 100666 500

5.2.7 IOブロックの時間の周期表示

このセクションでは、IO要求が完了するまでの待ち時間の合計を追跡する方法を示す。
これは過剰な未完了ブロックIO操作を特定するのに役に立つ。

#!/usr/bin/stap

global req_time, etimes

probe ioblock.request
{
  req_time[$bio] = gettimeofday_us()
}

probe ioblock.end
{
  t = gettimeofday_us()
  s =  req_time[$bio]
  delete req_time[$bio]
  if (s) {
    etimes[devname, bio_rw_str(rw)] <<< t - s
  }
}

/* for time being delete things that get merged with others */
probe kernel.trace("block_bio_frontmerge"),
      kernel.trace("block_bio_backmerge")
{
  delete req_time[$bio]
}

probe timer.s(10), end {
  ansi_clear_screen()
  printf("%10s %3s %10s %10s %10s\n",
         "device", "rw", "total (us)", "count", "avg (us)")
  foreach ([dev,rw] in etimes - limit 20) {
    printf("%10s %3s %10d %10d %10d\n", dev, rw,
           @sum(etimes[dev,rw]), @count(etimes[dev,rw]), @avg(etimes[dev,rw]))
  }
  delete etimes
}

ioblktime.stpは、各デバイスのブロックIOを待つ時間の平均を計算し、10秒毎に出力する。
この頻度は、timer.s(10)の数値を書き換えることで変更出来る。

未完了ブロックIOが多すぎる場合には、MAXMAPENTRIESの数分だけ出力される。
MAXMAPENTRIESの値を変更して実行したい場合には、-DMAXMAPENTRIES=10000をstapのオプションに指定して実行せよ。

以下は実行例である。

   device  rw total (us)      count   avg (us)
      dm-1   W      80425         11       7311
      dm-2   W      76476         10       7647
       sda   W      51706         10       5170
      sda2   W      92400          2      46200

この例は、デバイス名、実行している操作(rw)、全ての操作での待ち時間の合計(total(us))、操作の数(count)、全ての操作での待ち時間の平均時間(avg(us))を示す。
スクリプトによる時間の計算にはマイクロ秒単位の時間がかかる。

SystemTap Beginners Guide 5.1 のメモ

Useful SystemTap Scripts

この章では、SystemTap スクリプトを紹介する。
これらはsystemtap-testsuite RPMをインストールすると、/usr/share/systemtap/testsuite/にインストールされる。

5.1 Network

以下にネットワークに関するスクリプトを紹介する。

5.1.1 ネットワークプロファイリング

このセクションでは、どのようにしてネットワークの活動状況をプロファイルするのかについて詳述する。
nettop.stpは計算機上のプロセスがどの程度のネットワークトラフィックを生成しているのかについて、
各瞬間での状況を周期的に出力する。

nettop.stp

#! /usr/bin/env stap

global ifxmit, ifrecv
global ifmerged

probe netdev.transmit
{
	ifxmit[pid(), dev_name, execname(), uid()] <<< length
}

probe netdev.receive
{
	ifrecv[pid(), dev_name, execname(), uid()] <<< length
}

function print_activity()
{
	printf("%5s %5s %-7s %7s %7s %7s %7s %-15s\n",
		"PID", "UID", "DEV", "XMIT_PK", "RECV_PK",
		"XMIT_KB", "RECV_KB", "COMMAND")
	foreach ([pid, dev, exec, uid] in ifrecv) {
		ifmerged[pid, dev, exec, uid] += @count(ifrecv[pid,dev,exec,uid]);
	}
	foreach ([pid, dev, exec, uid] in ifxmit) {
		ifmerged[pid, dev, exec, uid] += @count(ifxmit[pid,dev,exec,uid]);
	}
	foreach ([pid, dev, exec, uid] in ifmerged-) {
		n_xmit = @count(ifxmit[pid, dev, exec, uid])
		n_recv = @count(ifrecv[pid, dev, exec, uid])
		printf("%5d %5d %-7s %7d %7d %7d %7d %-15s\n",
			pid, uid, dev, n_xmit, n_recv,
			n_xmit ? @sum(ifxmit[pid, dev, exec, uid])/1024 : 0,
			n_recv ? @sum(ifrecv[pid, dev, exec, uid])/1024 : 0,
			exec)
	}
	print("\n")
	delete ifxmit
	delete ifrecv
	delete ifmerged
}

probe timer.ms(5000), end, error
{
	print_activity()
}

function print_activity() では、以下の表現を使っている。
これはC言語の三項演算子と同じである。

n_xmit ? @sum(ifxmit[pid, dev, exec, uid])/1024 : 0
n_recv ? @sum(ifrecv[pid, dev, exec, uid])/1024 : 0

nettop.stpは以下の情報をプロセス毎に出力する。

• PID プロセスID
• UID ユーザーID。ユーザーID 0はrootである。
• DEV プロセスが送受信に使っているデバイス (例: eth0, eth1)
• XMIT_PK プロセスの送信パケット数
• RECV_PK プロセスの受信パケット数
• XMIT_KB 送信データ量(単位 kbytes)
• RECV_KB 受信データ量(単位 kbytes)

実行結果は以下のようになる。

$ sudo /usr/share/systemtap/testsuite/systemtap.examples/network/nettop.stp
  PID   UID DEV     XMIT_PK RECV_PK XMIT_KB RECV_KB COMMAND        

  PID   UID DEV     XMIT_PK RECV_PK XMIT_KB RECV_KB COMMAND        
    0     0 p20p1         0       2       0       0 swapper/0      
 1283  1000 p20p1         1       0       0       0 firefox        

  PID   UID DEV     XMIT_PK RECV_PK XMIT_KB RECV_KB COMMAND

5.1.2 ネットワークソケットの関数呼び出しのトレース

このセクションでは、net/socket.cの関数呼び出しをどのようにトレースするか説明する。

#! /usr/bin/env stap

probe kernel.function("*@net/socket.c").call {
	printf ("%s -> %s\n", thread_indent(1), probefunc())
}
probe kernel.function("*@net/socket.c").return {
	printf ("%s <- %s\n", thread_indent(-1), probefunc())
}

3.6で紹介したthread_indent()を使えば、以下のようにトレース出来る。

[...]
0 Xorg(3611): -> sock_poll
3 Xorg(3611): <- sock_poll
0 Xorg(3611): -> sock_poll
3 Xorg(3611): <- sock_poll
0 gnome-terminal(11106): -> sock_poll
5 gnome-terminal(11106): <- sock_poll
0 scim-bridge(3883): -> sock_poll
3 scim-bridge(3883): <- sock_poll
0 scim-bridge(3883): -> sys_socketcall
4 scim-bridge(3883): -> sys_recv
8 scim-bridge(3883):
-> sys_recvfrom
12 scim-bridge(3883):-> sock_from_file
16 scim-bridge(3883):<- sock_from_file
20 scim-bridge(3883):-> sock_recvmsg
24 scim-bridge(3883):<- sock_recvmsg
28 scim-bridge(3883):
<- sys_recvfrom
31 scim-bridge(3883): <- sys_recv
35 scim-bridge(3883): <- sys_socketcall
[...]

5.1.3 受信しているTCPコネクションの監視

このセクションでは、TCPコネクションの受信を監視する方法を説明する。
このタスクは、不正なネットワークアクセス要求をリアルタイムに特定する。

#! /usr/bin/env stap
probe begin {
  printf("%6s %16s %6s %6s %16s\n",
         "UID", "CMD", "PID", "PORT", "IP_SOURCE")
}

probe kernel.function("tcp_accept").return?,
      kernel.function("inet_csk_accept").return? {
  sock = $return
  if (sock != 0)
    printf("%6d %16s %6d %6d %16s\n", uid(), execname(), pid(),
           inet_get_local_port(sock), inet_get_ip_source(sock))
}

tcp_connections.stpは以下の情報を出力する。

• UID 現在のUID
• CMD コネクションを受け付けているコマンド
• PID プロセスID
• コネクションに使われているポート
• IP_SOURCE TCPコネクション要求元のIPアドレス

以下は出力例

UID  CMD  PID PORT   IP_SOURCE
0   sshd 3165   22 10.64.0.227
0   sshd 3165   22 10.64.0.227

5.1.4 TCPパケットの監視

このセクションでは、システムに届くTCPパケットの監視方法について説明する。
これはネットワークトラフィックの解析に有効である。

tcpdumplike.stp

#! /usr/bin/env stap
// A TCP dump like example
probe begin, timer.s(1) {
  printf("-----------------------------------------------------------------\n")
  printf("Source IP Dest IP SPort DPort U A P R S F \n")
  printf("-----------------------------------------------------------------\n")
}
probe tcp.receive {
  printf(%15s %15s %5d %5d %d %d %d %d %d %d\n",
         saddr, daddr, sport, dport, urg, ack, psh, rst, syn, fin)
}

tcpdumplike.stpはリアルタイムに受信したTCPパケットに関して、以下の情報を出力する。

• 発信元と送信先のIPアドレス (saddr, daddr)
• 発信元と送信先のPORT番号 (sport, dport)
• パケットフラグ

パケットの情報を特定するために、以下の関数を使用している。

• urg urgent
• ack acknowledgement
• psh push
• rst reset
• syn synchronize
• fin finished

これらの関数は、パケットの使用しているフラグを1か0で返す。

-----------------------------------------------------------------
Source IP
Dest IP SPort DPort U A P R S F
-----------------------------------------------------------------
209.85.229.147 10.0.2.15 80 20373 0 1 1 0 0 0
92.122.126.240 10.0.2.15 80 53214 0 1 0 0 1 0
92.122.126.240 10.0.2.15 80 53214 0 1 0 0 0 0
209.85.229.118 10.0.2.15 80 63433 0 1 0 0 1 0
209.85.229.118 10.0.2.15 80 63433 0 1 0 0 0 0
209.85.229.147 10.0.2.15 80 21141 0 1 1 0 0 0
209.85.229.147 10.0.2.15 80 21141 0 1 1 0 0 0
209.85.229.147 10.0.2.15 80 21141 0 1 1 0 0 0
209.85.229.147 10.0.2.15 80 21141 0 1 1 0 0 0
209.85.229.147 10.0.2.15 80 21141 0 1 1 0 0 0
209.85.229.118 10.0.2.15 80 63433 0 1 1 0 0 0
[...]

5.1.5 カーネルでのネットワークパケットの取りこぼしを監視する

Linuxでは様々な理由から、ネットワークスタックでパケットを捨てる事がある。
いくつかのLinuxカーネルではkernel.trace("kfree_skb")という、
捨てられたパケットを簡単に追跡するためのトレースポイントが含まれている。
dropwatch.stpはkernel.trace("kfree_skb")を使ってパケットが捨てられた事を追跡する。
スクリプトは5秒間隔で捨てられたパケットの位置を統計する。

#! /usr/bin/env stap
############################################################
# Dropwatch.stp
# Author: Neil Horman <nhorman@redhat.com>
# An example script to mimic the behavior of the dropwatch utility
# http://fedorahosted.org/dropwatch
############################################################
# Array to hold the list of drop points we find
global locations
# Note when we turn the monitor on and off
probe begin { printf("Monitoring for dropped packets\n") }
probe end { printf("Stopping dropped packet monitor\n") }
# increment a drop counter for every location we drop at
probe kernel.trace("kfree_skb") { locations[$location] <<< 1 }
# Every 5 seconds report our drop locations
probe timer.sec(5)
{
  printf("\n")
  foreach (l in locations-) {
    printf("%d packets dropped at %s\n",
           @count(locations[l]), symname(l))
  }
  delete locations
}
||>

kernel.trace("kfree_skb")はカーネルがネットワークパケットを取りこぼした箇所を追跡する。
kernel.trace("kfree_skb")は2つの引数を取る。一つは開放されたバッファを示すポインタ($skb)で、
もう一つはカーネルコードでの位置を示す($location)である。
dropwatch.stpスクリプトは、有効な$locationの位置にある関数を提供する。
関数名と$locationをマッピングする機能はデフォルトでは含まれていないため、
SystemTap 1.4では--all-modulesオプションを使う必要がある。

>||
stap --all-modules dropwatch.stp

古いバージョンのSystemTapを使う場合には、以下のようにして--all-modules を
模擬する必要がある。

stap -dkernel \
`cat /proc/modules | awk 'BEGIN { ORS = " " } {print "-d"$1}'` \
dropwatch.stp

dropwatch.stpは15秒毎に結果を出力する。
実行例を以下に示す。

Monitoring for dropped packets
1762 packets dropped at unix_stream_recvmsg
4 packets dropped at tun_do_read
2 packets dropped at nf_hook_slow
467 packets dropped at unix_stream_recvmsg
20 packets dropped at nf_hook_slow
6 packets dropped at tun_do_read
446 packets dropped at unix_stream_recvmsg
4 packets dropped at tun_do_read
4 packets dropped at nf_hook_slow
Stopping dropped packet monitor

スクリプトが、あるマシンでコンパイルされて、別のマシンで実行された場合に、--all-modulesも/proc/modulesディレクトリも有効出なかった場合には、symname関数は生のアドレスを返す。
/boot/System.map-`uname -r` を参照し、生のアドレスを手動でマッピングすることも出来る。

SystemTap Beginners Guide 4章のメモ

User-Space Probing

SystemTapはカーネル向けに作られたが、ユーザー空間のプローブも可能になった。
SystemTapのユーザ空間プローブには、カーネルのutrace拡張が必要である。
詳細は http://sourceware.org/systemtap/wiki/utrace で確認せよ。
現在のカーネルがutraceをサポートしているかどうかは、
"grep CONFIG_UTRACE /boot/config-`uname -r`"を実行して
"CONFIG_UTRACE=Y"と表示されれば、ユーザー空間でのプローブが出来る。

メモのメモ

linux kernel 3.5.0 からユーザー空間でのプローブを行うための機構uprobesが提供された。
このため、linux kernel 3.5.0以上とSystemTap1.8以上であれば、utraceをカーネルに組み込まなくても
SystemTapでユーザー空間のプローブが出来る。

4.1 ユーザー空間イベント

全てのユーザー空間イベントプローブはプロセスと共に始まる。
プロセスイベントはプロセスIDや実行ファイルパスによって、特定の実行中プロセスに限定する事が出来る。
SystemTapはPATH環境変数を参照するので、コマンドラインと実行ファイルの絶対パスの両方を実行に使うことが出来る。
いくつかのユーザー空間プローブイベントでは、debug情報が要求されるため実行ファイルパスかプロセスIDを指定する必要がある。
以下に列挙するprocessイベントのいくつかでは、実行ファイルパスかプロセスIDを指定する必要がある。
以下に列挙されていないprocessイベントでは、実行ファイルパスやプロセスIDの指定はオプションである。

• process("path").function("function")

ユーザー空間の実行ファイルパスの開始イベント。kernel.function("function")に相当する。
ワイルドカードも使えるし、.returnも使える。

• process("path").statement("statement")

statementに対する指示。kernel.statement("statement")に相当する。

• process("path").mark("marker")

pathで定義されている静的なプローブポイントマーカ。ワイルドカードを指定すれば、全てのマーカで単一のプローブが実行される。
静的なプローブポイントは($1,$2, etc)のような数値の引数を持っているかもしれない。
Javaのようなユーザー空間のパッケージは静的なプローブポイントを含んでいる。
静的なプローブポイントを提供するようなパッケージでは、生のユーザー空間マークイベントに対するエイリアスを提供している。
以下はx86_64 Java hotspot JVMのものである。

probe hotspot.gc_begin =
process("/usr/lib/jvm/java-1.6.0-openjdk-1.6.0.0.x86_64/jre/lib/amd64/server/libjvm.so").mark("gc__begin")

• process.begin

ユーザー空間プロセスが作成された。プロセスIDか実行ファイルのフルパスによって、限定することが出来る。

• process.thread.begin

ユーザー空間スレッドが作成された。プロセスIDか実行ファイルのフルパスによって、限定することが出来る。

• process.end

ユーザー空間プロセスの死亡。プロセスIDか実行ファイルのフルパスによって、限定することが出来る。

• process.thread.end

ユーザー空間スレッドの破壊。プロセスIDか実行ファイルのフルパスによって、限定することが出来る。

• process.syscall

ユーザー空間プロセスのシステムコール。システムコール番号は$syscallコンテキスト変数で利用出来、
引数の最初から6つ目までは$arg1から$arg6で利用することが出来る。
.returnサフィックスがあれば、システムコールの戻りで実行される。この時、$returnで戻り値を参照出来る。
プロセスIDか実行ファイルのフルパスによって、限定することが出来る。

4.2 ユーザー空間ターゲット変数

ユーザー空間ターゲット変数は3.3.2と同じ方法でアクセス出来る。
ユーザーとカーネルでアドレス空間が分かれているが、"->"演算子は最適なアドレス空間にアクセスする。
ポインター経由でユーザー空間のデータにアクセスする際には、以下の関数を利用出来る。

• user_char(address)

現在のユーザープロセスで、アドレスにある文字を得る。

• user_short(address)

現在のユーザープロセスで、アドレスにあるshortを得る。

• user_int(address)

現在のユーザープロセスで、アドレスにあるintを得る。

• user_long(address)

現在のユーザープロセスで、アドレスにあるlongを得る。

• user_string(address)

現在のユーザープロセスで、アドレスにあるstringを得る。

• user_string_n(address, n)

現在のユーザープロセスで、アドレスにあるstringをnbytesだけ得る。

4.3 User-Space Stack Backtraces

イベントが発生した状況を確認するためには、バックトレースがあると便利である。
SystemTapはバックトレースの表示にデバッグ情報を使っている。この機能はx86用であるため、他のアーキテクチャでは使えない。
バックトレースの表示には"-d 実行ファイルパス"オプションと、共有ライブラリのための-lddオプションが必要である。

例えば、lsコマンドでxmallocが呼ばれた際のユーザー空間のバックトレースが見たい場合には、以下のコマンドを実行する。

stap -d /bin/ls --ldd -e 'probe process("ls").function("xmalloc") {print_ustack(ubacktrace())}' -c "ls /"

実行に失敗する場合には、lsコマンド用のdebuginfoを以下のコマンドでインストールすること。
debuginfo-install coreutils-8.15-7.fc17.x86_64

さらに詳細に見たければ、ucontext-symbols.stpとucontext-unwind.stp tapsetsを参照せよ。
関数の詳細はSystemTap Tapset Reference Manualを参照せよ。