Are there performance issues with CSocket::Send?

Question

UPDATE 14 June 2011

A quick update... Most respondents have focused on the dodgy method for handling the queue of messages to be logged however while there is certainly a lack of optimisation there it's certainly not the root of the problem. We switched the Yield over to a short sleep (yes, the Yield did result in 100% CPU once the system went quiet) however the system still can't keep up with the logging even when it's going nowhere near that sleep. From what I can see the Send is just not very efficient. One respondent commented that we should block up the Send() together in to one send and that would seem like the most appropriate solution to the larger underlying issue and that's why I have marked this as the answer to the original question. I certainly agree the queue model is very flawed though, so thanks for feedback on that and I have up-voted all answers that have contributed to the discussion.

However, this exercise has got us to review why we're using the external logging over a socket like we are, and while it may well have made sense previously when the logging server did lots of processing over the log entries... it no longer does any of that and therefore we have opted to remote that entire module and go for a direct-to-file approach via some pre-existing logging framework, this should eliminate the problem entirely as well as remove unnecessary complexity in the system.

Thanks again for all the feedback.

ORIGINAL QUESTION

In our system we have two components important to this problem - one is developed in Visual C++ and the other is Java (don't ask, historic reasons).

The C++ component is the main service and generates log entries. These log entries are sent via a CSocket::Send out to a Java logging service.

The problem

Performance of sending data seems very low. If we queue on the C++ side then the queue gets backed up progressively on busier systems.

If I hit the Java Logging Server with a simple C# application then I can hammer it way faster then I will ever need to from the C++ tool and it keeps up beautifully.

In the C++ world, the function that adds messages to the queue is:

void MyLogger::Log(const CString& buffer)
{
    struct _timeb timebuffer;
    _ftime64_s( &timebuffer );

    CString message;
    message.Format("%d%03d,%04d,%s\r\n", (int)timebuffer.time, (int)timebuffer.millitm, GetCurrentThreadId(), (LPCTSTR)buffer);

    CString* queuedMessage = new CString(message);
    sendMessageQueue.push(queuedMessage);
}

The function run in a separate thread that sends to the socket is:

void MyLogger::ProcessQueue()
{
    CString* queuedMessage = NULL;
    while(!sendMessageQueue.try_pop(queuedMessage))
    {
        if (!running)
        {
            break;
        }
        Concurrency::Context::Yield();
    }

    if (queuedMessage == NULL)
    {
        return;
    }
    else
    {
        socket.Send((LPCTSTR)*queuedMessage, queuedMessage->GetLength());
        delete queuedMessage;
    }
}

Note that ProcessQueue is run repeatedly by the outer loop thread itself, which excluding a bunch of nonsense preamble:

while(parent->running)
{
    try
    {
        logger->ProcessQueue();
    }
    catch(...)
    {
    }
}

The queue is:

Concurrency::concurrent_queue<CString*> sendMessageQueue;

So the effect we're seeing is that the queue is just getting bigger and bigger, log entries are being sent out to the socket but at a much lower rate than they're going in.

Is this a limitation of CSocket::Send that makes it less than useful for us? A mis-use of it? Or an entire red-herring and the problem lies elsewhere?

Your advice is much appreciated.

Kind Regards

Matt Peddlesden

Answer 1

Well, you could start by using a blocking producer-consumer queue and to get rid of the 'Yield'. I'm not surprised that messages get blocked up - when one is posted, the logger thread is typically, on a busy system, ready but not running. This will introduce a lot of avoidable latency before any message on the queue can be processed. The background thread than has a quantum to try an get rid of all the messages that have accumulated on the queue. If there are a lot of ready threads on a busy system, it could well be that the thread just does not sufficient time to handle the messages. especially if a lot have built up and the socket.send blocks.

Also, almost competely wasting one CPU core on queue polling cannot be good for overall performance.

Rgds, Martin