Strange Behavior with Threading and Timer

Question

I explain my situation.

I have a producer 1 to N consumers pattern. I'm using blocking collections and everything is working well. Doing some test I noticed this strange behavior:

I was testing how long my manipulation of data took in my consumers. I noticed this strange things, below you'll find the code cleaned of my manipulation and which produce the strange behavior.

I have 4 consumers for 1 producer. For most of data, the Console doesn't print anything, because ts=0 (its under a tick) but randomly (between every 1 to 5sec) it plots something like this (not in this very specific order, but of the same kind):

It is of the order of 10,000 ticks so around 1ms. Always a number in the format (N)000(N-1) Note that the BlockingCollection I consume is filled depending on some network events which occurred completely at random times. Nothing regular from here.

The timing is almost perfect, always a multiple of 10,000 ticks.

What could be behind this ? Thks !

    while(IsAlive)
    {
            DataToFieldMapping item;
            try
            {
                _CollectionToConsume.TryTake(out item, -1);
            }
            catch
            {
                item = null;
            }
            if (item != null)
            {
                    long ts = (DateTime.Now.Ticks - item.TimeStamp.Ticks);
                    if(ts>10)
                       Console.WriteLine(ts);
            }
     }

score 4 · Accepted Answer · answered Mar 07 '14 at 19:28

What's going on here is that DateTime.Now has a fairly limited precision. It's not giving you the time to the nearest tick. It is only updated every 10,000 ticks or so, which is why you generally see multiples of 10k ticks in your prints.

If you really want to get a better feel for the duration of those events, use the StopWatch class, which has a much higher precision. That said, StopWatch is simply a diagnostic tool (hence why it's in the Diagnostics namespace). You should only be using it to help you diagnose what's going on, and should be using it in production code.

On a side note, there really isn't any need to use a timer here at all. It appears that you're creating several consumers that are polling the BlockingCollection for new content. There is no reason to do this. They can simply block until the collection has items. (Hence the name, BlockingCollection.

The easiest way is for the consumers to simply do this:

foreach(var item in _CollectionToConsume.GetConsumingEnumerable())
   ProcessItem(item);

Then just run that code in a background thread.

Ok, Thks for the side note , i'll replace my while()/trytake with your loop. — qwark, Mar 07 '14 at 19:40

score 1 · Answer 2 · answered Mar 07 '14 at 19:31

if you write the following and run, you'll see that ticks do not roll one to one, but rather in relatively large chunks b/c ticks resolution is actually much smaller.

for(int i =0; i< 100; i++)
{
    Console.WriteLine(DateTime.Now.Ticks);
}

Use Stopwatch class to measure performance as that one uses a high-resolution timer which is much more suitable for the purpose.

Strange Behavior with Threading and Timer

2 Answers2