Re: [Quickfix-developers] heartbeat gaps are longer than my HeartBeatInt

SourceForge Headquarters 225 Broadway Suite 1600 San Diego, CA 92101 +1 (858) 422-6466

Greetings,
I'm still having issues with my HeartBeatInt (and it's also affecting my
TestRequest sending).   The body of my toAdmin() function is below.

So I thought that on my development laptop the 3 conditionals and the three
calls to setField() might be adding some extra time, but 40 milliseconds???
 So I tested this out on my production environment -- 8-core (nehalem) Dell
R610, and sure enough, I'm still seeing these gaps.

Unfortunately, there's no way I can test the speed if I *don't* make those 3
calls to setField() because the CME will reject the message w/out these
fields.  I sincerely hope that making these three calls isn't adding this
much time.  Does anyone have any thoughts?  Does anyone see similar behavior
(I would think that the gap between heartbeats should be HeartBeatInt plus *
maybe *1 or 2 ms).  Is this simply the result of .NET managed to unmanaged
calls within QuickFix (please say no)?

public void toAdmin(QuickFix.Message __p1, SessionID __p2)
{
    if (__p1 is Logon) {
        ILinkSession session = null;
        if (m_SessionMap.TryGetValue(__p2.getSenderCompID(), out session)) {
            __p1.setField(new IntField(95, session.sessionPassword.Length));
            __p1.setField(new StringField(96, session.sessionPassword));
        }
    } else if (__p1 is ResendRequest) {
        ResendRequest request = (ResendRequest)__p1;
        Session session = Session.lookupSession(__p2);
        if(session != null){
            int expectedNext = session.getExpectedTargetNum();

        }
        MainFrame.AddStatusMessage("requesting iLink sequence numbers " +
request.getBeginSeqNo().getValue() + " through " +
request.getEndSeqNo().getValue());
        m_LastResendRequestSeqNum = __p1.getHeader().getInt(34);
        if (__p1.isSetField(369)) {
            __p1.removeField(369); // in using the CME's "basic resend"
functionality, tag 369 cannot be present.
        }
    } else if (__p1 is Logout) {
        if (!__p1.isSetField(789)) {
            Session userSession = Session.lookupSession(__p2);
            if (userSession != null) {
                __p1.setInt(789, userSession.getExpectedTargetNum());
            }
        }
    }
    if (!__p1.getHeader().isSetField(50)) {
        __p1.getHeader().setField(new StringField(50, m_ServerID));
    }
    __p1.getHeader().setField(new CharField(57, 'G'));
    __p1.getHeader().setField(new StringField(142, m_ServerID));
}

8=FIX.4.2 | 9=80 | 35=0 | 34=11295 | 369=871 | 52=20091015-15:10:31.355 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=124 |
8=FIX.4.2 | 9=81 | 35=0 | 34=872 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:10:50.771* | 56=CME | 57=G | 142=JBM152 | 10=229 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11296 | 369=872 | 52=20091015-15:10:51.394 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=131 |
8=FIX.4.2 | 9=81 | 35=0 | 34=873 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:11:10.812* | 56=CME | 57=G | 142=JBM152 | 10=223 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11297 | 369=873 | 52=20091015-15:11:11.435 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=126 |
8=FIX.4.2 | 9=81 | 35=0 | 34=874 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:11:30.852* | 56=CME | 57=G | 142=JBM152 | 10=230 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11298 | 369=874 | 52=20091015-15:11:31.476 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=135 |
8=FIX.4.2 | 9=81 | 35=0 | 34=875 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:11:50.892* | 56=CME | 57=G | 142=JBM152 | 10=237 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11299 | 369=875 | 52=20091015-15:11:51.517 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=135 |
8=FIX.4.2 | 9=81 | 35=0 | 34=876 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:12:10.934* | 56=CME | 57=G | 142=JBM152 | 10=232 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11300 | 369=876 | 52=20091015-15:12:11.560 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=114 |
8=FIX.4.2 | 9=81 | 35=0 | 34=877 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:12:30.978* | 56=CME | 57=G | 142=JBM152 | 10=243 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11301 | 369=877 | 52=20091015-15:12:31.600 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=113 |
8=FIX.4.2 | 9=81 | 35=0 | 34=878 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:12:50.018* | 56=CME | 57=G | 142=JBM152 | 10=231 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11302 | 369=878 | 52=20091015-15:12:51.641 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=122 |
8=FIX.4.2 | 9=81 | 35=0 | 34=879 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:13:10.060* | 56=CME | 57=G | 142=JBM152 | 10=226 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11303 | 369=879 | 52=20091015-15:13:11.683 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=127 |
8=FIX.4.2 | 9=81 | 35=0 | 34=880 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:13:30.102* | 56=CME | 57=G | 142=JBM152 | 10=217 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11304 | 369=880 | 52=20091015-15:13:31.723 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=117 |
8=FIX.4.2 | 9=81 | 35=0 | 34=881 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:13:50.142* | 56=CME | 57=G | 142=JBM152 | 10=224 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11305 | 369=881 | 52=20091015-15:13:51.764 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=126 |
8=FIX.4.2 | 9=81 | 35=0 | 34=882 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:14:10.184* | 56=CME | 57=G | 142=JBM152 | 10=228 |
8=FIX.4.2 | 9=80 | 35=0 | 34=11306 | 369=882 | 52=20091015-15:14:11.806 |
49=CME | 50=G | 56=XXXXXXN | 57=JBM152 | 10=122 |
8=FIX.4.2 | 9=81 | 35=0 | 34=883 | 49=XXXXXXN | 50=JBM152 | 52=20091015-*
15:14:30.226* | 56=CME | 57=G | 142=JBM152 | 10=228 |

On Wed, Oct 14, 2009 at 10:06 AM, Rick Lane <ric...@gm...> wrote:

> Greetings,
> I'm attempting to do some certification on the CME (I like to re-certify
> every year or so to ensure no new changes break any parts of our platform),
> and they've introduced a new certification environment that is more
> sensitive than prior systems.  There is an issue I'm seeing that seems to be
> causing a particular test to fail, and the issue is that the gap between my
> heartbeats is slightly over my pre-determined heartbeat interval, sometimes
> by 2 or 3 ms, but other times by 50-100 ms.  What could be causing this
> delay?
>
> At first I thought maybe it was my file logging of messages, so I turned
> that off and the CME was still seeing this gap.  It can't be a connection
> thing because the timestamps on my messages (when I have logging turned on)
> show gaps wider than 30 seconds, so it's something that's happening *before
> *the message leaves my box.
>
> Any thoughts?
>
> Thanks,
> Rick
>