Bug in epicsMessageQueue?

[Mark Rivers via Core-talk <core-talk at aps.anl.gov>]

I just wrote a little test program for epicsMessageQueue.  I think it demonstrates a bug, but perhaps it just means I am doing something wrong.

 

The program is attached.  The program takes 2 arguments, numLoops and delayTime.

 

The main program just loops numLoops times, waiting for delayTime and then sending a 32-bit integer message which is the loop counter.

 

There is a messageTask thread that just calls epicsMessageQueueReceiveWithTimeout with a 0.1 second timeout in an infinite loop.  It prints a message it if receives a message, or if it times out.  It also increments a numReceived counter.

 

If the program is called with numLoops=200 and delayTime=0.11 it works fine.  This is the final output, numLoops=numSent=numReceived=200.

 

Loops=200, numSent=200, numReceived=200

 

If the program is called with numLoops=200 and delayTime=0.09 it also works fine.  This is the final output, numLoops=numSent=numReceived=200.

 

Loops=200, numSent=200, numReceived=200

 

However, if it is called with numLoops=200 and delayTime=0.10 (the same value as the timeout in epicsMessageQueueReceiveWithTimeout) it fails:

 

Loops=200, numSent=200, numReceived=188

 

Here is some of the output:

 

2020/03/20 15:47:45.239     sent value=86

2020/03/20 15:47:45.239 received value=86

2020/03/20 15:47:45.339 receive timeout

2020/03/20 15:47:45.339     sent value=87

2020/03/20 15:47:45.339 received value=87

2020/03/20 15:47:45.439 receive timeout

2020/03/20 15:47:45.439 received value=88

2020/03/20 15:47:45.439     sent value=88

2020/03/20 15:47:45.539 receive timeout

2020/03/20 15:47:45.539 received value=89

2020/03/20 15:47:45.539     sent value=89

2020/03/20 15:47:45.639     sent value=90

2020/03/20 15:47:45.639 received value=90

2020/03/20 15:47:45.739     sent value=91

2020/03/20 15:47:45.739 received value=91

2020/03/20 15:47:45.839     sent value=92

2020/03/20 15:47:45.839 received value=92

2020/03/20 15:47:45.939     sent value=93

2020/03/20 15:47:45.939 received value=93

2020/03/20 15:47:46.039     sent value=94

2020/03/20 15:47:46.039 received value=94

2020/03/20 15:47:46.139     sent value=95

2020/03/20 15:47:46.139 received value=95

2020/03/20 15:47:46.239     sent value=96

2020/03/20 15:47:46.240 receive timeout

2020/03/20 15:47:46.240 receive timeout

2020/03/20 15:47:46.340     sent value=97

2020/03/20 15:47:46.340 receive timeout

2020/03/20 15:47:46.340 receive timeout

2020/03/20 15:47:46.440     sent value=98

2020/03/20 15:47:46.440 received value=98

2020/03/20 15:47:46.540     sent value=99

2020/03/20 15:47:46.540 received value=99

2020/03/20 15:47:46.640     sent value=100

2020/03/20 15:47:46.640 received value=100

 

Note that occasional timeouts are expected because the delay time between messages is “exactly” the same as the timeout.  We see that after messages 86 and 87, which is fine.  What is wrong is what happens after messages 96 and 97.  in both cases there are then 2 timeouts in less than 1 ms, and messages 96 and 97 are never received.  This seems like a bug?

 

This test is on linux-x86_64 with base 7.0.3.1 with commit  4f2228fb1d7527fb5ebc8b2d747c309f1dd7698d reverted.

 

Mark

 

 

 

From: Mark Rivers
Sent: Friday, March 20, 2020 1:07 PM
To: 'core-talk at aps.anl.gov' <core-talk at aps.anl.gov>
Subject: RE: C++ question

 

I reverted commit  4f2228fb1d7527fb5ebc8b2d747c309f1dd7698d in EPICS base that uses epicsTimeMonotonic.  That did not fix the problem.

 

I still see things like this:

 

2020/03/20 12:52:34.510 ImageEventHandler::OnImageEvent sending uniqueId=80

2020/03/20 12:52:34.511 ADSpinnaker::grabImage received uniqueID 80 from message queue

2020/03/20 12:52:34.625 ImageEventHandler::OnImageEvent sending uniqueId=81

2020/03/20 12:52:34.626 ADSpinnaker::grabImage received uniqueID 81 from message queue

2020/03/20 12:52:34.740 ImageEventHandler::OnImageEvent sending uniqueId=82

2020/03/20 12:52:34.741 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 12:52:34.742 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 12:52:34.842 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 12:52:34.855 ImageEventHandler::OnImageEvent sending uniqueId=83

2020/03/20 12:52:34.855 ADSpinnaker::grabImage received uniqueID 83 from message queue

2020/03/20 12:52:34.970 ImageEventHandler::OnImageEvent sending uniqueId=84

2020/03/20 12:52:34.970 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 12:52:34.971 ADSpinnaker::grabImage received uniqueID 84 from message queue

 

and this

 

2020/03/20 12:52:38.305 ImageEventHandler::OnImageEvent sending uniqueId=113

2020/03/20 12:52:38.305 ADSpinnaker::grabImage received uniqueID 113 from message queue

2020/03/20 12:52:38.419 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 12:52:38.420 ImageEventHandler::OnImageEvent sending uniqueId=114

2020/03/20 12:52:38.421 ADSpinnaker::grabImage received uniqueID 114 from message queue

2020/03/20 12:52:38.535 ImageEventHandler::OnImageEvent sending uniqueId=115

2020/03/20 12:52:38.535 ADSpinnaker::grabImage received uniqueID 115 from message queue

2020/03/20 12:52:38.650 ImageEventHandler::OnImageEvent sending uniqueId=116

2020/03/20 12:52:38.650 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 12:52:38.652 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 12:52:38.754 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 12:52:38.765 ImageEventHandler::OnImageEvent sending uniqueId=117

2020/03/20 12:52:38.765 ADSpinnaker::grabImage received uniqueID 117 from message queue

2020/03/20 12:52:38.880 ImageEventHandler::OnImageEvent sending uniqueId=118

2020/03/20 12:52:38.880 ADSpinnaker::grabImage received uniqueID 118 from message queue

 

Messages 82 and 116 were sent on the messageQueue but never received.  In both cases there are 2 timeouts within 1-2 ms, when the timeout is 100 ms.

 

Mark

 

 

 

 

From: Mark Rivers
Sent: Friday, March 20, 2020 11:56 AM
To: 'core-talk at aps.anl.gov' <core-talk at aps.anl.gov>
Subject: RE: C++ question

 

Folks,

 

I have added debugging print statements when sending a message on the epicsMessageQueue and when receiving the message on the epicsMessageQueue.  Each time a message is sent I print the UniqueID of the image that was sent.  When the message is received I also print the UniqueID of the message that was received.  The time between message is about 0.115 seconds, while the epicsMessageQueue receive timeout is 0.1 seconds. 

 

Here is what I observed:

 

2020/03/20 11:37:37.098 ImageEventHandler::OnImageEvent sending uniqueId=85

2020/03/20 11:37:37.098 ADSpinnaker::grabImage received uniqueID 85 from message queue

2020/03/20 11:37:37.213 ImageEventHandler::OnImageEvent sending uniqueId=86

2020/03/20 11:37:37.213 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 11:37:37.214 ADSpinnaker::grabImage received uniqueID 86 from message queue

2020/03/20 11:37:37.328 ImageEventHandler::OnImageEvent sending uniqueId=87

2020/03/20 11:37:37.328 ADSpinnaker::grabImage received uniqueID 87 from message queue

2020/03/20 11:37:37.443 ImageEventHandler::OnImageEvent sending uniqueId=88

2020/03/20 11:37:37.443 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 11:37:37.445 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 11:37:37.546 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 11:37:37.557 ImageEventHandler::OnImageEvent sending uniqueId=89

2020/03/20 11:37:37.558 ADSpinnaker::grabImage received uniqueID 89 from message queue

2020/03/20 11:37:37.672 ImageEventHandler::OnImageEvent sending uniqueId=90

2020/03/20 11:37:37.672 ADSpinnaker::grabImage received uniqueID 90 from message queue

2020/03/20 11:37:37.784 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 11:37:37.787 ImageEventHandler::OnImageEvent sending uniqueId=91

2020/03/20 11:37:37.787 ADSpinnaker::grabImage received uniqueID 91 from message queue

 

Messages with UniqueID 85, 86, and 87 were received fine.  When reading messages 85 and 87 there was no timeout, but when reading 86 there was a timeout.  However,  0.001 second after that timeout the receive succeeded.

 

The problem is message 88.

 

2020/03/20 11:37:37.443 ImageEventHandler::OnImageEvent sending uniqueId=88

2020/03/20 11:37:37.443 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 11:37:37.445 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 11:37:37.546 ADSpinnaker::grabImage timeout receiving from message queue

2020/03/20 11:37:37.557 ImageEventHandler::OnImageEvent sending uniqueId=89

2020/03/20 11:37:37.558 ADSpinnaker::grabImage received uniqueID 89 from message queue

 

Note that it was sent at 37.443.  There were then 3 timeouts trying to read that message, at 37.443, 37.445, and 37.546.  Message 88 was never received!

 

Something seems seriously wrong here.  It is making me wonder if this is related to the problem with epicsTimeMonotonic that I observed with callbackRequestDelay and Andrew observed with epicsEventWaitWithTimeout?  What could cause that message #88 to never be received from the message queue?  Why are there 2 timeouts within 0.002 seconds, when the timeout is 0.1 second?

 

Thanks,

Mark

 

 

 

From: Mark Rivers
Sent: Friday, March 20, 2020 9:52 AM
To: core-talk at aps.anl.gov
Subject: C++ question

 

Folks,

 

I am having a problem with the areaDetector ADSpinnaker driver.  I am quite sure the problem is that I am doing something wrong in my C++ callback code.

 

The code in question is quite simple.

 

The following is a class that implements callbacks from the vendor library when a new image is available.  It inherits from the vendor’s ImageEvent class, and implments a method they define called OnImageEvent.  That method is passed a smart pointer of type ImagePtr.  I made a copy of that smart pointer and pass its address on an epicsMessageQueue.  The copy is deleted in the receiving function.

 

***************************************

class ImageEventHandler : public ImageEvent

{

public:

 

    ImageEventHandler(epicsMessageQueue *pMsgQ)

     : pMsgQ_(pMsgQ)

    {}

    ~ImageEventHandler() {}

 

    void OnImageEvent(ImagePtr image) {

        ImagePtr *imagePtrAddr = new ImagePtr(image);

 

        if (pMsgQ_->send(&imagePtrAddr, sizeof(imagePtrAddr)) != 0) {

            printf("OnImageEvent error calling pMsgQ_->send()\n");

        }

    }

 

private:

    epicsMessageQueue *pMsgQ_;

 

};

***************************************

 

This is the receiving function.

 

***************************************

asynStatus ADSpinnaker::grabImage()

{

    asynStatus status = asynSuccess;

    size_t nRows, nCols;

    NDDataType_t dataType;

    NDColorMode_t colorMode;

    int timeStampMode;

    int uniqueIdMode;

    int convertPixelFormat;

    bool imageConverted = false;

    int numColors;

    size_t dims[3];

    ImageStatus imageStatus;

    PixelFormatEnums pixelFormat;

    int pixelSize;

    size_t dataSize, dataSizePG;

    void *pData;

    int nDims;

    ImagePtr pImage;

    ImagePtr *imagePtrAddr=0;

    static const char *functionName = "grabImage";

 

    try {

        while(1) {

            unlock();

            int recvSize = pCallbackMsgQ_->receive(&imagePtrAddr, sizeof(imagePtrAddr), 0.1);

            lock();

            if (recvSize == sizeof(imagePtrAddr)) {

                break;

            } else if (recvSize == -1) {

                // Timeout

                int acquire;

                getIntegerParam(ADAcquire, &acquire);

                if (acquire == 0) {

                    return asynError;

                } else {

                    continue;

                }

            } else {

                asynPrint(pasynUserSelf, ASYN_TRACE_ERROR,

                        "%s::%s error receiving from message queue\n",

                        driverName, functionName);

                return asynError;

            }

        }

        pImage = *imagePtrAddr;

        // Delete the ImagePtr that was passed to us

        delete imagePtrAddr;

…

Finishing processing pImage …

***************************************

 

Note that I have a timeout of 0.1 second on the msgQ->receive() call.  if the call times out it tries again if it is still acquiring.  This allows the function to return quickly if acquisition is stopped after it is called.

 

This code generally works fine when the time between images is 0.1 second or less, or 0.12 seconds or more.  However, if the time between images is 0.115 seconds, for example, I “lose” about 2-3% of the images.  There are no error messages.  If I increase the 0.1 second timeout to 0.2 seconds, then images are lost if the time between images is about 0.215 seconds. 

 

It seems to me that the problem must be that another callback happens before the previous image has been processed.  I thought that making a copy of the smart pointer on the stack would prevent this, but I must be doing something wrong.  Perhaps I am deleting the smart pointer too soon, or perhaps the whole approach I am using is unsafe?

 

Any advice is much appreciated!

 

Thanks,

Mark

 

#include <stdio.h>
#include <stdlib.h>
#include <epicsThread.h>
#include <epicsMessageQueue.h>
#include <asynDriver.h>

#define TIMEOUT 0.1
#define MAX_MESSAGES 10

epicsMessageQueueId msgQId;
asynUser *pasynUser;
int numReceived;

void messageTask(void *parg)
{
  int recvSize;
  int value;
  while (1) {
    recvSize = epicsMessageQueueReceiveWithTimeout(msgQId, &value, sizeof(value), TIMEOUT);
    if (recvSize == sizeof(value)) {
      asynPrint(pasynUser, ASYN_TRACE_ERROR, "received value=%d\n", value);
      numReceived++;
    }
    else if (recvSize == -1) {
      asynPrint(pasynUser, ASYN_TRACE_ERROR, "receive timeout\n");
    }
    else {
      asynPrint(pasynUser, ASYN_TRACE_ERROR, "error calling epicsMessageQueueReceiveWithTimeout\n");
    }
  }
}

int main(int argc, char *argv[]) {
  
  int numLoops = atoi(argv[1]);
  double delayTime = atof(argv[2]);
  int i;
  int status;
  int numSent=0;

  pasynUser = pasynManager->createAsynUser(NULL, NULL);
  printf("numLoops=%d, delayTime=%f\n", numLoops, delayTime);
  msgQId = epicsMessageQueueCreate(MAX_MESSAGES, sizeof(int));
  epicsThreadCreate("messageThread",
                    epicsThreadPriorityMedium,
                    epicsThreadGetStackSize(epicsThreadStackMedium),
                    (EPICSTHREADFUNC)messageTask,
                    NULL);

  numReceived = 0;
  for (i=0; i<numLoops; i++) {
    epicsThreadSleep(delayTime);
    status = epicsMessageQueueSend(msgQId, &i, sizeof(i));
    if (status) {
      asynPrint(pasynUser, ASYN_TRACE_ERROR, "error calling epicsMessageQueueSend\n");
      break;
    }
    asynPrint(pasynUser, ASYN_TRACE_ERROR, "    sent value=%d\n", i);
    numSent++;
  }
  
  epicsThreadSleep(1.0);  /* Let messageTask thread process any remaining messages */
  printf("Loops=%d, numSent=%d, numReceived=%d\n", numLoops, numSent, numReceived);
  return 0;
}