Quickfix/n network related issue

Question

I have an issue with my fix engine which I can't quite get to the bottom of. I ran the following test: I sent multiple requests to the fix server(for example-new order single), let's say 20 at a time. Then when I receive the execution reports back, the Quickfix engine takes a long time to process them, it processes a few than halts/stops for a 150 ms or so and continues(so it takes about 1 ms per message, but with long pauses). I used a packet sniffer to check the network stream and it show no such delays, all messages arrive in 2-3 ms span. I removed all my logic, and set the session setting on bare minimum to avoid any extra work, and memory allocations. I ran this test many times, and it shows the same results each time.

I use the engine log file timestamps to read message time.

Heres the .cfg file

[DEFAULT]
ConnectionType=initiator
ReconnectInterval=2
FileStorePath=store
FileLogPath=Log
StartTime=06:00:00
EndTime=03:00:00
UseDataDictionary=N
ValidateLengthAndChecksum=N
ValidateFieldsOutOfOrder=N
ValidateFieldsHaveValues=N
ValidateUserDefinedFields=N
SocketTcpNoDelay=Y
DataDictionary=FixSpec/FIX44.xml
SocketConnectHost=x.x.x.x
SocketConnectPort=xxxxx
LogoutTimeout=5
ResetOnLogon=Y
UseMassCancel=N
UseMassStatus=N
ResetOnDisconnect=Y
HeartBtInt=30

[SESSION]
BeginString=FIX.4.4
SenderCompID=xxxxx
TargetCompID=xxx

here is my FromApp:

public void FromApp(Message message, SessionID sessionId)
    {
        try
        {
            Crack(message, sessionId);
        }
        catch (UnsupportedMessageType ex)
        {
            UnSupportedMessage?.Invoke(this, message);
        }
    }

And My ExecutionReport handler

 public void OnMessage(ExecutionReport m, SessionID s)
    {

    }

I removed all logic from my Application to avoid unnecessary noise.

Example log output:

20160811-07:10:44.541 : 8=FIX.4.49=24135=856=xxxxx49=XXX34=452=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-355=AAPL54=138=159=540=244=50.00000017=8916296071=xxxxx22=248=202180515=USD20=039=0150=037=89162960860=20160811-07:10:44.57210=129
20160811-07:10:44.545 : 8=FIX.4.49=24135=856=xxxxx49=XXX34=552=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-455=AAPL54=138=159=540=244=50.00000017=8916296091=xxxxx22=248=202180515=USD20=039=0150=037=89162961060=20160811-07:10:44.57410=128
20160811-07:10:44.546 : 8=FIX.4.49=24135=856=xxxxx49=XXX34=652=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-555=AAPL54=138=159=540=244=50.00000017=8916296111=xxxxx22=248=202180515=USD20=039=0150=037=89162961260=20160811-07:10:44.57710=128
20160811-07:10:44.549 : 8=FIX.4.49=24135=856=xxxxx49=XXX34=752=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-655=AAPL54=138=159=540=244=50.00000017=8916296131=xxxxx22=248=202180515=USD20=039=0150=037=89162961460=20160811-07:10:44.58010=128
20160811-07:10:44.551 : 8=FIX.4.49=24135=856=xxxxx49=XXX34=852=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-755=AAPL54=138=159=540=244=50.00000017=8916296151=xxxxx22=248=202180515=USD20=039=0150=037=89162961660=20160811-07:10:44.58310=137
20160811-07:10:44.554 : 8=FIX.4.49=24135=856=xxxxx49=XXX34=952=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-855=AAPL54=138=159=540=244=50.00000017=8916296171=xxxxx22=248=202180515=USD20=039=0150=037=89162961860=20160811-07:10:44.58510=145
20160811-07:10:44.557 : 8=FIX.4.49=24235=856=xxxxx49=XXX34=1052=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-955=AAPL54=138=159=540=244=50.00000017=8916296191=xxxxx22=248=202180515=USD20=039=0150=037=89162962060=20160811-07:10:44.58810=185
20160811-07:10:44.560 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=1152=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-1055=AAPL54=138=159=540=244=50.00000017=8916296211=xxxxx22=248=202180515=USD20=039=0150=037=89162962260=20160811-07:10:44.59110=216
20160811-07:10:44.562 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=1252=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-1155=AAPL54=138=159=540=244=50.00000017=8916296231=xxxxx22=248=202180515=USD20=039=0150=037=89162962460=20160811-07:10:44.59410=225
20160811-07:10:44.565 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=1352=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-1255=AAPL54=138=159=540=244=50.00000017=8916296251=xxxxx22=248=202180515=USD20=039=0150=037=89162962660=20160811-07:10:44.59610=233
20160811-07:10:44.693 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=1452=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-1355=AAPL54=138=159=540=244=50.00000017=8916296271=xxxxx22=248=202180515=USD20=039=0150=037=89162962860=20160811-07:10:44.59910=242
20160811-07:10:44.693 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=1552=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-1455=AAPL54=138=159=540=244=50.00000017=8916296291=xxxxx22=248=202180515=USD20=039=0150=037=89162963060=20160811-07:10:44.60210=224
20160811-07:10:44.693 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=1652=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-1555=AAPL54=138=159=540=244=50.00000017=8916296311=xxxxx22=248=202180515=USD20=039=0150=037=89162963260=20160811-07:10:44.60510=224
20160811-07:10:44.699 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=1752=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-1655=AAPL54=138=159=540=244=50.00000017=8916296331=xxxxx22=248=202180515=USD20=039=0150=037=89162963460=20160811-07:10:44.60910=234
20160811-07:10:44.699 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=1852=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-1755=AAPL54=138=159=540=244=50.00000017=8916296351=xxxxx22=248=202180515=USD20=039=0150=037=89162963660=20160811-07:10:44.61310=235
20160811-07:10:44.699 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=1952=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-1855=AAPL54=138=159=540=244=50.00000017=8916296371=xxxxx22=248=202180515=USD20=039=0150=037=89162963860=20160811-07:10:44.61710=245
20160811-07:10:44.699 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=2052=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-1955=AAPL54=138=159=540=244=50.00000017=8916296391=xxxxx22=248=202180515=USD20=039=0150=037=89162964060=20160811-07:10:44.62110=228
20160811-07:10:44.699 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=2152=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-2055=AAPL54=138=159=540=244=50.00000017=8916296411=xxxxx22=248=202180515=USD20=039=0150=037=89162964260=20160811-07:10:44.71410=219
20160811-07:10:44.699 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=2252=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-2155=AAPL54=138=159=540=244=50.00000017=8916296431=xxxxx22=248=202180515=USD20=039=0150=037=89162964460=20160811-07:10:44.71610=227
20160811-07:10:44.700 : 8=FIX.4.49=24335=856=xxxxx49=XXX34=2352=20160811-07:10:4432=031=0.000000151=114=06=0.00000011=rA0Ny-2255=AAPL54=138=159=540=244=50.00000017=8916296451=xxxxx22=248=202180515=USD20=039=0150=037=89162964660=20160811-07:10:44.72010=228

Any ideas? Is this normal behavior? Where would you look for solutions?

Any thoughts on what is going on under the hood there?

I want to see what's in your `OnMessage(ExecutionReport)` function. — Grant Birchmeier, Aug 10 '16 at 20:52
You are probably doing some blocking operation in your `onMessage` implementation? Have you timed how long it takes you to crack a message? — TT., Aug 11 '16 at 06:56
Just ran the test again, removed all logic from FromApp - even Crack call. It gives same results. just updated my question with log data, showing times. — Shaaak, Aug 11 '16 at 07:13
What's the log output is that on the client or server side? What rig are you running the server on? How many CPU? — rupweb, Aug 11 '16 at 14:51

Quickfix/n network related issue

0 Answers0