2011/07/21

ＭＴ４用ＥＡ開発時代 － 「OrderSelect問題」が再発した！！



さて前回は、久しぶりに発生した２件の問題を解析／処置検討したところまで書きました。今回は、以前からお騒がせしている「OrderSelect問題」が再発したという報告です。


また怪しげなメールが来た～


という事で、メールとログの内容から。

【ログ等】
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
●メール内容（2011/7/19受信）
[[WARN]][DEMO][FOREX.com Japan][TEST1]NZDJPYfxf.(Sample1:51209945)(Ticket:5940701)WriteLog : Unknown ticket no. StatTicket(0) OrderTicket(5940701):errno:0:no error

●「Experts」タブ上のログ
11:10:39 SmoothMADILong AUDUSDfxf.,M5: [[DEBUG]](1.1V):Tick(137681984)[[CALLBACK]]:EAOnBarChanged was called
11:10:39 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137681984)FWClosePositions():START!!
11:10:39 SmoothMADILong AUDUSDfxf.,M5: [[DEBUG]](1.1V):Tick(137681984)FWModifyOrder():START!!
11:10:40 Sample1 NZDJPYfxf.,M5: close #5941768 buy 0.65 AUDUSDfxf. at 1.06 sl: 1.06 at price 1.06
11:10:40 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137682343)FWClosePositions():END(Success)!!
11:10:40 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137682343)[[CLOSE]]:Ticket(5952969)
11:10:40 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137682406)Order was closed
11:10:40 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137682406)FWModifyOrder():START!!
11:10:40 SmoothMADILong AUDUSDfxf.,M5: modify #5952969 buy 0.03 NZDJPYfxf. at 66.9500 sl: 66.8400 tp: 67.2500 ok
11:10:40 SmoothMADILong AUDUSDfxf.,M5: [[DEBUG]](1.1V):Tick(137682953)FWModifyOrder():END!! SlPrice(1.05860000) , TargetPrice(0.00000000)
11:10:41 SmoothMADILong USDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137685656)[[CALLBACK]]:EAOnBarChanged was called
11:10:41 SmoothMADILong USDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137685656)FWModifyOrder():START!!
11:10:41 SmoothMADILong USDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137685656)FWModifyOrder():END!! : Specified SL price is far from previous SL 
11:10:41 SmoothMADILong GBPJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137685671)[[CALLBACK]]:EAOnBarChanged was called
11:10:41 SmoothMADILong GBPUSDfxf.,M5: [[DEBUG]](1.1V):Tick(137685687)[[CALLBACK]]:EAOnBarChanged was called
11:10:41 SmoothMADILong GBPUSDfxf.,M5: [[DEBUG]](1.1V):Tick(137685687)FWModifyOrder():START!!
11:10:41 SmoothMADILong GBPUSDfxf.,M5: [[DEBUG]](1.1V):Tick(137685687)FWModifyOrder():END!! SlPrice(1.60340000) , TargetPrice(0.00000000) but not changed
11:14:01 Sample1 NZDJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]NZDJPYfxf.(Sample1:51209945)(Ticket:5952969)FWModifyOrder Ticket(5952969) , SlPrice(66.84000000) , TargetPrice(67.25000000) Ask(66.92000000) Bid(66.86000000) : Retry after long time.:errno:128:trade timeout
11:14:01 Sample1 NZDJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]NZDJPYfxf.(Sample1:51209945)(Ticket:5952969)Wait for next tick to OrderModify().:errno:0:no error
11:14:01 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137888453)FWClosePositions():START!!
11:14:07 Sample1 NZDJPYfxf.,M5: close #5952969 buy 0.03 NZDJPYfxf. at 66.95 sl: 66.84 tp: 67.25 at price 66.89
11:14:07 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137893281)FWClosePositions():END(Success)!!
11:14:07 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137893281)[[CLOSE]]:Ticket(0)
11:14:07 Sample1 NZDJPYfxf.,M5: [[WARN]][DEMO][FOREX.com Japan][TEST1]NZDJPYfxf.(Sample1:51209945)(Ticket:5940701)WriteLog : Unknown ticket no. StatTicket(0) OrderTicket(5940701):errno:0:no error
11:14:07 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(137893281)Order was closed

●「操作履歴」タブ上のログ
11:10:37 '153141': modify order #5940701 buy 0.63 EURUSDfxf. at 1.4077 sl: 1.4088 tp: 0.0000 -> sl: 1.4089 tp: 0.0000
11:10:40 '153141': request was accepted by server
11:10:40 '153141': request in process
11:10:40 '153141': order #5940701 buy 0.63 EURUSDfxf. at 1.4077 was modified -> sl: 1.4089 tp: 0.0000
11:10:41 '153141': modify order #5941768 buy 0.65 AUDUSDfxf. at 1.0603 sl: 1.0585 tp: 0.0000 -> sl: 1.0586 tp: 0.0000
11:10:41 '153141': request was accepted by server
11:10:41 '153141': request in process
11:10:41 '153141': order #5941768 buy 0.65 AUDUSDfxf. at 1.0603 was modified -> sl: 1.0586 tp: 0.0000
11:10:41 '153141': modify order #5952969 buy 0.03 NZDJPYfxf. at 66.95 sl: 66.83 tp: 67.25 -> sl: 66.84 tp: 67.25
11:10:41 '153141': request was accepted by server
11:10:41 '153141': request in process
11:10:41 '153141': order #5952969 buy 0.03 NZDJPYfxf. at 66.95 was modified -> sl: 66.84 tp: 67.25
11:14:01 '153141': modification of order #5952969 buy 0.03 NZDJPYfxf. at 66.95 sl: 66.84 tp: 67.25 -> sl: 66.84 tp: 67.25 failed [Trade timeout]
11:14:11 '153141': close order #5952969 buy 0.03 NZDJPYfxf. at 66.95 sl: 66.84 tp: 67.25 at price 66.89
11:14:12 '153141': request was accepted by server
11:14:12 '153141': request in process
11:14:12 '153141': order #5952969 buy 0.03 NZDJPYfxf. at 66.95 sl: 66.84 tp: 67.25 closed at price 66.89
11:14:13 Mail: '[[WARN]][DEMO][FOREX.com Japan][TEST1] NZDJPYfxf.(5940701):WriteLog : Unknown ticket no. StatTicket(0) OrderTicket(5940701)' has been sent

●トレードログ（独自ログ）
1 5952969 NZDJPY 2011/7/19 11:00 1970/1/1 0:00 1 66.95 66.86 0.03 0 0 -270 -270 2 0 0
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

【発生事象の要約】
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
主人公は、NZDJPYとAUDUSDなので、そこをおおまかに抜粋

●メール内容
　内部管理しているチケット番号がゼロだったのでエラーメール

●「Experts」タブ上のログ
　11:10:39 ： NZDJPYの決済処理と、AUDUSDのＳＬ／ＴＰ変更処理が同時に開始
　11:10:40 ： NZDJPYのＥＡが、AUDUSDのオーダ（OrderTicket()：5941768）をOrderClose()
　　　　　　　内部管理のチケット番号は5952969
　11:10:40 ： AUDUSDのＥＡが、NZDJPYのオーダ（OrderTicket()：5952969）をOrderModify()
　11:14:01 ： NZDJPYのＥＡが、NZDJPYのオーダ（OrderTicket()：5952969）をOrderModify()
　　　　　　　しようとしてタイムアウト発生
　11:14:07 ： NZDJPYfxfのＥＡが、NZDJPYのオーダ（OrderTicket()：5952969）をOrderClose()
　11:14:07 ： 内部管理しているチケット番号がゼロなので警告メール通知

●「操作履歴」タブ上のログ
　11:10:40 ： （AUDUSDのオーダ（OrderTicket()：5941768）をOrderClose()）のログなし
　11:10:41 ： NZDJPYのオーダ（5952969）のOrderModify成功
　11:14:01 ： NZDJPYのオーダ（5952969）のOrderModifyでタイムアウト発生
　11:14:12 ： NZDJPYのオーダ（5952969）のOrderClose成功
　11:14:13 ： エラーメール送信

●トレードログ（独自ログ）
　NZDJPYのOrderCloseTime()がゼロ
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－


【問題解析】
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－





もう、めちゃくちゃ。

　
　
NZDJPYのＥＡがAUDUSDのオーダを決済してるし、
AUDUSDのＥＡがNZDJPYのオーダをＳＬ変更してるし。


おまけに、AUDUSDのオーダ決済を決済した時のログが「操作履歴」タブ上のログに残ってない。
＃プログラムロジック上は、OrderClose()自体エラーになっても、OrderSelect()ループで、該当オーダが見つからなければ成功としてる。
　Printでログが出力されないパターンは、「ERR_NO_RESULT」が返却されたか、OrderSelect()ループで見つからなかった時だけ。

コレ、start()排他制御しない設定のデモ環境で発生。


まさに以前発生した「OrderSelect問題」と同じ事象が発生。


●以前の「OrderSelect問題」動作内容概略（再掲）
　１．GBPJPYのFWModifyOrder(OrderModifyする共通関数）と、AUDUSDの
　　　FWClosePositions（通貨ペアとMAGICが同じポジションを全て決済する共通関数）
　　　が同時に処理を開始
　２．AUDUSDのEAが、GBPJPY(#5409644)を、OrderCloseして成功　★恐ろしい事１
　　　→ ここで、内部管理しているチケット番号を格納した変数の内容をゼロに設定。
　３．AUDUSDのEAが、FWModifyOrder()開始（キーはOrderTicket()）
　　　初回で、ERR_TRADE_TIMEOUTが発生し、リトライ開始
　　　最初のリトライ後、ERR_NO_RESULTが返却され、成功扱いに。
　４．AUDUSDのEAが、FWClosePositions()開始
　　　AUDUSDのオーダ(#5412969)をOrderCloseして成功
　５．ログ出力の際、内部管理しているチケット番号を格納した変数が０なので、
　　　エラー検出。★発生事象「４．」の箇所。
　６．GBPJPYのEAが、AUDUSD(#5412969)のOrderModify（キーはOrderTicket()）
　　　に成功 ★恐ろしい事２
　

当時の「操作履歴」上のログを改めて確認すると、上記「２．」のOrderClose()をしたログがやはり残ってなかった。

OrderModifyとOrderCloseを同時にしようとしたところとか、別の通貨ペアをオーダ操作したところとかも含めて、発生事象は同じ。しかもなぜか途中のOrderModify()でタイムアウト発生するところまで同じ。

前々回の記事で書いたOrderSelect()が別の不審な挙動をした時、やはり通信異常が発生しているという共通点を考えると、ＭＴ４の通信用スレッドの制御がヘンな感じ。
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

【結論】
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
再現したって事は、少なくとも、start()関数の排他制御の効果はあったっぽい。

もしかしたらオーダ操作時だけ排他制御すればいいのかもしれないけど、あっちこっちにロック／アンロックロジックいれるとバグの温床になるし、処理時間の大半はきっとオーダ操作時だし。このままでいいかなと。

●補足
　・MT4のその後のバージョンアップ情報として、以下を見たけどようわからんかった。

　結局、「Fixed errors reported on the forum and in crash logs.」とかで表現
　されてる部分に一体何が含まれてるのかわからん。。。
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

【今後について】
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－
前々回の記事でも書いたけど、start()関数の排他制御は残す。
あとは、今回問題が発生したデモ環境でstart()関数排他制御を行う様に設定して、本番始まる前まで再発しなければＯＫ。
－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－




これで決着ほぼついたかな？？？






どや、まいったか！！



そして、原因不明にも関わらずにドヤ顔をしながら、「FXシステムトレード初心者奮闘記」の「ＭＴ４用ＥＡ開発時代」は、ＰＣ障害時のトレード用ＰＣ切替について話が進むのでした。
＃「モンテカルロ法による最大ドローダウンシミュレーションツール」を利用した方から反応頂いてめっちゃ嬉しかった！！

投稿者 時刻:
ラベル:

0 件のコメント:

コメントを投稿

登録: コメントの投稿 (Atom)