2011/07/17

MT4用EA開発時代 - 発注しようとしたバーで発注できなかった件



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

さっそく事象から。

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

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

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

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

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

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

●「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


これは5分足でEAを実行していた。最初の発注時にエラーが返却されて、返却されたエラーコードが一旦start()関数を抜けて次のティックデータの受信を待つパターン。
「Expert」タブ上のログでは、最初にエラーを検出した時刻は「09:25:31」そして次のバーにいってしまったという状態を検出したのは「09:25:35」。

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







もしかして、バグ???


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

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

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

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

通信障害のログは出力されていないので、つまるところ、4分程度トレードサーバからティックデータ送信が止まっていた様に見える。
でも、最初に失敗したオーダ操作を開始した時刻は「09:25:17」。

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

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

●今回の発生事象仮説

-----------------------------------

【対処方法検討】
-----------------------------------



対処したらへん!


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

★★ 2011/7/17 19:44追記 ★★
★★ 下記の件は、バグではなく、TimeCurrent()が通貨ペアによらない最新のサーバ時刻である ★★
★★ 事に起因する現象です。詳細はコメントを参照ください。                        ★★
もう1つ言うとしたら、Barsが示す時間帯とTimeCurrent()が不一致になるというサーバ側のバグなんじゃないかと。つまりサーバがティックデータ送信時にTimeCurrent()に相当するデータを付与するのは、MT4クライアントへのデータ送信直前というツクリの様に見える。
#だからズレが発生するんじゃないかと。。

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


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


こういう事象ってデモ環境がゆえんなのかなぁ。
サーバ構築する側としては、デモ環境はキャパを需要に対してギリギリにして、本番環境は需要に対してある程度余裕をもたせたキャパにするのが普通だと思うんやけど。
#コスト的な観点で。





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

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



そして、微妙なソース修正発生にがっくりしながら、「FXシステムトレード初心者奮闘記」の「MT4用EA開発時代」は、どこかに進むのでした。
MT4用EA開発用共通部品「ahfw」のドキュメント増強執筆があと少しで完了!!

4 件のコメント:

  1. kartz 【旧ブログから転記】2013/05/07 18:30

    こんばんは。

    ログは詳しくは見ていませんが、

    > Barsが示す時間帯とTimeCurrent()が不一致になるというサーバ側のバグ

    TimeCurrent() は、気配値ウインドに登録されている(通常、複数の)通貨ペアの気配値の更新時刻のうち最も新しいものを返す関数です。MarketInfo(Symbol(), MODE_TIME) と混同しないようにしましょう。

    テスターでは両者は同じになると思いますが。

    【旧ブログから転記】
    ※ このコメントは、旧ブログで頂いたコメントを、ブログ筆者が転記したものです。

    返信削除
  2. kartz様

    いつもありがとうございます!

    Barsが示す時間帯とTimeCurrent()が不一致になるケースがあるのは、
    バグじゃなくて、仕様だという事ですよね?

    確かに、ログ出力日時=TimeCurrentだと思うので、
    MarketInfo(Symbol(), MODE_TIME)と不一致であればバグだけど、
    そうではないので、バグじゃないですね。。。

    ログ観る時はこの辺りを気をつけないといけないですね~

    う~ん。。
    MarketInfo(Symbol(), MODE_TIME)もログに出力した方がいいのかなぁ。。。

    ともかく、ご指摘ありがとうございます!

    スッキリしました!

    > こんばんは。
    >
    > ログは詳しくは見ていませんが、
    >
    > > Barsが示す時間帯とTimeCurrent()が不一致になるというサーバ側のバグ
    >
    > TimeCurrent() は、気配値ウインドに登録されている(通常、複数の)通貨ペアの気配値の更新時刻のうち最も新しいものを返す関数です。MarketInfo(Symbol(), MODE_TIME) と混同しないようにしましょう。
    >
    > テスターでは両者は同じになると思いますが。

    【旧ブログから転記】
    ※ このコメントは、旧ブログのコメントを、ブログ筆者が転記したものです。

    返信削除
  3. kartz 【旧ブログから転記】2013/05/07 18:31

    こんにちは。

    > MarketInfo(Symbol(), MODE_TIME)もログに出力した方がいいのかなぁ。。。

    蛇足ながら、MarketInfo(Symbol(), MODE_TIME) は RefreshRates() しなくても更新されていきますので、start() が起動された時刻を知りたい場合は、start() の先頭で別途保存しておかなければなりません。

    【旧ブログから転記】
    ※ このコメントは、旧ブログで頂いたコメントを、ブログ筆者が転記したものです。

    返信削除
  4. kartz様

    度々ありがとうございます!

    > MarketInfo(Symbol(), MODE_TIME) は RefreshRates() しなくても更新されていきます

    そうなんですか!
    勉強になります!

    だとすると今回の出力目的で言うと、MarketInfo(Symbol(), MODE_TIME)も含めて出力する意味が
    なくなっちゃいますね。。
    #Barsの情報から、実は前のバーのデータなのかが判別できるので。

    ともかく、また暴走する前にアドバイス頂きありがとうございます!

    > こんにちは。
    >
    > > MarketInfo(Symbol(), MODE_TIME)もログに出力した方がいいのかなぁ。。。
    >
    > 蛇足ながら、MarketInfo(Symbol(), MODE_TIME) は RefreshRates() しなくても更新されていきますので、start() が起動された時刻を知りたい場合は、start() の先頭で別途保存しておかなければなりません。

    【旧ブログから転記】
    ※ このコメントは、旧ブログのコメントを、ブログ筆者が転記したものです。

    返信削除