Re: Bug in epicsMessageQueue?

[Michael Davidsaver via Core-talk <core-talk at aps.anl.gov>]

From a very quick glance, you might start looking
on the receive side.  What is visible as
epicsMessageQueueReceiveWithTimeout()
returns -1 for conditions other than timeout.

https://github.com/epics-base/epics-base/blob/25bb966cbc4be1f2a47116a8b9ec940bc2270b12/modules/libcom/src/osi/os/default/osdMessageQueue.cpp#L355-L358


On 3/20/20 1:56 PM, Mark Rivers via Core-talk wrote:
> 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 <mailto: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 <mailto: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
> 
>  
>