b3132 SemaphoreFullException

[freddie]

Just had the following exception 5 minutes after upgrading to b3132:

Code: Select all

2021-05-22 08:35:01.038 Realtime[128]: MySQL 1 rows were affected.
2021-05-22 08:35:01.038 Realtime[128]: MySQL executing - DELETE IGNORE FROM Realtime WHERE LogDateTime < DATE_SUB('2021-05-22 08:34:59', INTERVAL 2 DAY);
2021-05-22 08:35:01.039 DoLogFile: MySQL 1 rows were affected.
2021-05-22 08:35:01.755 Realtime[129]: Start cycle
2021-05-22 08:35:01.755 Realtime[129]: Creating realtime.txt
2021-05-22 08:35:01.756 Realtime[129]: Processing realtime file - realtimegauges.txt
2021-05-22 08:35:01.757 Realtime[129]: Processing extra file[0] - /home/install/CumulusMX/web-local/cumulusT.xml
2021-05-22 08:35:01.758 Realtime[129]: Copying extra file[0] /home/install/CumulusMX/web-local/cumulusT.xmltmp to /var/www/weather/cumulus.xml
2021-05-22 08:35:01.758 Realtime[129]: Processing extra file[1] - /home/install/CumulusMX/web-local/realtimeT.xml
2021-05-22 08:35:01.763 Realtime[129]: Copying extra file[1] /home/install/CumulusMX/web-local/realtimeT.xmltmp to /var/www/weather/realtime.xml
2021-05-22 08:35:01.763 Realtime[129]: Processing extra file[2] - /home/install/CumulusMX/web-local/realtimegaugesT.txt
2021-05-22 08:35:01.766 Realtime[129]: Copying extra file[2] /home/install/CumulusMX/web-local/realtimegaugesT.txttmp to /var/www/weather/realtimegauges.txt
2021-05-22 08:35:01.766 Realtime[129]: Processing extra file[11] - /home/install/CumulusMX/web-local/realtime2T.txt
2021-05-22 08:35:01.768 Realtime[129]: Copying extra file[11] /home/install/CumulusMX/web-local/realtime2T.txttmp to /var/www/weather/realtime.txt
2021-05-22 08:35:01.770 Realtime[129]: Opening MySQL Connection
2021-05-22 08:35:01.773 Realtime[129]: Error encountered during MySQL operation.
2021-05-22 08:35:01.774 Cannot Open when State is Open.
2021-05-22 08:35:01.799 Realtime[129]: End cycle
!!! Unhandled Exception !!!
System.Threading.SemaphoreFullException: Adding the specified count to the semaphore would cause it to exceed its maximum count.
  at System.Threading.SemaphoreSlim.Release (System.Int32 releaseCount) [0x0004c] in <a17fa1457c5d44f2885ac746c1764ea5>:0
  at System.Threading.SemaphoreSlim.Release () [0x00000] in <a17fa1457c5d44f2885ac746c1764ea5>:0
  at System.Net.Sockets.SocketAsyncResult.Complete () [0x000c0] in <4e15bbae9d7043d8afd6cfd50bd9bd5a>:0
  at System.Net.Sockets.SocketAsyncResult.Complete (System.Int32 total) [0x00007] in <4e15bbae9d7043d8afd6cfd50bd9bd5a>:0
  at System.Net.Sockets.Socket+<>c.<.cctor>b__366_11 (System.IOAsyncResult ares) [0x0007c] in <4e15bbae9d7043d8afd6cfd50bd9bd5a>:0
  at System.IOSelectorJob.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem () [0x00000] in <4e15bbae9d7043d8afd6cfd50bd9bd5a>:0
  at System.Threading.ThreadPoolWorkQueue.Dispatch () [0x00074] in <a17fa1457c5d44f2885ac746c1764ea5>:0
  at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback () [0x00000] in <a17fa1457c5d44f2885ac746c1764ea5>:0
2021-05-22 08:35:02.196 LOOP: Data - 32: 4C-4F-4F-3C-00-E1-03-BB-73-7E-02-38-D9-01-03-07-15-01-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-FF-54-FF-FF-FF-FF-FF-FF-FF-00-00-FF-FF-7F-2D-00-15-5A-00-00-77-01-89-05-00-00-00-00-1C-00-FF-FF-FF-FF-FF-FF-FF-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-20-03-08-78-95-01-DC-07-0A-0D-EA-BE
2021-05-22 08:35:02.196 LOOP: 32 - Data packet is good

This caused the program to stop. I have just restarted it.

EDIT: this exception kept being thrown - typically around 20 seconds after the web update interval (mine is set to 5 minutes). It didn't occur every time - on a couple of occasions the program ran for about 16-17 minutes, so managed to successfully process three web updates before failing on the 4th one. Note that the problem seems connected to MySQL updates, as it seems to occur when a database connection is opened (according to the stack trace), but database connections occur at the realtime interval (2 seconds) - but confusingly only seemed to occur when a web update had just finished.

I have rolled back to b3122.

[mcrossley]

Thanks for the report!

It looks like people have been battling this issue since 2007, the problem is related to running the MySQL connection on a separate thread to where it was created.
But it also seems to be related to a MySQL database setting as well.

I cannot reproduce the problem with my database using 2 second realtime and 1 minute update intervals

The safest way out of this is to create a new sql connector for every update rather than reusing one as it does now. I'll have a look at what the possible performance impact of this would be.

If need be I'll switch back to running the MySQL synchronously.

[freddie]

Thanks for taking a look, Mark. Which mysql setting is it related to? Perhaps I can do some experimenting?

[mcrossley]

I don't recall off the top of my head, but I did a test earlier. And creating a new connection object every time you want connect to the database rather than reusing the same object is actually faster! Significantly faster on my test system, 7ms rather than 32ms. Who would have thought it.

[freddie]

Unlike Oracle, haha. Yep I have heard that before about MySQL. It's the recommended way for PHP too - i.e. don't pool connections, just create when needed.

[mcrossley]

I have a test build available using the create on demand, could you try it out?

[freddie]

Yes, no problem.