WR blog

about Enterprise IT, Oracle Database, Jazz/Fusion Music, etc…

WR blog RSS Feed
 
 
 
 

quick'n'dirtyトラブルシューティングのために/procファイルシステムを使用してLinuxカーネルランドを覗く

http://blog.tanelpoder.com/2013/02/21/peeking-into-linux-kernel-land-using-proc-filesystem-for-quickndirty-troubleshooting/ の翻訳です。

本文書に関する指摘については、原文著者のTanel Poderさんではなく、渡部まで御連絡お願いいたします。

注意事項

  • 自動翻訳に手を加えたレベルの翻訳と理解してください
  • 意味をとりやすくするために追加した箇所については、《…》で囲っています。
  • 訳がわからない、または、自信がない箇所は★をつけています。

日本語訳:渡部 亮太 (WR at Csus4 dot net)

履歴

  • 2013-04-09: 初稿up


quick'n'dirtyトラブルシューティングのために/procファイルシステムを使用してLinuxカーネルランドを覗く

このブログは、モダンなLinuxについてのものです。言い換えれば、2.6.3xのカーネル相当のRHEL6についてであり、、残念ながら企業の中で最も一般的である2.6.18カーネル相当の古代のRHEL5(なにこれ?!)についてではありません。そして、いや、私は、カーネルデバッガまたはSystemTapスクリプトを使用するつもりはありません。昔ながらの "cat /proc/PID/xyz"のコマンドを、いくつかの有用な/ procファイルシステムのエントリに対して使います。

"遅い"プロセスのトラブルシューティング

これは、私のラップトップで再現させた1つの体系的なトラブルシューティングの例です。彼らが実行したfindコマンドはしばらくの間何も結果を返さずに、"かなり遅く"実行されていたことを、DBAは不思議に思っていた。環境を知って、我々は《原因を》直感したが、私はこれ -のたった今 - すでに進行中の問題 - に対するトラブルシューティングの体系的なアプローチがどのようなものかについて尋ねられてしまった

幸いにもシステムではOEL6を実行していたので、かなり新しいカーネルだった。実際には、2.6.39 UEK2であった。

では、いくつかトラブルシューティングを行ってみましょう。まず最初に、そのfindプロセスがまだ生きているかどうかを見てみましょう:

[root@oel6 ~]# ps -ef | grep find
root     27288 27245  4 11:57 pts/0    00:00:01 find . -type f
root     27334 27315  0 11:57 pts/1    00:00:00 grep find

うん、生きています。 - PIDは27288です。(トラブルシューティングの例では、そのpidを使用します)。

基礎から始めて、このプロセスのボトルネックが何であるかを簡単に見てみましょう。によってそれが何かに(それがキャッシュから必要なものをすべて読んなど)ブロックされていない場合、CPUを100%使用しているでしょう。 もし、いくつかのIOや競合の問題がボトルネックであるならば、 CPU使用率は低いか、または完全に0%でなければならない。

[root@oel6 ~]# top -cbp 27288
top - 11:58:15 up 7 days,  3:38,  2 users,  load average: 1.21, 0.65, 0.47
Tasks:   1 total,   0 running,   1 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.1%us,  0.1%sy,  0.0%ni, 99.8%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   2026460k total,  1935780k used,    90680k free,    64416k buffers
Swap:  4128764k total,   251004k used,  3877760k free,   662280k cached
 
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
27288 root      20   0  109m 1160  844 D  0.0  0.1   0:01.11 find . -type f

topコマンドは、このプロセスはCPUの使用率が0%であるか、また​​はゼロパーセントに非常に近い(それが出力に0%に丸められます)ことを示しています。全くCPUを使用するチャンスがない完全にstuckしたプロセスと、時々待機状態から抜け出すプロセス(例えば、いくつかのポーリング操作が時々タイムアウトして、スリープ状態に戻ることを選択する) については、重要な違いがある。だから、Linux上のtopコマンドは確かにその違いを示すために十分なツールではありません - しかし、少なくとも我々は、このプロセスが多くのCPU時間のを使っていないことを知っています。

その後、何か他のものを使用しましょう​​。通常、プロセスがそのようにstuckしているように見えるとき、プロセスが現在stuckしているシステムコールにトレースするために、私はstraceコマンドを実行します。 (CPU使用率0%は通常、プロセスが何らかのブロッキングシステムコールでスタックしていることを意味します- これは、カーネルがプロセスをsleepさせることになります) プロセスは、実際に完全にstuckしておらず、システムコールから戻り、ときどき目を覚ますならば、それがstraceで現れるでしょう(ブロッキングシステムコールが完了し、少し後に再度システムコールを実行するような):

[root@oel6 ~]# strace -cp 27288
Process 27288 attached - interrupt to quit
 
^C
^Z
[1]+  Stopped                 strace -cp 27288
 
[root@oel6 ~]# kill -9 %%
[1]+  Stopped                 strace -cp 27288
[root@oel6 ~]# 
[1]+  Killed                  strace -cp 27288

おっと、straceコマンドもhungしました! 長い時間は出力を表示しませんでしたし、Ctrl + Cキーに応答しなかったので、私はCtrl + Zでバックグラウンドにして、そこからそれをkillしなければならなかった。So much for easy diagnosis.★

では、pstackを試してみましょう(Linuxでは、pstackはただのGDBデバッガのシェルスクリプトラッパーです)。pstackはカーネルランドを見ないが、私達に、システムコールが要求されたか箇所についての手掛かりを与える:(通常、ユーザランド·スタックのトップに、対応するlibcライブラリコールがあるので)

[root@oel6 ~]# pstack 27288
 
^C
^Z
[1]+  Stopped                 pstack 27288
 
[root@oel6 ~]# kill %%
[1]+  Stopped                 pstack 27288
[root@oel6 ~]# 
[1]+  Terminated              pstack 27288

pstackも、何も返さずにstuckしてしまった!

だから、我々はまだ、我々のプロセスが100%(絶望的)stuckなのか、または単に99.99%stuckなのか(プロセスはスリープ状態に戻ることを続けているのか)をしりません。stuckしている箇所も知りません。

OK、他にどこを見れば?一般的に入手可能でチェックすべきものが1つ以上あります - 古き良きpsコマンドを経由してレポートできる、プロセスの状態とWCHANフィールド: (このプロセスがゾンビではないことを確認するために、私はもっと早くこのコマンド実行しておくべきだったかもしれない)

[root@oel6 ~]# ps -flp 27288
F S UID        PID  PPID  C PRI  NI ADDR SZ WCHAN  STIME TTY          TIME CMD
0 D root     27288 27245  0  80   0 - 28070 rpc_wa 11:57 pts/0    00:00:01 find . -type f

プロセスが同じ状態のままであることを確認するために、あなたは、in a row、psを複数回実行する必要があります(あなたが不運な時に取得した、1つのサンプルに惑わされたくはありません)が、私は簡単のため一度だけそれをここに表示しています。

プロセスは、(psのmanページも言うように)通常ディスクIO関連である状態D(割り込み不可のスリープ)になっています。そして、WCHAN(このプロセスでのスリープ/待機を引き起こした関数)フィールドは少し切り捨てられています。少し広くこれをプリントアウトするには、(manを読んで)psオプションを使うことができますが、この情報は結局のところprocファイルシステムから来ているので、ソースから直接それを問い合せることにします。(繰り返しになるが、プロセスが完全にstuckしているか、または単にほとんど寝ているかどうかはまだわからないので、複数回サンプリングをすると良いだろう):

[root@oel6 ~]# cat /proc/27288/wchan
rpc_wait_bit_killable

うーん…このプロセスは、いくつかのRPCコールを待っています。RPCは、通常、プロセスが他のプロセス(ローカルサーバーまたはリモートサーバーであっても)と話していることを意味します。しかし、我々はまだ理由がわからない。

なにか動きがあるか、またはプロセスが完全にstuckしているか?

この資料の "meat"に進む前に、このプロセスが完全にstuckしているかどうかを把握しましょう​​。モダンなカーネルでは、/proc/PID/statusがこれを私たちに教えることができる。私は、我々の目的のための興味深いところを強調している:

[root@oel6 ~]# cat /proc/27288/status 
Name:   find
State:  D (disk sleep)
Tgid: 27288
Pid:    27288
PPid:   27245
TracerPid:  0
Uid:    0   0   0   0
Gid:    0   0   0   0
FDSize: 256
Groups: 0 1 2 3 4 6 10 
VmPeak:   112628 kB
VmSize:   112280 kB
VmLck:         0 kB
VmHWM:      1508 kB
VmRSS:      1160 kB
VmData:      260 kB
VmStk:       136 kB
VmExe:       224 kB
VmLib:      2468 kB
VmPTE:        88 kB
VmSwap:        0 kB
Threads:    1
SigQ:   4/15831
SigPnd: 0000000000040000
ShdPnd: 0000000000000000
SigBlk: 0000000000000000
SigIgn: 0000000000000000
SigCgt: 0000000180000000
CapInh: 0000000000000000
CapPrm: ffffffffffffffff
CapEff: ffffffffffffffff
CapBnd: ffffffffffffffff
Cpus_allowed:   ffffffff,ffffffff
Cpus_allowed_list:  0-63
Mems_allowed:   00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000000,00000001
Mems_allowed_list:  0
voluntary_ctxt_switches:    9950
nonvoluntary_ctxt_switches: 17104

プロセスは状態D -ディスク スリープ(割り込み不可のスリープ) - にある。そして、voluntary_ctxt_switchesnonvoluntary_ctxt_switches の数を見てみる - これは、プロセスがCPUを取り上げられた(または戻した)回数を示します。そして、数秒後にもう一度同じコマンドを実行し、それらの数値が増加したかどうかを見てください。私のケースでは、これらの数字は増加しなかった。よって、私は、(まあ、少なくとも数秒の間にこれらのコマンドの間は)プロセスが完全にstuckしていたと結論付けることができた。だから、私は、このプロセスは完全にstuckしていると今ではもっと自信を持つことができます。(そして、ずっとCPU時間の0.04%を使って、レーダーの下を飛んでいる《0%とみなされるぐらい小さい値のことを指しているのでは》のではないことも)

ところで、コンテキストスイッチの数を取得できる場所は、2つ以上あります。(そして、2番目の場所が古代のカーネルでも同様に機能します)

[root@oel6 ~]# cat /proc/27288/sched
find (27288, #threads: 1)
\---------------------------------------------------------
se.exec_start                      :     617547410.689282
se.vruntime                        :       2471987.542895
se.sum_exec_runtime                :          1119.480311
se.statistics.wait_start           :             0.000000
se.statistics.sleep_start          :             0.000000
se.statistics.block_start          :     617547410.689282
se.statistics.sleep_max            :             0.089192
se.statistics.block_max            :         60082.951331
se.statistics.exec_max             :             1.110465
se.statistics.slice_max            :             0.334211
se.statistics.wait_max             :             0.812834
se.statistics.wait_sum             :           724.745506
se.statistics.wait_count           :                27211
se.statistics.iowait_sum           :             0.000000
se.statistics.iowait_count         :                    0
se.nr_migrations                   :                  312
se.statistics.nr_migrations_cold   :                    0
se.statistics.nr_failed_migrations_affine:                    0
se.statistics.nr_failed_migrations_running:                   96
se.statistics.nr_failed_migrations_hot:                 1794
se.statistics.nr_forced_migrations :                  150
se.statistics.nr_wakeups           :                18507
se.statistics.nr_wakeups_sync      :                    1
se.statistics.nr_wakeups_migrate   :                  155
se.statistics.nr_wakeups_local     :                18504
se.statistics.nr_wakeups_remote    :                    3
se.statistics.nr_wakeups_affine    :                  155
se.statistics.nr_wakeups_affine_attempts:                  158
se.statistics.nr_wakeups_passive   :                    0
se.statistics.nr_wakeups_idle      :                    0
avg_atom                           :             0.041379
avg_per_cpu                        :             3.588077
nr_switches                        :                27054
nr_voluntary_switches              :                 9950
nr_involuntary_switches            :                17104
se.load.weight                     :                 1024
policy                             :                    0
prio                               :                  120
clock-delta                        :                   72

ここでは、nr_switchesの数(nr_voluntary_switches + nr_involuntary_switches に等しい)を調べる必要があります。

nr_switchesの合計は上記の出力では27054であり、これは、/proc/PID/schedstatショーの3番目のフィールドでも表示されます:

[root@oel6 ~]# cat /proc/27288/schedstat 
1119480311 724745506 27054

そして、それは増加していませんでした…

/procファイルシステムを使用して、カーネルランドを覗く

だから、それは私たちのプロセスはかなりstuckしているように見えます :) straceとpstackは役に立たなかった。それらのコマンドは、プロセスにアタッチして、そのメモリを覗くために、ptrace()システムコールを使用しますが、非常に可能性が高いいくつかのシステムコールで、プロセスが絶望的にstuckしていると、ptrace()コールもhungするのだと私は推測しています。(ところで、ターゲットプロセスにアタッチするとき、straceのプロセス自体をstracingしようとしたことがある。すると、それはターゲットをクラッシュさせた。あなたに警告しましたよ :)

それで、どのシステムコールでstuckしているかを確認する方法は? - straceやpstackなしで幸いにも私は最新のカーネルで実行されていた - /proc/PID/syscall に挨拶しましょう★!

[root@oel6 ~]# cat /proc/27288/syscall 
262 0xffffffffffffff9c 0x20cf6c8 0x7fff97c52710 0x100 0x100 0x676e776f645f616d 0x7fff97c52658 0x390e2da8ea

OK WTF 私はそれをどうするんだって?
さて、これらの数字は、通常何かを示している。それは "0xある大きな数"の場合、それは通常、メモリアドレス(およびそれらが指す場所のpmapのようなツールを使用することができる)ですが、それが小さな数の場合、おそらくそれは、いくつかの配列のインデックスだ - (/proc/PID/fdから読むことができるような)オープンされたファイル記述子の配列 または、今回の場合は、我々はシステムコールを扱っている、- それはあなたのプロセスが現在いる、システムコール番号です!だから、このプロセスは、システムコール#262でstuckしている!

システムコール番号は、OSの種類、OSのバージョン、プラットフォーム間で異なる可能性があることに注意してください。OSの種類に応じて適切なヘッダファイル(*.h)からそれを読むべきです。通常は/usr/includeから "syscall*"を検索することが、良いスタートポイントです。Linuxの私のバージョンとプラットフォーム(64ビット)上のシステムコールは、/usr/include/asm/unistd_64.h のここで定義されています:

[root@oel6 ~]# grep 262 /usr/include/asm/unistd_64.h 
#define __NR_newfstatat             262

お待たせしました!syscall 262 はnewfstatat と呼ばれるものでした。それが何であるかを調べるために、単に manを実行します。ここでは、システムコールの名前に関するヒントがあります - manページが呼び出しを見つけることができなかった場合、次に可能な接尾辞と接頭辞なしでをmanを実行してみてほしい (たとえば、代わりに "man pread64"の "man pread") - この場合は、"new"という接頭辞なしで man fstatat 。さもなくばgoogleを。

とにかく、このシステムコール"new-fstat-at"は、あなたは、通常のstatシステムコールのように、ファイルのプロパティを読み取ることができます。そして、我々は、このファイルのメタデータの読み取り動作でstuckしている。だから、我々はさらに一歩進んだことになるしかし、なぜそこでstuckしているかが我々はまだ分からない。

さて、 /proc/PID/stackSay Hello To My Little Friendしてみよう。これは、単位procファイルをcatするだけで、プロセスのカーネルスタックのバックトレースを読み取ることができる!

[root@oel6 ~]# cat /proc/27288/stack
[] rpc_wait_bit_killable+0x24/0x40 [sunrpc]
[] __rpc_execute+0xf5/0x1d0 [sunrpc]
[] rpc_execute+0x43/0x50 [sunrpc]
[] rpc_run_task+0x75/0x90 [sunrpc]
[] rpc_call_sync+0x42/0x70 [sunrpc]
[] nfs3_rpc_wrapper.clone.0+0x35/0x80 [nfs]
[] nfs3_proc_getattr+0x47/0x90 [nfs]
[] __nfs_revalidate_inode+0xcc/0x1f0 [nfs]
[] nfs_revalidate_inode+0x36/0x60 [nfs]
[] nfs_getattr+0x5f/0x110 [nfs]
[] vfs_getattr+0x4e/0x80
[] vfs_fstatat+0x70/0x90
[] sys_newfstatat+0x24/0x50
[] system_call_fastpath+0x16/0x1b
[] 0xffffffffffffffff

最上位の関数が、私たちが今stuckしている箇所のカーネルコードである - それは、正確にWCHAN 出力が見せてくれたものになっている。(実際には、その上にいくつかのより多くの関数があることに注意してほしい。たとえば、プロセスをスリープさせたり、必要に応じてCPUを割り当てたりするカーネルのschedule()関数のように。しかし、それらは、おそらくここには示されない。なぜならば、原因ではなくて、待ち条件の結果であるからだ。)

このタスクの完全なカーネルランド·スタックのおかげで、どのようにして、このrpc_wait_bit_killable関数を呼ぶことになったのかを理解するために、ボトムアップからそれを読むことができます。そして、スケジューラを呼び出して、スリープモードに私たちを入れてしまうことになったのかを。

ボトムのsystem_call_fastpathは、我々が発行したnewfstatatシステムコール(sys_newfstatat )のための、カーネルコードを呼び出した汎用のカーネル システムコールハンドラ関数です。そして、 "子"の関数を通って上方に行き続けて、我々は、スタックのNFS機能の束に会うことになる!これは、我々は、NFSコードパスの下のどこかであることを100パーセント否定できない証拠です★。私は "NFSのコードパスの中"とは言わない。 あなたがNFS関数を超えて上向きに読み続けたとき、あなたは一番上のNFS関数は、他のプロセス - このケースは、おそらく、[kworker/N:N] [nfsiod] [lockd]または[rpciod]カーネルIOスレッド - に通信するためのいくつかのRPC機能(rpc_call_sync)をコールしているのを見る。そして、我々はいくつかの理由で(たいていの疑いは、ネットワーク接続、パケットまたは単にネットワーク接続の問題を落としたであろう)のために、それらのスレッドからの応答を取得することがない。

ヘルパースレッドのいずれかがネットワーク関連のコードに引っかかっているかどうかを確認するためには、それらのカーネルスタックをサンプリングできます。しかし、kworkersは単なるNFS RPC通信より多くのことを行う。別の実験(ちょうど、NFS経由で大きなファイルをコピーする)の間に、あるkworkersがネットワークコードで待機していることをキャッチした:

[root@oel6 proc]# for i in `pgrep worker` ; do ps -fp $i ; cat /proc/$i/stack ; done
UID        PID  PPID  C STIME TTY          TIME CMD
root        53     2  0 Feb14 ?        00:04:34 [kworker/1:1]
 
[] __cond_resched+0x2a/0x40
[] lock_sock_nested+0x35/0x70
[] tcp_sendmsg+0x29/0xbe0
[] inet_sendmsg+0x48/0xb0
[] sock_sendmsg+0xef/0x120
[] kernel_sendmsg+0x41/0x60
[] xs_send_kvec+0x8e/0xa0 [sunrpc]
[] xs_sendpages+0x173/0x220 [sunrpc]
[] xs_tcp_send_request+0x5d/0x160 [sunrpc]
[] xprt_transmit+0x83/0x2e0 [sunrpc]
[] call_transmit+0xa8/0x130 [sunrpc]
[] __rpc_execute+0x66/0x1d0 [sunrpc]
[] rpc_async_schedule+0x15/0x20 [sunrpc]
[] process_one_work+0x13e/0x460
[] worker_thread+0x17c/0x3b0
[] kthread+0x96/0xa0
[] kernel_thread_helper+0x4/0x10

これは、カーネルが正確なカーネルスレッドは、他のカーネルスレッドと通信するための知っているのトレースを有効にすることが可能でなければなりませんが★、私はこの記事でそこに行くことはありません - 実用的な(そして単純な:)トラブルシューティングの練習であることになっている!

診断と "修正"

とにかく、最近のLinuxカーネルでは(それが導入されたとき、私は正確なバージョンがわからない)、非常に簡単なカーネルスタックのサンプリングのおかげで、我々は、findコマンドがstuckした箇所 - LinuxカーネルのNFSコードの中 - を体系的に把握することができました そして、NFS関連がハングアップしているときに、もっとよく疑われるのは、ネットワークの問題である。私がこの問題をどうやって再現できたか、貴方が疑問に思っているなら、私はVMからNFSボリュームをマウントしました。findコマンドを開始して、次にVMを単にsuspendしました。これは、TCPエンドポイントに通知することなく接続が暗黙的に削除されたか、パケットが何らかの理由で通らないようなネットワーク(構成、ファイアウォール)の問題と同様の症状を生成します。

スタックに記載されている最上位の関数が"killable"safe-to-kill関数(rpc_wait_bit_killable )の1つであるため、その後私たちはkill -9 でそれを殺すことができる:

[root@oel6 ~]# ps -fp 27288
UID        PID  PPID  C STIME TTY          TIME CMD
root     27288 27245  0 11:57 pts/0    00:00:01 find . -type f
[root@oel6 ~]# kill -9 27288
 
[root@oel6 ~]# ls -l /proc/27288/stack
ls: cannot access /proc/27288/stack: No such file or directory
 
[root@oel6 ~]# ps -fp 27288
UID        PID  PPID  C STIME TTY          TIME CMD
[root@oel6 ~]#

プロセスがなくなっています。

Poor-manのカーネルスレッドプロファイリング

/proc/PID/stackはただのプレーンなテキストprocファイルのように見えるので、あなたはカーネルスレッドでもPoor-manのスタックプロファイリングを行うことができることに注意してください!これは、現在のシステムコールとカーネルスタック(システムコールの場合)をサンプリングし、それを貧乏人の方法で半階層的プロファイルに集約する例です。

[root@oel6 ~]# export LC_ALL=C ; for i in {1..100} ; do cat /proc/29797/syscall | awk '{ print $1 }' ; cat /proc/29797/stack | /home/oracle/os_explain -k ; usleep 100000 ; done | sort -r | uniq -c 
     69 running
      1 ffffff81534c83
      2 ffffff81534820
      6 247
     25 180
 
    100    0xffffffffffffffff 
      1     thread_group_cputime 
     27     sysenter_dispatch 
      3     ia32_sysret 
      1      task_sched_runtime 
     27      sys32_pread 
      1      compat_sys_io_submit 
      2      compat_sys_io_getevents 
     27       sys_pread64 
      2       sys_io_getevents 
      1       do_io_submit 
     27        vfs_read 
      2        read_events 
      1        io_submit_one 
     27         do_sync_read 
      1         aio_run_iocb 
     27          generic_file_aio_read 
      1          aio_rw_vect_retry 
     27           generic_file_read_iter 
      1           generic_file_aio_read 
     27            mapping_direct_IO 
      1            generic_file_read_iter 
     27             blkdev_direct_IO 
     27              __blockdev_direct_IO 
     27               do_blockdev_direct_IO 
     27                dio_post_submission 
     27                 dio_await_completion 
      6                  blk_flush_plug_list

これは、あなたのカーネルでは、プロセスが時間を費やした箇所への非常に大まかなサンプルを与える - すべての場合。システムコール番号は上記に太字で分離されている - "running"は、このプロセスがサンプル中に(システムコール内ではなく)ユーザランドにいたことを意味します。だから、サンプリング中の時間の69%で、このプロセスはユーザランドのコードを実行していた。時間の25%は、システムコール #180(私のシステムでnfsservctl)で、6%がsyscall#247(waitid)。

この出力に見られるように、さらに2つの "関数"がある - しかし、何らかの理由でそれらが適切に関数名に翻訳されていません。さて、このアドレスが何かを表しています。手動での我々の運を試してみましょう:

[root@oel6 ~]# cat /proc/kallsyms | grep -i ffffff81534c83
ffffffff81534c83 t ia32_sysret

だから、これらのサンプルは32ビットアーキテクチャと互換性のあるシステムコールのリターン関数に関するものであることに見える - しかし、この関数はシステムコールではありません(単に内部ヘルパー関数)、おそらくそれが、/proc/stackのルーチンがそれを翻訳しなかった理由です。もしかすると、/procビューに"読取り一貫性"がないために、これらのアドレスが表示されたのかもしれない。所有するスレッドがこれらのメモリー構造とエントリを変更するとき、読み出しスレッドは、時には "in-flux"のデータを読むかもしれない。

他のアドレスも確認してみましょう:

[root@oel6 ~]# cat /proc/kallsyms | grep -i ffffff81534820
[root@oel6 ~]#

存在しない?まあ、トラブルシューティングをまだやめる必要はありません - そのアドレスの周りに何か面白いものがないか見てみましょう。アドレスから、trailingいくつかの文字を削除してみました:

[root@oel6 ~]# cat /proc/kallsyms | grep -i ffffff815348 
ffffffff8153480d t sysenter_do_call
ffffffff81534819 t sysenter_dispatch
ffffffff81534847 t sysexit_from_sys_call
ffffffff8153487a t sysenter_auditsys
ffffffff815348b9 t sysexit_audit

sysenter_dispatch関数は、/proc/PID/stackによって表示されたオリジナルのアドレスのわずか1バイト前にて、開始するように見えます。だから我々はおそらくすでに1バイト(おそらく動的トレースプローブトラップのためにそこに残されたNOP動作)を実行した。しかしそれにもかかわらず、これらのスタックのサンプルはsysenter_dispatch関数の中にいるようにみえる。それは、システムコールではなく、システムコールヘルパー関数である。

スタックプロファイラの詳細

スタックサンプラーには様々な種類があることに注意してください- LinuxのPerf、oprofileツール、Solaris DTraceのprofileプロバイダーは、CPUで現在実行中のスレッドの命令ポインタ(x64上の32ビットIntelまたはRIPのEIP) とスタック·ポインタ(64ビットで32ビットおよびRSP上のESP)のレジスタを実際にサンプリングします。そして、そこから逆方向にスタックポインタを歩く。したがって、これらのツールは、サンプリングしたときにCPUにいたスレッドのみを表示します!高CPU使用率の問題のトラブルシューティングのときひは、これはもちろん完璧です。しかし、hungしたプロセスやプロセスの非常に長いスリープと待機のトラブルシューティングには有用ではありません。

Linux、Solaris、HP-UXのpstack、(AIXの)procstack、ORADEBUG SHORT_STACKのようなツール、単に/proc/PID/stack 擬似ファイルを読むことは、CPUプロファイリングツールの良い追加(置き換えではなく)を提供する。 それらは、CPUスケジューリング状態に関係なく検出されたプロセスのメモリにアクセスし、そこからスタックを読むからだ。プロセスにCPUが割り当てられておらず、スリープしている場合は、スタックの開始点がストアドコンテキスト - コンテキストスイッチ中に、OSのスケジューラによってカーネル·メモリーに保存される - から読み取ることができます。

もちろん、CPUイベントプロファイリングツールは、しばしば単なるpstack、OProfile、Perfよりもはるかに多くの処理を行うことができる。(Solaris11の)DTraceのCPCプロバイダは、メインメモリを待ってストールしているCPUサイクルの量、L1/L2キャッシュミスの量等を推定するためのCPU内部のパフォーマンスカウンタを設定し、サンプリングできる。 Kevin Clossonがこれらのトピックについて言ったことを読んでみてほしい:(PERFoprofile

Enjoy :-)

Profile

渡部亮太 / Watabe Ryota
代官山在住のOracle Database Engineer。 株式会社コーソル所属。講演/講師業もぼちぼち。書籍「プロとしてのOracle運用管理入門」「プロとしてのOracleアーキテクチャ入門」買ってくれるとうれしいなっと。 twitter:wrcsus4

Book



Other Works

Certifications

  • Oracle Master 10g Platinum
  • Oracle Master 11g Gold
  • Oracle Master Silver Oracle PL/SQL Developer
  • Oracle Master Expert 10g RAC
  • Oracle Master Expert Oracle on Linux
  • LPIC level2
  • CCNA
  • 日商簿記3級

Contact

wrcsus4 _at_ gmail _dot_ com

Archives

Recent Posts

Recent Comments

Categories

Tags

Meta