きどたかのブログ

いつか誰かがこのブログからトラブルを解決しますように。

WAS for z/OSのJMSトレースを読み耽っていた二日間の収穫

WebSphere Application Server z/OS MDB RRS WebSphere MQ 性能 RMF

先にいっておくと、別に答えらしい何かはあまりない。

 

ろくな資料が手元になく、

唯一意味があったのがJMSトレースを含むログだけだった。

トランザクションとJ2Cもたぶん入ってた。

 

一時的な性能劣化。

そういう時はなにを疑うだろうか。

 

GCか？

おこってない。メモリは一切波立ってない。

 

Javaのロックか？

ログだけでは判断できないが、そんなところでsynchronizedしないだろうって箇所ばかりで遅いように思える。ほとんどスレッド動いてない。

 

SQLか？

ログ見た感じ、SQL以外のところが変だ。

 

MQか？

ログ見た感じ、確かにMQに関係する部分が遅いことがあるようだ。

ただ、見てるのはWASのログで、MQJMSに関する部分ではあるが、

MQのネイティブな部分が遅いという見え方には思えない。

 

コミットに時間がかかっているか？

ログ見た感じ、かかっていることもあれば、そうでないこともある。

 

一日目はCRのログを見ていた。

二日目はSRのログを見ていた。

z/OSで見ると検索性が悪いのでログは手元でやることにした。

デカすぎるので開けないから、PowerShellで分割するのに丸一日かけた。

40万ラインで分割すると、だいたい１ファイル20MBになった。

それが60ファイルだ。

見たい時間帯は59番目のファイルにあった。おいおいｗ

今度からはJavaのコード書いてマルチスレッドで分割しようと思う。

 

正直この手の問題はログで答えがでることは稀で、

今回のもログから解決することはないだろう。

だからただの状況把握が目的。

 

わりと頻繁に発生してくれるのなら情報収集の方法も考えられるが

ログを見てる限り、これを容易に再現することはかなわないだろう。

 

SYSLOGもながめたが、平穏な内容だった。

CPUが枯渇してそうな状況ではない。

 

ページングか？

ログから分かるはずもない。

 

スワップか？

WASはふつうスワップさせないようにNOSWAPで設定しとくものだ。

 

Javaのロックの点は、ログ読んでたら何個くらいスレッド動いてるか分かる。

１個だ。ちょっとだけかぶってるのがあったけどそれでも２個だ。

それも１個目のグローバルトランのコミットが終わったあと

お掃除してるときに２つ目のがやってきたという程度の話で、

ユーザーアプリケーションが同時に動いていない。

 

とりあえずSMF、RMFレポートがないと進まないだろう。

とくにDelay Reportが見たい。だからきっとモニターIIIが必要。

その他もろもろのレポートも当然見たい。

PAGEとCPUとWLM Activityと、あとはCFも念のため。

 

WASのSMF120は今回のには向かない気がする。

Javaプロファイラーも向かないかな。

どこか特定のメソッドが遅いとかじゃないんで。

javacoreやSVCDUMPを取る意味もあまりない。

 

いやSVCDUMPでSYSTRACEを眺める価値はあるのかな・・・。

WASからどれくらいの間隔でインストラクション来てるとか。

問題が起こったときに即座にダンプが取れればの話だけど、今回のは取れると思う。

 

Javaをやっていて遅いと速いの基準

個人的にはおおむね次のような感覚だ。

 

メソッドコール1ミリ秒は文句なし。

1ミリ秒未満でも1ミリ秒に見えることはある。

 

メソッドコール10ミリ秒はやや不満。

CPUやメソッドがやってる内容にもよる。

遅いといえば遅いが、主原因であることはほとんどない。

軽いSQLなら10ミリ秒以内でかえってくることもある。

 

メソッドコール50ミリ秒はけっこう不満。

問題児リストに名前をあげるか迷うライン。

 

メソッドコール100ミリ秒以上は我慢ならん。

重ねて言うがメソッドのやってる内容による。

根っこのやつが100ミリ秒とかは問題じゃない。

 

 

さて、過去の知識の復習の部分もあるけど、

今回の収穫（気付き）を書いてみよう。

 

収穫その１

ちゃんと確かめてはいないが、やっぱりSRの処理は一貫して1スレッドっぽい。

MQが裏でスレッド使ってそうだなと思っていたんだが、

ServerSessionいじるあたりからずっと同じスレッドっぽい気がする。

 

収穫その２

com.ibm.ws390.mdb.MDBCppUtilities.onMessageReference

トレースからこいつを探すと動き出しと終了がだいたいわかる。

これはSRがMQGETする前の部分。

 

MQGETの部分はまずはその外側のconsume()を探すのでもいい。

開始は　consume()

終了は　consume(), msg

とりあえずconsume()で検索してmsgがついてるラインは終了だと思う。

 

ユーザーアプリケーションの開始地点を見るなら

com.ibm.ejs.jms.listener.MDBWrapper.onMessage

あたりをおさえておけば十分だろう。

com.ibm.ejs.jms.listener.WS390ServerSession.runMRはそれよりも外側。

このあたりはAPARを適当に探せばスタックトレースあるからすぐ分かる。

 

収穫その３

CRの動き出しはproxyってのがついてる。

どんな文字だったか忘れた。

proxyconsumerだっけかな・・・。

proxyconsumershadowだっけかな・・・。

これはたぶんBROWSE特有な気がしている。

その前後のトレースは、クラス名が分からないやつで囲まれてる。

メッセージがあれば同一スレッドで続くし、なければ続かない。

 

収穫その４

収穫というか今後の研究対象だけど。

stage1processing

stage2processing

stage3processing

ってのを調べようと思う。たぶんそんな資料は見つからないだろう。

名前書き間違えてるかもしれんが、stage1から3まであったのは確か。

MDBの処理が抜けた後のコミットに関する部分。

今回のはstage1processingでコミットしてるようだった。

stage2とstage3は何のためにあるのやら。

SDSRMに関係してるのか？

WASの2フェーズの最適化が関係してるのか？ 

 

収穫その５

WASからpre-prepareがでてるっぽい。

pre-prepareはRRSの用語になる。

WASがSDSRMで動いてるのかはまだ確信はない。

 

収穫その６

com.ibm.ws390.tx.NativeTransactionContext

これはRRSのContext Serviceに深く関係しているようだ。

URに関するメソッドもすこしあったはず。

RRSとWASの関係を紐解くうえで、注意して見ておこうと思う。 

 

収穫その７

RRS関係でSTOKENが使われているのは調べがついていたんだが、

やっぱりMDBを処理するときにSTOKENを取得してるのが見れた。

どのサービスのために使ったのかは今後みておきたい。

 

収穫その８

WLMキューイング・モデルのサーバ・マネージャがキューイング・マネージャに終了を通知、キューイング・マネージャが受信して動く部分がだいたい分かった。

CR=キューイング・マネージャ

SR=サーバ・マネージャ

方法はさておき、昔から想像していたとおり、そういう部分が確認できた。

CRは通知を受け取るとMDBスロットルをメンテしてるっぽい。

うんうん、想像どおりだ。

SRでのコミットと、この通知は若干のラグが発生してるように思える。

 

なんて検索すればいいんだっけかな、notifyMDBあたり。

notifyListenerとかでもよかったはず。

CR側でひょっこりとスレッドが動き出す。

 

収穫その９

MQのreinflateってなんだ？

Referenceをコピーしてるっぽい。

 

収穫その１０

handleMessageReferenceでCRがSRに送ってると思う。

 

収穫その１１

LTCでdelistしてる部分。

あれはいったいなんだろう。

きっとenlistもあったんだろうな。

トランザクションに関係してるリソースでも積んでるんだろう。

 

 

テキストファイルで見れる量であればいいが、

やはりz/OSで見ないといけない局面がきっとあるだろう。

これらはそのための勉強だ。

MQJMSのデータを見るようなキーワードは今回あまり含まなかったが、

ふつうにmqgetやmqmdとかでやっとけばその場でよりよいキーワードが見つかる。