今携わっている仕事は JAVA の仕事で既存の稼働中のシステムのサーバをベースにして新システム用のシステム用のサーバを開発するというものである。
まぁ基本的にそのまま持ってくるだけなのだが。
JAVA 6 + Tomcat 6 である。開発環境は Eclipse 3.5。
しかしこの仕事の前に JAVA を触ったことはほとんど無い。
それこそ 15年以上前にちょっと弄ってみたくらいである。
いやまぁこの仕事断ったら社内失業状態になるところだったんでやる以外の選択肢はなかったが。
まぁそれでもフレームワークをビルド出来るようになってソースを持って来れるようになればなんとかやれるようにはなった。
さて、今週は元のシステムに追加された機能をベースにした新機能の追加した。
なんやかんやで結構手を入れているので単純作業だけど時間は食った。
実装を終えてテスト用サーバで動かしてみた。
動かしている途中、ログを見ると「スレッド停止警告」と出ていた。あらら。
元のプログラムは直接スレッドを監視していなかったので起動したスレッドのオブジェクトを参照できるように拡張し、thread.getState() 出力するようにした。すると「Thread.State.BLOCKED」だった。
これは Deadlock が発生したな。
でもどこで起こっているのだろう。
で、再現させようと Eclipse でデバッグ実行。・・・・発生しない。
一晩放置で動かしたがデッドロックは発生しなかった。
テスト用のデータをソケットを介して流してくるテスト用サーバーからデータが流れてこないのが原因かと思い、ソケット受信するスレッドの代わりにダミーデータを送出するスレッドに置き換えたがやっぱり発生しない。
途方にくれてログに対して「BLOCKED」で grep をかけてみた。
・・・引っかかっているスレッド、今回追加した部分とは関係ないやつやん。あわわ。
無関係だと思って設定で起動しないようにしたスレッドを動かすようにしたら見事にログに BLOCKED と出てくるようになった。
BLOCK している状態で Eclipse の「デバッグ」ビューでそのスレッドを一時停止すると実行可能になったら次に実行する行を示して呼び出し階層が表示される。引っかかっているスレッドをすべて一時停止し、呼び出し階層をみて調べてみた。・・・・う～ん、なんで Deadlock になっているのかがわからん。Synchronized 付けたメソッドで互いに呼び出しあっているメソッドなんてないし。(そもそもこの時点で大きな勘違いをしている)。
いろいろ見て調べたが、最終的には「eclipse java debug deadlock」でググったときに出てくる
Stackoverflow の「 How to Debug a deadlock in Java using Eclipse」(http://stackoverflow.com/questions/2081766/how-to-debug-a-deadlock-in-java-using-eclipse)
を見て、
ことを知り、
「Jconsole Eclipse」でググって「Eclipseのtomcatプラグインから、jconsoleを利用する」(http://javastring.blog55.fc2.com/blog-entry-29.html) にたどり着いて
ことを知った。
「Eclipseのtomcatプラグインから、jconsoleを利用する」にある JAVA の起動パラメータを設定をして サーバーをデバッグ起動し、そして Jconsole を実行してみた・・・ら、ローカルでデバッグする場合は特に追加の JAVA起動パラメータを設定しなくても Jconsole が JVM に接続できることが分かったのでいったん終了し、追加した JVM起動パラメータを削除してもとに戻してサーバーをデバッグ起動し、Jconsole を起動して接続してみた。・・・おぉ、なんやグラフが表示される。
Jconsole でスレッドタブに移動する。「デッドロックを検出する」というボタンがある。押してみるとデッドロックしているスレッドの呼び出し階層とともに、ロックしている"もの"がロックした場所とともに表示された。
ロックしているものは「クラス名@16進数の数字」で表示されている。
で、まず、クラス名レベルで互いにロックしていることを確認し、数字も一致していることを確認した。・・・が、呼び出している synchronized メソッドは全然異なる。なんでだ？
そのとき閃いた。
はい、JAVA触って3か月目ですが、いまだきちんと学習していません。素人です。
調べたら 確かに JAVA で synchronized キーワードをメソッドにつけたらそのオブジェクトをロックするという意味だった。あとから考えたら、そしてよくあるロックの機構を考えたらそれが妥当であるし。
この前々日くらいに「いやぁ、こんなに synchronized 付けまくってたら同時実行性能が下がってしまいますよ。これ書いた人って分かって synchronized 付けているんですかね～」って軽口を叩いていたが、見事にブーメランの法則、「synchronized を分かっていないのはおれだぁ～。」である。(同時実行性能低下の問題があるのは確かなのですが)
オブジェクトがロックされていると分かれば問題となる個所もすぐにわかり、対応して無事 Deadlock が発生しなくなった。
やはり、慣れない言語に手をだすときは一通り言語の仕様を知るようにしましょう。思い込みは危険です。あうあうあう。
まぁ基本的にそのまま持ってくるだけなのだが。
JAVA 6 + Tomcat 6 である。開発環境は Eclipse 3.5。
しかしこの仕事の前に JAVA を触ったことはほとんど無い。
それこそ 15年以上前にちょっと弄ってみたくらいである。
いやまぁこの仕事断ったら社内失業状態になるところだったんでやる以外の選択肢はなかったが。
まぁそれでもフレームワークをビルド出来るようになってソースを持って来れるようになればなんとかやれるようにはなった。
さて、今週は元のシステムに追加された機能をベースにした新機能の追加した。
なんやかんやで結構手を入れているので単純作業だけど時間は食った。
実装を終えてテスト用サーバで動かしてみた。
動かしている途中、ログを見ると「スレッド停止警告」と出ていた。あらら。
元のプログラムは直接スレッドを監視していなかったので起動したスレッドのオブジェクトを参照できるように拡張し、thread.getState() 出力するようにした。すると「Thread.State.BLOCKED」だった。
これは Deadlock が発生したな。
でもどこで起こっているのだろう。
で、再現させようと Eclipse でデバッグ実行。・・・・発生しない。
一晩放置で動かしたがデッドロックは発生しなかった。
テスト用のデータをソケットを介して流してくるテスト用サーバーからデータが流れてこないのが原因かと思い、ソケット受信するスレッドの代わりにダミーデータを送出するスレッドに置き換えたがやっぱり発生しない。
途方にくれてログに対して「BLOCKED」で grep をかけてみた。
・・・引っかかっているスレッド、今回追加した部分とは関係ないやつやん。あわわ。
無関係だと思って設定で起動しないようにしたスレッドを動かすようにしたら見事にログに BLOCKED と出てくるようになった。
BLOCK している状態で Eclipse の「デバッグ」ビューでそのスレッドを一時停止すると実行可能になったら次に実行する行を示して呼び出し階層が表示される。引っかかっているスレッドをすべて一時停止し、呼び出し階層をみて調べてみた。・・・・う～ん、なんで Deadlock になっているのかがわからん。Synchronized 付けたメソッドで互いに呼び出しあっているメソッドなんてないし。(そもそもこの時点で大きな勘違いをしている)。
いろいろ見て調べたが、最終的には「eclipse java debug deadlock」でググったときに出てくる
Stackoverflow の「 How to Debug a deadlock in Java using Eclipse」(http://stackoverflow.com/questions/2081766/how-to-debug-a-deadlock-in-java-using-eclipse)
を見て、
「Jconsole」なるものがある
ことを知り、
「Jconsole Eclipse」でググって「Eclipseのtomcatプラグインから、jconsoleを利用する」(http://javastring.blog55.fc2.com/blog-entry-29.html) にたどり着いて
「JDK に Jconsole という JAVA アプリが含まれている」
ことを知った。
「Eclipseのtomcatプラグインから、jconsoleを利用する」にある JAVA の起動パラメータを設定をして サーバーをデバッグ起動し、そして Jconsole を実行してみた・・・ら、ローカルでデバッグする場合は特に追加の JAVA起動パラメータを設定しなくても Jconsole が JVM に接続できることが分かったのでいったん終了し、追加した JVM起動パラメータを削除してもとに戻してサーバーをデバッグ起動し、Jconsole を起動して接続してみた。・・・おぉ、なんやグラフが表示される。
Jconsole でスレッドタブに移動する。「デッドロックを検出する」というボタンがある。押してみるとデッドロックしているスレッドの呼び出し階層とともに、ロックしている"もの"がロックした場所とともに表示された。
ロックしているものは「クラス名@16進数の数字」で表示されている。
で、まず、クラス名レベルで互いにロックしていることを確認し、数字も一致していることを確認した。・・・が、呼び出している synchronized メソッドは全然異なる。なんでだ？
そのとき閃いた。
「もしかして、JAVA のメソッドに付けた synchronized キーワードってそのメソッドが呼び出されたらそのメソッドを持つオブジェクトをロックしているのか?」
はい、JAVA触って3か月目ですが、いまだきちんと学習していません。素人です。
調べたら 確かに JAVA で synchronized キーワードをメソッドにつけたらそのオブジェクトをロックするという意味だった。あとから考えたら、そしてよくあるロックの機構を考えたらそれが妥当であるし。
この前々日くらいに「いやぁ、こんなに synchronized 付けまくってたら同時実行性能が下がってしまいますよ。これ書いた人って分かって synchronized 付けているんですかね～」って軽口を叩いていたが、見事にブーメランの法則、「synchronized を分かっていないのはおれだぁ～。」である。(同時実行性能低下の問題があるのは確かなのですが)
オブジェクトがロックされていると分かれば問題となる個所もすぐにわかり、対応して無事 Deadlock が発生しなくなった。
やはり、慣れない言語に手をだすときは一通り言語の仕様を知るようにしましょう。思い込みは危険です。あうあうあう。
