test

Sun Java System Directory Server Enterprise Edition 6.3 トラブルシューティングガイド

応答しないプロセスに関するデータの分析: 例

たとえば、次のように Directory Server 上で ldapsearch の実行を試みます。


# ldapsearch -p 5389 -D "cn=Directory Manager" -w secret 
-b"o=test" description=*

このコマンドにより 40 秒の検索が実行されますが、結果は得られません。プロセスが応答しない原因を分析するには、最初に次のコマンドを実行してプロセス ID を取得します。


# ps -aef | grep slapd | grep slapd-server1
   mares 15013 24159  0 13:06:20 pts/32   0:00 grep slapd-server1
   mares 14993     1  1 13:05:36 ?        0:04 ./ns-slapd -D
/u1/SUNWdsee/user1/52/slapd-server1 -i /u1/SUNWdsee/user1/52/slapd-s

次に、検索を再実行し、検索中に Directory Server プロセスに対して prstat および pstack コマンドを同時に実行します。上記の出力では、このプロセスのプロセス ID は 14993 です。


prstat -L -p 14993 0 1 > prstat.output ; pstack 14993 > pstack.output

2 秒の間隔をおいてコマンドを 3 回連続して実行します。

最初の prstat コマンドの出力は、次のようになります。


   PID USERNAME  SIZE   RSS STATE  PRI NICE      TIME  CPU PROCESS/LWPID      
 14993 mares     128M  110M cpu0    59    0   0:00.02 3.0% ns-slapd/51
 14993 mares     128M  110M sleep   59    0   0:00.49 1.3% ns-slapd/32
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/16
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/15
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/14
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/13
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/12
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/11
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/10
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/9
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/8
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/6
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/5
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/4
 14993 mares     128M  110M sleep   59    0   0:00.00 0.0% ns-slapd/3
Total: 1 processes, 51 lwps, load averages: 0.36, 0.29, 0.17

問題はスレッド 51 で発生しているようです。次に最初の pstack コマンドの出力内でスレッド 51 を検索すると、次のようになっています。


-----------------  lwp# 51 / thread# 51  --------------------
 ffffffff7eb55a78 ???????? (1, 102183a10, ffffffff70c1d340, 1001c5390, 0, 
ffffffff7ecea248)
 ffffffff77925fe0 id2entry (1002b7610, 1a09, 0, ffffffff70c1e7f4, 0, ffffffff77a6faa8) 
+ 3e8
 ffffffff7795ed20 ldbm_back_next_search_entry_ext (101cfcb90, 10190fd60, 0, 101b877b0, 
1a08, 45b4aa34) + 300
 ffffffff7ebaf6f8 ???????? (101cfcb90, 1002b7610, 1, ffffffff70c1eaf4, 0, 0)
 ffffffff7ebafbc4 ???????? (101cfcb90, 1, ffffffff70c1eaf4, 0, 10190fd60, 
ffffffff70c1e980)
 ffffffff7ebaf170 op_shared_search (101cfcb90, 0, 1015ad240, 0, ffffffffffffffff, 
ffffffff7ecea248) + 8c0
 ffffffff7e92efcc search_core_pb (101cfcb90, 2, 1000, 4000, ffffffff7ea4c810, 
ffffffff7ea56088) + 6c4
 ffffffff7e93a710 dispatch_operation_core_pb (101cfcb90, 101cfcb90, c00, 
ffffffff7ea4c810, 0, d10) + cc
 ffffffff7e926420 ???????? (101f3fe80, 102fd3250, 2, 63, 2, 200000)
 ffffffff7e92672c ldap_frontend_main_using_core_api (101f3fe80, 102fd3250, 2, 
101da1218, 10133db10, 0) + fc
 ffffffff7e927764 ???????? (220, 101c97310, ffffffffffffffff, 800, 958, 101f3fe80)
 ffffffff7d036a7c _pt_root (101c97310, ffffffff70b00000, 0, 0, 20000, ffffffff70c1ff48)
 + d4
 ffffffff7c1173bc _lwp_start (0, 0, 0, 0, 0, 0)
注 –

この例では、各行をページに納めるために行末を改行しています。

2 番目および 3 番目の pstack コマンドの出力では、スレッド 51 が同じタイプの操作を実行し、同じ結果が表示されます。

2 秒間隔で実行した 3 つの pstack の出力はすべて、スレッド 51 が同じ検索操作を実行していることを示しています。op_shared_search 関数の最初のパラメータには、実行される操作のアドレス (101cfcb90) が含まれます。3 つのスタックのそれぞれで同じ操作が実行されています。これは、最初と最後の pstack の実行間隔である 4 秒間に同じ検索が実行されていることを示します。さらに、prstat の出力は、スレッド 51 が CPU 使用量のもっとも高いスレッドであることを常に示しています。

アクセスログでハングアップ検出時の検索操作の結果を確認すると、これがインデックスを使用しない記述エントリ上での検索の結果であることがわかります。このハングアップは、記述インデックスを作成することで回避できます。