Hi,

I have not contributed to this forum for some time, purely because, well, things have been pretty good. This is a great value product that delivers exactly what we need nearly all of the time.

That said, there are occasional issues and last night we experienced one of them. When market conditions change quickly, we sometimes find that the data we receive from DTN becomes quite delayed. Last night, in the middle of the market fall, the delay on our Nasdaq feed (66.112.156.221) hit 15 seconds. Being intra-day traders, this is quite worrying for us, and could prove to be quite expensive!

To be clear, at the same time as our Nasdaq data was being delayed, we had an identically-configured machine receiving roughly twice as much Nyse data (66.112.156.228) that was not particularly impacted. We have actually found this to be very common: Nasdaq data from our DTN feeds is much more prone to being delayed than Nyse data. Neither of our machines is stressed in any way (less than 10% CPU usage), and our internet connections are more than adequate to our needs.

We routinely graph DTN latency for each day. The latency graph for 66.112.156.221 for yesterday is attached.

Our questions are:
1. Can these latency problems be confirmed/refuted by DTN?
2. Given that they are real, are they across all machines?
3. Why would we see this with Nasdaq data, but not the more voluminous Nyse data?

Thanks,

Just a clarification, we are based in Australia (our machines are in the U.S.), hence my references to "last night". The day in question is Wednesday July 21.

Neil, thanks for the report. We are looking into this and I will let you know what we find out.

Neil, the screenshot shows that this happened between ~14:00 - 14:30. Can you confirm what timezone this is?

Is this Feed time (EST) or Pacific (if I remember right, your machines are colo'd in LA).

Hi Steve,

Sorry for the delay in responding - for some reason I'm not getting emails automatically forwarded for forum updates (probably my own fault).

All the times are Feed time (EST); market open 9:30, market close 16:00. I think we're currently colo'd in New Jersey!

On any given day it is incredibly rare for us to see a delay over 600ms. More than 95% of the time we experience latency under 90ms, with a median around 50ms (which is pretty impressive).

Regards,

Neil

Steve,

Did your investigations turn anything up? We experienced a similar delay (5 seconds, this time) on our NYSE feed at 10am market time today.

Regards,

Neil Brennan

We are still looking into it.

---

Visit our new online forums! DTN employees actively monitor the forums to provide you the highest level of support in the industry. Our forums also has an announcements area where you can learn about new features or changes within DTN. You can even use the forums to exchange trading ideas or tips and tricks on how you use your DTN data to be more profitable.

Go to http://forums.dtniq.com now to start sharing information with fellow DTN subscribers!

Hi,

We saw a perfect example of this problem again today, when the Fed made its announcement in the afternoon. At 2:16pm EST we saw a huge spike in latency from the standard value of under 100ms (which had been the case all day) to over 19 seconds!

Needless to say, being roughly 20 seconds behind the market probably isn't a great thing.

Our graph of the day's latency against the DOW is attached.

Regards,

Neil Brennan

I saw exactly the same even though I'm unfortunately still far away from Australia.

Hi Skunk!

To be clear, although we personally reside in Aus, our servers are colo'd in New Jersey and are not subject to any kind of inter-continental lag. :-)

Was there any resolution here, as I am also seeing delays?
I am subscribed to 70 symbols with IQFeed and my program using less than 10% CPU.
Yet I see constant differences in the quote timestamps of over 10 seconds with local clock.

The server is 66.112.156.222

64 bytes from 66.112.156.222: icmp_seq=1 ttl=53 time=215 ms
64 bytes from 66.112.156.222: icmp_seq=2 ttl=53 time=216 ms
64 bytes from 66.112.156.222: icmp_seq=3 ttl=53 time=214 ms
64 bytes from 66.112.156.222: icmp_seq=4 ttl=53 time=214 ms
64 bytes from 66.112.156.222: icmp_seq=5 ttl=53 time=214 ms
64 bytes from 66.112.156.222: icmp_seq=6 ttl=53 time=214 ms
64 bytes from 66.112.156.222: icmp_seq=7 ttl=53 time=215 ms
--- 66.112.156.222 ping statistics ---
7 packets transmitted, 7 received, 0% packet loss, time 6008ms
rtt min/avg/max/mdev = 214.112/215.035/216.041/0.632 ms

Local clock is sync'd with NTP

remote refid st t when poll reach delay offset jitter
==============================================================================
*europium.canoni 193.79.237.14 2 u 425 1024 377 311.390 1.016 0.964
Edited by Craig on Nov 4, 2010 at 12:56 PM

Craig, we are always monitoring and making adjustements to our systems to eliminate delays as much as possible.

We haven't heard any reports recently about delays which could be tracked back to anything on our end.

Is it possible for you to send me an example of the delays you are seeing? If I can see the data you received from the feed, it might help us track down the source of the issues you are seeing.

Hi Steve,
I'll add in some more explicit logging and try to capture some specific examples.

Hi,

We are no longer seeing the huge spikes in latency that caused us to open this thread. Normally we would see figures of between 50-100ms, although delays of a few seconds are still fairly common when the market moves swiftly.

Of considerable interest was the performance of the combined DTN/our-end system (which is all we can measure) on Wednesday. In a day of fairly savage market movements, our worst latency was only around 3 seconds and was quickly recovered. When we opened this thread a delay of 15 seconds at this point would have been common.

Regards,

Neil Brennan

Hi Neil,
That is good to know, hopefully it can be tracked to something on my side.

Craig,

I think it's pretty likely that it is a problem at your end. We're watching 1000 symbols.

Cheers,

Neil

Here is a sample...

[2010-Nov-05 09:47:42 EDT] jitter [-14] data [Q,MYL,20.1600,112182,20.1500,20.1600,2900,1300,09:47:28b]
[2010-Nov-05 09:47:42 EDT] jitter [-14] data [Q,MYL,20.1600,112182,20.1500,20.1600,2900,1400,09:47:28b]
[2010-Nov-05 09:47:42 EDT] jitter [-14] data [Q,MYL,20.1600,112182,20.1500,20.1600,2400,1400,09:47:28b]
[2010-Nov-05 09:47:42 EDT] jitter [-13] data [Q,ERX,44.1099,181519,44.0900,44.1100,1300,100,09:47:29b]
[2010-Nov-05 09:47:42 EDT] jitter [-13] data [Q,ERX,44.1099,181519,44.1000,44.1100,100,100,09:47:29b]
[2010-Nov-05 09:47:42 EDT] jitter [-13] data [Q,ERX,44.1099,181519,44.0900,44.1100,1300,100,09:47:29b]
[2010-Nov-05 09:47:42 EDT] jitter [-14] data [Q,MYL,20.1600,112182,20.1500,20.1600,2200,1400,09:47:28b]
[2010-Nov-05 09:47:42 EDT] jitter [-14] data [Q,MYL,20.1600,112182,20.1500,20.1600,2100,1400,09:47:28b]
[2010-Nov-05 09:47:42 EDT] jitter [-14] data [Q,MYL,20.1600,112182,20.1500,20.1600,1900,1400,09:47:28b]
[2010-Nov-05 09:47:42 EDT] jitter [-13] data [Q,PBR,36.3500,1201081,36.3400,36.3500,2700,900,09:47:29b]
[2010-Nov-05 09:47:42 EDT] jitter [-12] data [Q,FWLT,26.2900,939849,26.2800,26.2900,300,1100,09:47:30b]
[2010-Nov-05 09:47:42 EDT] jitter [-12] data [Q,GOOG,621.6475,258228,621.5000,621.7800,700,100,09:47:30b]
[2010-Nov-05 09:47:42 EDT] jitter [-13] data [Q,AAPL,317.9500,2354967,317.9600,317.9900,100,200,09:47:29b]
[2010-Nov-05 09:47:42 EDT] jitter [-13] data [Q,PBR,36.3500,1201081,36.3400,36.3500,2700,800,09:47:29b]
[2010-Nov-05 09:47:42 EDT] jitter [-13] data [Q,PBR,36.3500,1201081,36.3400,36.3500,2700,800,09:47:29b]
[2010-Nov-05 09:47:42 EDT] jitter [-13] data [Q,PBR,36.3500,1201081,36.3400,36.3500,2700,700,09:47:29b]
[2010-Nov-05 09:47:42 EDT] jitter [-13] data [Q,PBR,36.3500,1201081,36.3400,36.3500,2800,700,09:47:29b]
[2010-Nov-05 09:47:42 EDT] jitter [-13] data [Q,PBR,36.3500,1201081,36.3400,36.3500,2800,700,09:47:29b]
[2010-Nov-05 09:47:42 EDT] jitter [-12] data [Q,VXX,11.1800,5341804,11.1700,11.1800,11800,6400,09:47:30b]
[2010-Nov-05 09:47:42 EDT] jitter [-12] data [Q,VXX,11.1800,5341804,11.1700,11.1800,11800,6300,09:47:30b]
[2010-Nov-05 09:47:42 EDT] jitter [-14] data [Q,MYL,20.1600,112182,20.1500,20.1600,1700,1400,09:47:28b]
[2010-Nov-05 09:47:42 EDT] jitter [-12] data [Q,FWLT,26.2900,939849,26.2800,26.2900,400,1100,09:47:30b]
[2010-Nov-05 09:47:42 EDT] jitter [-12] data [Q,HYG,91.6352,198042,91.6000,91.6400,200,700,09:47:30t]

Notes:
1. The program is processing the whole TCP buffer up to the last separator contained in the data each time, so the delay is not due to bursting due to waiting for a separator at the end of the buffer.
2. The program opens trades @ 9:30 EST, this does in fact happen within a couple of seconds of 9:30, so not all quotes are delayed.

Here is full log from a different period, in this one you can see the 'T" messages, which seem to be timely and are processed out of the same buffer in order.


13:36:15.275424 0x9757150 Tokenizer::Dispatch, 'T' [T,20101105 13:36:15]
13:36:15.275580 0x9757150 IqFeedConnection::ConnectionStateLive::OnTimeStampMessage
13:36:15.275754 0x9757150 Timer::Timer(00:05:00, Timeouts::QuoteNoMessage), Id=[35532]
13:36:15.276597 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:15 EDT] jitter [-19] data [Q,MMM,86.2400,1985453,86.2500,86.2600,500,800,13:35:56b]
13:36:15.277040 0x9757150 TimerMap::OnTimer(35531, Operation canceled, Timeouts::QuoteNoMessage)
13:36:15.495586 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:15 EDT] jitter [-48] data [Q,NRF,4.3200,275586,4.3200,4.3300,2700,3300,13:35:27b]
13:36:16.157787 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:16 EDT] jitter [-114] data [Q,SRCL,72.5800,260790,72.5800,72.5900,100,100,13:34:22b]
13:36:16.159223 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:16 EDT] jitter [-15] data [Q,ESRX,52.8300,2235149,52.8300,52.8400,900,2300,13:36:01b]
13:36:16.159996 0x9757150 Tokenizer::Dispatch, 'T' [T,20101105 13:36:16]
13:36:16.160084 0x9757150 IqFeedConnection::ConnectionStateLive::OnTimeStampMessage
13:36:16.160229 0x9757150 Timer::Timer(00:05:00, Timeouts::QuoteNoMessage), Id=[35533]
13:36:16.160503 0x9757150 TimerMap::OnTimer(35532, Operation canceled, Timeouts::QuoteNoMessage)
13:36:16.375366 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:16 EDT] jitter [-34] data [Q,RYAAY,31.5100,380786,31.5000,31.5200,600,100,13:35:42b]
13:36:16.376171 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:16 EDT] jitter [-114] data [Q,SRCL,72.5800,260790,72.5800,72.5900,200,100,13:34:22b]
13:36:16.594672 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:16 EDT] jitter [-34] data [Q,RYAAY,31.5100,380786,31.5000,31.5200,700,100,13:35:42b]
13:36:16.596048 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:16 EDT] jitter [-13] data [Q,EXC,41.1385,2939178,41.1300,41.1400,4200,400,13:36:03b]
13:36:16.596283 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:16 EDT] jitter [-13] data [Q,EXC,41.1385,2939178,41.1300,41.1400,4200,500,13:36:03b]
13:36:17.256414 0x9757150 Tokenizer::Dispatch, 'T' [T,20101105 13:36:17]
13:36:17.256702 0x9757150 IqFeedConnection::ConnectionStateLive::OnTimeStampMessage
13:36:17.256882 0x9757150 Timer::Timer(00:05:00, Timeouts::QuoteNoMessage), Id=[35534]
13:36:17.259492 0x9757150 TimerMap::OnTimer(35533, Operation canceled, Timeouts::QuoteNoMessage)
13:36:17.478541 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:17 EDT] jitter [-35] data [Q,RYAAY,31.5100,380786,31.5000,31.5200,700,100,13:35:42b]
13:36:18.354159 0x9757150 Tokenizer::Dispatch, 'T' [T,20101105 13:36:18]
13:36:18.354336 0x9757150 IqFeedConnection::ConnectionStateLive::OnTimeStampMessage
13:36:18.355251 0x9757150 Timer::Timer(00:05:00, Timeouts::QuoteNoMessage), Id=[35535]
13:36:18.356532 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 13:36:18 EDT] jitter [-18] data [Q,BMC,46.1100,834856,46.1000,46.1100,100,1600,13:36:00b]

Seems odd we should get the 'T" marked 13:36:17 on time followed by a quote marked 13:35:42. Any observations welcome...
Edited by Craig on Nov 5, 2010 at 01:20 PM

Further examination does reveal a load problem earlier


09:47:10.890006 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 09:47:10 EDT] jitter [-12] data [Q,ERX,44.2700,176109,44.2200,44.2400,800,800,09:46:58b]
09:47:10.890518 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 09:47:10 EDT] jitter [-28] data [Q,JBHT,37.1400,22358,37.1200,37.1400,100,100,09:46:42b]
09:47:10.891096 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 09:47:10 EDT] jitter [-12] data [Q,ERX,44.2700,176109,44.2200,44.2400,800,300,09:46:58b]
09:47:10.892154 0x9757150 QuoteManager::OnUpdate, local clock [2010-Nov-05 09:47:10 EDT] jitter [-12] data [Q,ERX,44.2700,176109,44.2200,44.2400,800,200,09:46:58b]
09:47:10.904543 0x9757150 Tokenizer::Dispatch, 'T' [T,20101105 09:47:04]

One can see here a delayed 'T' message getting processed in order, however, I still can't explain the 13 hour log.

Here I have expanded the logging to log TCP receives.

14:52:28.692858 0x9b36a20 Connection::Connection::HandleRead(Q,CL,77.3300,1790594,77.3300,77.3400,100,600,14:52:26b,
Q,CL,77.3300,1790594,77.3300,77.3400,100,500,14:52:26b,
Q,CL,77.3300,1790594,77.3300,77.3400,100,500,14:52:26b,
Q,CTAS,28.2100,284526,28.2100,28.2200,1900,1100,14:51:28b,
Q,ADSK,35.7500,2084513,35.7400,35.7500,3200,600,14:52:27b,
Q,AMAT,12.9320,9843918,12.9300,12.9400,32000,21700,14:52:19b,
)
14:52:28.692945 0x9afe150 IqFeedConnection::Connection::OnDataReceieved(Q,CL,77.3300,1790594,77.3300,77.3400,100,600,14:52:26b,
Q,CL,77.3300,1790594,77.3300,77.3400,100,500,14:52:26b,
Q,CL,77.3300,1790594,77.3300,77.3400,100,500,14:52:26b,
Q,CTAS,28.2100,284526,28.2100,28.2200,1900,1100,14:51:28b,
Q,ADSK,35.7500,2084513,35.7400,35.7500,3200,600,14:52:27b,
Q,AMAT,12.9320,9843918,12.9300,12.9400,32000,21700,14:52:19b,
)
14:52:28.692996 0x9afe150 Tokenizer::Parse, 'Q' [Q,CL,77.3300,1790594,77.3300,77.3400,100,600,14:52:26b]
14:52:28.693099 0x9afe150 Tokenizer::Parse, 'Q' [Q,CL,77.3300,1790594,77.3300,77.3400,100,500,14:52:26b]
14:52:28.693163 0x9afe150 Tokenizer::Parse, 'Q' [Q,CL,77.3300,1790594,77.3300,77.3400,100,500,14:52:26b]
14:52:28.693227 0x9afe150 Tokenizer::Parse, 'Q' [Q,CTAS,28.2100,284526,28.2100,28.2200,1900,1100,14:51:28b]
14:52:28.693319 0x9afe150 QuoteManager::OnUpdate, local clock [2010-Nov-05 14:52:28 EDT] jitter [-60] data [Q,CTAS,28.2100,284526,28.2100,28.2200,1900,1100,14:51:28b]


One can see that @ 14:52:28.692858 I receive a block of raw data which contains messages with about ~1 second delay, mixed in is a CTAS quote with a delay of about 1 minute.
Edited by Craig on Nov 5, 2010 at 02:10 PM

Craig, I had the server guys take a look at your connection from our end and there isn't anything that we can see which would indicate any delays on our end currently. Additionally, as I mentioned above, we haven't been hearing these reports from other customers recently either. At this point, I'll have to agree with Neil that this is probably something we need to track down with your connection and diagnose.

Unfortunately, there are quite a few places that delays could be occuring. First, keep in mind that the timestamps in trade messages are provided by the exchange and we do not alter or reorder them. Next, we need to make sure that your CPU is not saturated during these times. If your CPU is getting saturated, there is a very good chance that you will see some delays somewhere along the line. Last, we need to make sure that you are not saturating your bandwidth during the times that you are seeing the delays. If we can't send you data, then it would certainly be getting delayed as we will queue some data waiting for bandwidth to free up. Along those lines, you might end up needing to make sure any networking equipment on your end is in good working order (not causing temporary drops of connectivity and or packet loss) which would essentially cause the same thing as a saturated internet connection. Let me know if you need help testing these and I can offer some suggestions.

With that said, lets get down to investigating the data that you have already submittted. One thing I noticed in your posts is that most of the messages you are calculating the difference in local time and trade time on every message (including bid updates). The trade time field in the feed only updates on trades so this certainly won't be an accurate measure of delay on anything without a trade indicator or a timestamp message.

Now, if we exclude the bid updates from your reports, we have the following:

1st example:
[2010-Nov-05 09:47:42 EDT] jitter [-12] data [Q,HYG,91.6352,198042,91.6000,91.6400,200,700,09:47:30t]

2nd example:
13:36:15.275424 0x9757150 Tokenizer::Dispatch, 'T' [T,20101105 13:36:15]
13:36:16.159996 0x9757150 Tokenizer::Dispatch, 'T' [T,20101105 13:36:16]
13:36:17.256414 0x9757150 Tokenizer::Dispatch, 'T' [T,20101105 13:36:17]
13:36:18.354159 0x9757150 Tokenizer::Dispatch, 'T' [T,20101105 13:36:18]

3rd example:
09:47:10.904543 0x9757150 Tokenizer::Dispatch, 'T' [T,20101105 09:47:04]

4th example shows all bid updates...

This smaller sample of data isn't really enough to make any conclusive determinations (although it does indicate that there is something going on somewhere since the timetamp mesages in the 3rd example is 6s off while the timestamp messages in the 2nd is on time).

Can you get a better sample size that includes a larger timeframe and only includes trades and timestamp messages? That would be a good place to start further investigation.

Hi Steve,
Thank you for the reply, I'll separate things out into points.
1) CPU: Hovering about the 5% mark most of the time, spikes up to 10%.
2) Networking: Happy to try any tests you suggest (connection is ~13Mbs download).
3) Trade time: point taken.
4) As market time is almost over today, I will prepare a sample minus the bids during Mondays session.
Edited by Craig on Nov 5, 2010 at 03:18 PM

Over the weekend I reworked the code, given my misunderstanding of the last trade time-stamp field, as of now I see no latency, even at market open. I suspect the bottleneck was being created due to the massive amount of logging generated by the bad time-stamp code.
So all good, thank you for your patience.