ＭＴ４用ＥＡ開発時代 － 発注しようとしたバーで発注できなかった件

さて前回は、久しぶりに発生した問題２件のうちOrderSelect絡みを解析して結論づけたところまで書きました。今回は、もう１件の「発注しようとしたバーで結局発注できなかった」という事象について解析／検討している様子を書いてみたいと思います。

さっそく事象から。

【発生事象】

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

仕様としては、オーダ操作時にエラー返却された場合、エラーコードによっては一旦start()関数を抜けて、次のティックデータ受信時に再度オーダ操作を試行する仕様になっている。けれども、一旦start()関数を抜けた結果、次のバーに進んでしまったら、発注に失敗したという事で警告メールを出す。

そして、今回この条件が整って警告メールを受信した。

●メール内容

[[WARN]][DEMO][FOREX.com Japan][TEST1]NZDJPYfxf.(Sample1:51209945)(Ticket:5838429) start() : Give up OrderSend until next bar.:errno:0:no error

５分足で１０通貨ペアを１つのＭＴ４で動かしているから、オーダ操作がぶつかってサーバ遅延とかしたら発生してて運が悪ければ発生しうる状態。

正直、「あぁ、なんだサーバがスローダウンしたんかぁ」と最初は思った。

でも、ログを見てみると以下の様な感じ。

●「Expert」タブ上のログ

09:20:39 SmoothMADILong USDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202459125)FWModifyOrder():START!!

09:20:39 SmoothMADILong USDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202459125)FWModifyOrder():END!! : Specified SL price is far from previous SL 

09:24:34 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202691890)Order was loss cutted:StatTicket(5838629) , FWOrderCond(0)

09:24:34 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202691906)Order was closed

09:24:34 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202691906)FWToOrder() : Decided to order

09:24:34 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202691906)FWSendOrderOrdinary():START!!

09:24:34 Sample1 EURJPYfxf.,M5: open #5839123 buy 0.07 EURJPYfxf. at 111.33 sl: 111.27 tp: 112.91 ok

09:24:34 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202693156)FWSendOrderOrdinary():END!!

09:24:34 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202693156)[[LONG]] Ticket(5839123)

09:25:17 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202734656)Order was loss cutted:StatTicket(5839123) , FWOrderCond(0)

09:25:17 Sample1 EURJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202734671)Order was closed

09:25:17 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202748421)Order was loss cutted:StatTicket(5838627) , FWOrderCond(0)

09:25:17 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202748437)Order was closed

09:25:17 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202748437)FWToOrder() : Decided to order

09:25:17 Sample1 NZDJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202748437)FWSendOrderOrdinary():START!!

09:25:31 SmoothMADILong GBPJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202752625)[[CALLBACK]]:EAOnBarChanged was called

09:25:31 SmoothMADILong GBPJPYfxf.,M5: [[DEBUG]](1.1V):Tick(202752625)FWModifyOrder():START!!

09:25:31 SmoothMADILong GBPJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]GBPJPYfxf.(SmoothMADILong:22301840)(Ticket:5838995)OrderModify : Retry cause IsTradeAllowed() return FALSE or another error was occurred.:errno:0:no error

09:25:31 SmoothMADILong AUDUSDfxf.,M5: [[DEBUG]](1.1V):Tick(202752625)[[CALLBACK]]:EAOnBarChanged was called

09:25:31 SmoothMADILong AUDUSDfxf.,M5: [[DEBUG]](1.1V):Tick(202752625)FWModifyOrder():START!!

09:25:31 SmoothMADILong AUDUSDfxf.,M5: [[DEBUG]](1.1V):Tick(202752625)FWModifyOrder():END!! : Specified SL price is far from previous SL 

09:25:31 Sample1 NZDJPYfxf.,M5: [[INFO]][DEMO][FOREX.com Japan][TEST1]NZDJPYfxf.(Sample1:51209945)(Ticket:5838429)FWSendOrderOrdinary cmd(1),lots(0.06000000),openPrice(65.27000000),OrderSlippage(5),vSlPrice(65.20000000),vTpPrice(66.36000000),Ask(65.27000000),Bid(65.22000000) : Should re-calc:errno:130:invalid stops

09:25:31 SmoothMADILong EURUSDfxf.,M5: [[DEBUG]](1.1V):Tick(202752796)[[CALLBACK]]:EAOnBarChanged was called

09:25:31 SmoothMADILong EURUSDfxf.,M5: [[DEBUG]](1.1V):Tick(202752796)FWModifyOrder():START!!

09:25:31 SmoothMADILong EURUSDfxf.,M5: [[DEBUG]](1.1V):Tick(202752796)FWModifyOrder():END!! SlPrice(1.39190000) , TargetPrice(0.00000000) but not changed

09:25:35 Sample1 NZDJPYfxf.,M5: [[WARN]][DEMO][FOREX.com Japan][TEST1]NZDJPYfxf.(Sample1:51209945)(Ticket:5838429) start() : Give up OrderSend until next bar.:errno:0:no error

●「操作履歴」タブ上のログ

09:20:33 '153141': modify order #5838994 buy 1.12 GBPUSDfxf. at 1.5949 sl: 1.5898 tp: 0.0000 -> sl: 1.5899 tp: 0.0000

09:20:37 '153141': request was accepted by server

09:20:37 '153141': request in process

09:20:37 '153141': order #5838994 buy 1.12 GBPUSDfxf. at 1.5949 was modified -> sl: 1.5899 tp: 0.0000

09:20:37 '153141': modify order #5838429 buy 1.04 USDCHFfxf. at 0.8320 sl: 0.8284 tp: 0.0000 -> sl: 0.8285 tp: 0.0000

09:20:38 '153141': request was accepted by server

09:20:38 '153141': request in process

09:20:38 '153141': order #5838429 buy 1.04 USDCHFfxf. at 0.8320 was modified -> sl: 0.8285 tp: 0.0000

09:20:39 '153141': modify order #5838967 buy 0.04 EURGBPfxf. at 0.8791 sl: 0.8783 tp: 0.8824 -> sl: 0.8787 tp: 0.8824

09:20:39 '153141': request was accepted by server

09:20:39 '153141': request in process

09:20:39 '153141': order #5838967 buy 0.04 EURGBPfxf. at 0.8791 was modified -> sl: 0.8787 tp: 0.8824

09:20:39 '153141': modify order #5838781 buy 0.97 AUDUSDfxf. at 1.0617 sl: 1.0558 tp: 0.0000 -> sl: 1.0559 tp: 0.0000

09:20:39 '153141': request was accepted by server

09:20:39 '153141': request in process

09:20:39 '153141': order #5838781 buy 0.97 AUDUSDfxf. at 1.0617 was modified -> sl: 1.0559 tp: 0.0000

09:24:35 '153141': instant order buy 0.07 EURJPYfxf. at 111.33 sl: 111.27 tp: 112.91

09:24:36 '153141': request was accepted by server

09:24:36 '153141': request in process

09:24:36 '153141': order was opened : #5839123 buy 0.07 EURJPYfxf. at 111.33 sl: 111.27 tp: 112.91

09:25:32 '153141': instant order buy 0.06 NZDJPYfxf. at 65.27 sl: 65.20 tp: 66.36

09:25:35 '153141': order buy 0.06 NZDJPYfxf. opening at 65.27 sl: 65.20 tp: 66.36 failed [Invalid S/L or T/P]

09:25:36 '153141': modify order #5838995 buy 0.28 GBPJPYfxf. at 126.76 sl: 125.16 tp: 0.00 -> sl: 125.17 tp: 0.00

09:25:36 '153141': request was accepted by server

09:25:36 '153141': request in process

09:25:36 '153141': order #5838995 buy 0.28 GBPJPYfxf. at 126.76 was modified -> sl: 125.17 tp: 0.00

09:25:37 Mail: '[[WARN]][DEMO][FOREX.com Japan][TEST1] NZDJPYfxf.(5838429): start() : Give up OrderSend until next bar.' has been sent

これは５分足でＥＡを実行していた。最初の発注時にエラーが返却されて、返却されたエラーコードが一旦start()関数を抜けて次のティックデータの受信を待つパターン。

「Expert」タブ上のログでは、最初にエラーを検出した時刻は「09:25:31」、そして次のバーにいってしまったという状態を検出したのは「09:25:35」。

つまり５分足で、同じバーにも関わらず、次のバーにいってしまったという誤検知の様に見える。

もしかして、バグ？？？

でもやっぱり、プログラムを何度見ても怪しいところが無い。発注失敗時のBarsの値を覚えておいて、ティックデータ受信時のBarsが、覚えておいたBarsと異なっていたら今回の警告メール送信という至って単純なロジック。しかもdouble型と違って、両方int型なので桁数云々というややこしい事は無い。

残念ながらログ上に、該当Barsの値を出力してなかったので、ここは改善しなければ。。。

それでも、ログを見ると不穏な箇所が。

「Expert」タブ上のログの出力時刻を見ると、「09:20:39」の次のログが「09:24:34」。

「操作履歴」タブ上のログ出力時刻を見ると、「09:20:39」の次のログが「09:24:35」。

通信障害のログは出力されていないので、つまるところ、４分程度トレードサーバからティックデータ送信が止まっていた様に見える。

でも、最初に失敗したオーダ操作を開始した時刻は「09:25:17」。

なので仮説として考えら得るのは、最初のオーダ操作でエラー検出したのは実は「09:20」のバーの時のデータで、次ティックデータ受信時には「09:25」のバーになってしまってたので警告エラーになったんじゃないかと。

つまり、通信遅延かサーバスローダウン起因で、TimeCurrent()が示す時刻とティックデータ内のBarsにズレが生じて、今回の様な見え方になったんじゃないかなぁと。
 

それを絵にしたのが、以下。

●今回の発生事象仮説

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

【対処方法検討】

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

対処したらへん！

なぜかと言うと、仮説だけど、実際にサーバ側の間欠障害が起因していて、異常が発生していたんだと思う。しかも発注しようとしたのが発注できなかったんだから、警告メールを送信するのは妥当。

しかも、そんな頻繁に発生する事象でもない。

★★ 2011/7/17 19:44追記 ★★
★★ 下記の件は、バグではなく、TimeCurrent()が通貨ペアによらない最新のサーバ時刻である　★★
★★ 事に起因する現象です。詳細はコメントを参照ください。 　　　　　　 　　　　　　　　　　　　　　　 ★★

もう１つ言うとしたら、Barsが示す時間帯とTimeCurrent()が不一致になるというサーバ側のバグなんじゃないかと。つまりサーバがティックデータ送信時にTimeCurrent()に相当するデータを付与するのは、ＭＴ４クライアントへのデータ送信直前というツクリの様に見える。

＃だからズレが発生するんじゃないかと。。

とういう事は、それを証明しようとしたらTimeCurrent()もログ出力する様にせんといかんのか。。。

－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－－

後日同じ警告メールを受信したけど、その時はタイムアウト発生起因なので、全く別事象でした。。

こういう事象ってデモ環境がゆえんなのかなぁ。

サーバ構築する側としては、デモ環境はキャパを需要に対してギリギリにして、本番環境は需要に対してある程度余裕をもたせたキャパにするのが普通だと思うんやけど。

＃コスト的な観点で。

対策打たないけど、またソース修正。。。。

ちょっと微妙な心境。。。。

そして、微妙なソース修正発生にがっくりしながら、「FXシステムトレード初心者奮闘記」の「ＭＴ４用ＥＡ開発時代」は、どこかに進むのでした。

＃ＭＴ４用ＥＡ開発用共通部品「ahfw」のドキュメント増強執筆があと少しで完了！！