B4J Question Fine tuning of Garbage Collector?

[vfafou]

Hello!
My web socket server application with MySQL database connection pooling, seems that something needs about garbage collection (or there is a memory leak???).
The Java Visual VM shows the following data:

Morning (1):

Live Threads: ~1120
Used Heap: ~850MB before GC, ~140MB after GC
Total Started Threads: ~1700

Evening (2):

Live Threads: ~980
Used Heap: ~1.1GB before GC, ~210MB after GC
Total Started Threads: ~2300

Night (3):

Live Threads: ~510
Used Heap: ~1.3GB before GC, ~250MB after GC
Total Started Threads: ~2900

Pressing the Perform (full) GC button, the night's data are (4):

Live Threads: ~510
Used Heap: ~230MB
Total Started Threads: ~2900

Stopping and starting the server application after (4):

Live Threads: ~226
Used Heap: ~880MB before GC, ~47MB after GC
Total Started Threads: ~247

I'm starting the server with:

java -Xms2G -Xmx5G -XX:MaxPermSize=256m -XX:NewRatio=1 -XX:+UseConcMarkSweepGC -verbosegc -jar MyServer.jar

Note that after restarting, the live threads became ~226 instead of ~510.

All database connections are closed after using them.
The most "useless" threads seems that are websocket connections!

My server is a HP proliant with 4core XEON and 16GB RAM, with Ubuntu Linux OS.

Do you think that something goes wrong?

Thank you in advance!

 

[Erel]

Do you eventually get an out of memory error? If not then I think that you should run the JVM with the default parameters.

 

[vfafou]

Hello Erel,
Thank you for your response.
Yes, I eventually get out of memory, after 8-10 days uptime...

 

[Erel]

This means that there is a memory leak. Changing the GC configuration will not help.

You need to take a memory dump and analyze it with a tool such as VisualVM.

 

[vfafou]

I think that my problem is

ws.Session.MaxInactiveInterval = 86400 * 10

Is it a good idea to set this property to 1 hour?

Does the Garbage Collector remove the web socket connections handled by the objects removed from the map?

Update:
I have analyzed the heap dump and I've noticed that the cause of my memory leak is the remaining open websocket threads, as I suspected.
The analysis tool gave me:

One instance of "org.eclipse.jetty.websocket.server.WebSocketServerFactory"loaded by "sun.misc.Launcher$AppClassLoader @ 0x750006720" occupies 55.389.928 (56,56%) bytes. The memory is accumulated in one instance of "java.lang.Object[]" loaded by "<system class loader>".

Keywords
sun.misc.Launcher$AppClassLoader @ 0x750006720
java.lang.Object[]
org.eclipse.jetty.websocket.server.WebSocketServerFactory

The connections remain open when the mobile internet of the device goes down.
I think that when reconnecting, a new websocket connection is created.
What is the best strategy to go with?
If I leave the default ws.Session.MaxInactiveInterval value to 3 hours, will my problem be solved or another problem will be caused?

Thank you in advance.

 

[Erel]

Why did you change it to 10 days?

Try it with the default 3 hours timeout.

 

[vfafou]

I've set it to 10 days at my very early steps to B4X, because I was afraid of forced disconnections from the server (I thought that these connections are something like database connections) but over time I understood how websockets work. However, I forgot to leave the timeout to the default value.
Yesterday night I changed this to 1 hour, I eventually remove the useless connections from ActiveConnections map and now I'm watching the results realtime.
As I noticed by now (after 9.5 hours uptime), I have 271 devices connected at the moment and the live threads are 599... Is it reasonable?

One more notice:
The Active Connections are held within a Map Object.
When a property of a connection is changed, does the connection object stored in the map being updated automatically? I mean when the LastPingTime is changed, the map updates it or I have to replace the connection object programmatically?

 

[Erel]

I have 271 devices connected at the moment and the live threads are 599... Is it reasonable?

Hard to say. Check whether they are released eventually. If not then there is a leak somewhere.

When a property of a connection is changed, does the connection object stored in the map being updated automatically?

Yes. You are storing references to the same object. Make sure to use a thread safe map for any map that is accessed from different threads.

Note that the online server example is running for several months (https://b4x.com:51041/) and the memory usage is constant.

 

[vfafou]

Make sure to use a thread safe map for any map that is accessed from different threads.

Thank you Erel for all your help!
The manipulation of the ActiveConnections map has been kept as you have it implemented with your Custom WebSocket framework.
The new sub I have written for deleting unused connections, is called from NewConnection sub in the PushShared module, which is called from the Device_Id event called from devices with CallSubDelayed. Does this require a thread safe map?

 

[Erel]

Does this require a thread safe map?

Yes.

 

[vfafou]

OK, Erel!
I'll change it to thread safe!

Note that the online server example is running for several months (https://b4x.com:51041/) and the memory usage is constant.

I would like to ask you if you mean the Heap memory or the PermGen memory, because in my case PermGen is always constant but the Heap behaves like I have explained to my 1st post!

 

[Erel]

The overall memory usage is more or less constant. It never crashes. It can run for months.

 

[vfafou]

Hello again, Erel!
I've made a newer heap dump and the results were the following:

Problem Suspect 1
One instance of "org.eclipse.jetty.websocket.server.WebSocketServerFactory" loaded by "sun.misc.Launcher$AppClassLoader @ 0x6c0002488" occupies 76.705.616 (46,63%) bytes. The memory is accumulated in one instance of "java.lang.Object[]" loaded by "<system class loader>".

Keywords
java.lang.Object[]
org.eclipse.jetty.websocket.server.WebSocketServerFactory
sun.misc.Launcher$AppClassLoader @ 0x6c0002488


Problem Suspect 2
5.785 instances of "java.lang.ref.Finalizer", loaded by "<system class loader>"occupy 57.299.056 (34,83%) bytes.

Keywords
java.lang.ref.Finalizer

For the Suspect 1, I've found entries like the following:

Class Name                                                                                               | Shallow Heap | Retained Heap | Percentage
-----------------------------------------------------------------------------------------------------------------------------------------------------
org.eclipse.jetty.websocket.server.WebSocketServerFactory @ 0x6c016e3b8                                  |          112 |    76.705.616 |     46,63%
|- java.util.concurrent.CopyOnWriteArraySet @ 0x6c016e830                                                |           16 |    76.704.432 |     46,63%
|  '- java.util.concurrent.CopyOnWriteArrayList @ 0x6c016e840                                            |           24 |    76.704.416 |     46,63%
|     |- java.lang.Object[7794] @ 0x6c9f61cb0                                                            |       31.192 |    76.704.312 |     46,63%
|     |  |- org.eclipse.jetty.websocket.common.WebSocketSession @ 0x6c35c07a8                            |          120 |        11.752 |      0,01%
|     |  |  |- org.eclipse.jetty.websocket.server.WebSocketServerConnection @ 0x6c35c0c28                |          104 |         3.704 |      0,00%
|     |  |  |  |- org.eclipse.jetty.websocket.common.Parser @ 0x6c35c1098                                |           56 |         1.216 |      0,00%
|     |  |  |  |- org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher @ 0x6c35c1360|           56 |         1.008 |      0,00%
|     |  |  |  |- org.eclipse.jetty.io.SelectChannelEndPoint @ 0x6c35c0cf8                               |          104 |           912 |      0,00%
|     |  |  |  |- org.eclipse.jetty.websocket.common.io.IOState @ 0x6c35c14c8                            |           32 |           152 |      0,00%
|     |  |  |  |- org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Stats @ 0x6c35c1548  |           24 |            96 |      0,00%
|     |  |  |  |- java.util.concurrent.CopyOnWriteArrayList @ 0x6c35c0c90                                |           24 |            88 |      0,00%
|     |  |  |  |  |- java.util.concurrent.locks.ReentrantLock @ 0x6c35c0ca8                              |           16 |            48 |      0,00%
|     |  |  |  |  |  '- java.util.concurrent.locks.ReentrantLock$NonfairSync @ 0x6c35c0cb8               |           32 |            32 |      0,00%
|     |  |  |  |  |- java.lang.Object[0] @ 0x6c35c0cd8                                                   |           16 |            16 |      0,00%
|     |  |  |  |  '- Total: 2 entries                                                                    |              |               |        
|     |  |  |  |- org.eclipse.jetty.websocket.common.Generator @ 0x6c35c1080                             |           24 |            24 |      0,00%
|     |  |  |  |- java.util.ArrayList @ 0x6c35c14b0                                                      |           24 |            24 |      0,00%
|     |  |  |  |- java.util.concurrent.atomic.AtomicReference @ 0x6c35c0ce8                              |           16 |            16 |      0,00%
|     |  |  |  |- org.eclipse.jetty.io.AbstractConnection$ReadCallback @ 0x6c35c0e58                     |           16 |            16 |      0,00%
|     |  |  |  |- org.eclipse.jetty.io.AbstractConnection$1 @ 0x6c35c1070                                |           16 |            16 |      0,00%
|     |  |  |  |- java.util.concurrent.atomic.AtomicBoolean @ 0x6c35c1350                                |           16 |            16 |      0,00%
|     |  |  |  |- java.util.concurrent.atomic.AtomicBoolean @ 0x6c35c15a8                                |           16 |            16 |      0,00%
|     |  |  |  '- Total: 13 entries                                                                      |              |               |        
|     |  |  |- org.eclipse.jetty.websocket.servlet.ServletUpgradeRequest @ 0x6c35c16d8                   |           64 |         3.008 |      0,00%
|     |  |  |- org.eclipse.jetty.websocket.common.extensions.ExtensionStack @ 0x6c35c10e8                |           88 |         2.896 |      0,00%
|     |  |  |- org.eclipse.jetty.websocket.servlet.ServletUpgradeResponse @ 0x6c35c21b0                  |           40 |           640 |      0,00%
|     |  |  |- java.net.URI @ 0x6c35c0938                                                                |           80 |           528 |      0,00%
|     |  |  |- org.eclipse.jetty.websocket.common.WebSocketRemoteEndpoint @ 0x6c35c1618                  |           32 |           192 |      0,00%
|     |  |  |- org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver @ 0x6c35c0b90          |           40 |           160 |      0,00%
|     |  |  |- java.util.concurrent.CopyOnWriteArrayList @ 0x6c35c0820                                   |           24 |            88 |      0,00%
|     |  |  |- java.util.concurrent.CopyOnWriteArrayList @ 0x6c35c0888                                   |           24 |            88 |      0,00%
|     |  |  |- java.util.concurrent.CopyOnWriteArrayList @ 0x6c35c08e0                                   |           24 |            88 |      0,00%
|     |  |  |  |- java.util.concurrent.locks.ReentrantLock @ 0x6c35c08f8                                 |           16 |            48 |      0,00%
|     |  |  |  |  '- java.util.concurrent.locks.ReentrantLock$NonfairSync @ 0x6c35c0908                  |           32 |            32 |      0,00%
|     |  |  |  |- java.lang.Object[0] @ 0x6c35c0928                                                      |           16 |            16 |      0,00%
|     |  |  |  '- Total: 2 entries                                                                       |              |               |        
|     |  |  |- java.lang.String @ 0x6c35c0a08  108.151.36.224                                            |           24 |            72 |      0,00%
|     |  |  |  '- char[14] @ 0x6c35c0a20  108.151.36.224                                                 |           48 |            48 |      0,00%
|     |  |  |- org.eclipse.jetty.websocket.api.WebSocketPolicy @ 0x6c35c0bb8                             |           56 |            56 |      0,00%
|     |  |  |- java.lang.String @ 0x6c35c15b8  13                                                        |           24 |            48 |      0,00%
|     |  |  |  '- char[2] @ 0x6c35c15d0  13                                                              |           24 |            24 |      0,00%
|     |  |  |- java.util.HashMap @ 0x6c35c15e8                                                           |           48 |            48 |      0,00%
|     |  |  |- java.lang.Object @ 0x6c35c0878                                                            |           16 |            16 |      0,00%
|     |  |  '- Total: 15 entries                                                                         |              |               |        
-----------------------------------------------------------------------------------------------------------------------------------------------------

For the Suspect 2, I've done a quick pass and I found that the finalizer is used from (~34000) objects like:

Class Name                                                          | Shallow Heap | Retained Heap | Percentage
----------------------------------------------------------------------------------------------------------------
java.lang.ref.Finalizer @ 0x6c8c55ad0                               |           40 |        45.176 |      0,03%
'- com.mysql.jdbc.Connection @ 0x6c8c798d8                          |          912 |        45.136 |      0,03%
   |- java.util.HashMap @ 0x6c8c7e6c0                               |           48 |        24.192 |      0,01%
   |  '- java.util.HashMap$Entry[256] @ 0x6c8c7e6f0                 |        1.040 |        24.144 |      0,01%
   |     |- java.util.HashMap$Entry @ 0x6c8c7f820                   |           32 |           640 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c7ff20                   |           32 |           568 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c7f260                   |           32 |           512 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c82d18                   |           32 |           496 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c81e10                   |           32 |           488 |      0,00%
   |     |  |- java.util.HashMap$Entry @ 0x6c8c81ed0                |           32 |           296 |      0,00%
   |     |  |  |- java.util.HashMap$Entry @ 0x6c8c81f50             |           32 |           168 |      0,00%
   |     |  |  |- java.lang.String @ 0x6c8c81ef0  new               |           24 |            48 |      0,00%
   |     |  |  |- java.lang.String @ 0x6c8c81f20  OFF               |           24 |            48 |      0,00%
   |     |  |  '- Total: 3 entries                                  |              |               |     
   |     |  |- java.lang.String @ 0x6c8c81e78  Official MySQL binary|           24 |            88 |      0,00%
   |     |  |- java.lang.String @ 0x6c8c81e30  version_comment      |           24 |            72 |      0,00%
   |     |  '- Total: 3 entries                                     |              |               |     
   |     |- java.util.HashMap$Entry @ 0x6c8c81a40                   |           32 |           480 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c82138                   |           32 |           456 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c83170                   |           32 |           456 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c7ee28                   |           32 |           448 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c83b30                   |           32 |           360 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c81148                   |           32 |           336 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c82958                   |           32 |           336 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c833d8                   |           32 |           336 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c83528                   |           32 |           328 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c83c98                   |           32 |           328 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c7eba8                   |           32 |           320 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c7ece8                   |           32 |           320 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c81c20                   |           32 |           320 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c81ff8                   |           32 |           320 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c82f08                   |           32 |           320 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c84210                   |           32 |           320 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c80158                   |           32 |           312 |      0,00%
   |     |  |- java.util.HashMap$Entry @ 0x6c8c801f8                |           32 |           152 |      0,00%
   |     |  |  |- java.lang.String @ 0x6c8c80218  log_slow_queries  |           24 |            72 |      0,00%
   |     |  |  |  '- char[16] @ 0x6c8c80230  log_slow_queries       |           48 |            48 |      0,00%
   |     |  |  |- java.lang.String @ 0x6c8c80260  OFF               |           24 |            48 |      0,00%
   |     |  |  '- Total: 2 entries                                  |              |               |     
   |     |  |- java.lang.String @ 0x6c8c80178  large_files_support  |           24 |            80 |      0,00%
   |     |  |- java.lang.String @ 0x6c8c801c8  ON                   |           24 |            48 |      0,00%
   |     |  '- Total: 3 entries                                     |              |               |     
   |     |- java.util.HashMap$Entry @ 0x6c8c80778                   |           32 |           312 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c826d8                   |           32 |           312 |      0,00%
   |     |- java.util.HashMap$Entry @ 0x6c8c80948                   |           32 |           304 |      0,00%
----------------------------------------------------------------------------------------------------------------

Almost all of 34000 objects refer to mysql jdbc library.

What all the above results from analyzer mean?
Is there something I can do?

What does it mean "One instance of org.eclipse.jetty.websocket.server.WebSocketServerFactory"?
One thread or a bunch of threads?

Could you suggest me a good method to find where the memory leak is?
I've searched the internet and I can't find any specific methodology!

Thank you in advance!

 

[Erel]

How did you configure the connection pool?

 

[vfafou]

The connection pool configuration is:

Private jo As JavaObject = Pool
jo.RunMethod("setMinPoolSize", Array As Object(30))
jo.RunMethod("setInitialPoolSize", Array As Object(30))
jo.RunMethod("setMaxPoolSize", Array As Object(1012))
jo.RunMethod("setMaxIdleTime", Array As Object(90))
jo.RunMethod("setMaxIdleTimeExcessConnections", Array As Object(80))
jo.RunMethod("setAcquireRetryAttempts", Array As Object(50))
jo.RunMethod("setAcquireRetryDelay", Array As Object(2000))
jo.RunMethod("setPreferredTestQuery", Array As Object("Select 1"))
jo.RunMethod("setTestConnectionOnCheckout", Array As Object(False))
jo.RunMethod("setTestConnectionOnCheckin", Array As Object(True))
jo.RunMethod("setIdleConnectionTestPeriod", Array As Object(60))
jo.RunMethod("setMaxStatements", Array As Object(8))

Is it right to think that the jdbc behavior prevents the invalidation/garbage collection of the websocket threads?

 

[dar2o3]

Your problem may have something to do with this thread?
https://www.b4x.com/android/forum/threads/solved-connectionpool-maxpoolsize-issue.61096/#post-399261

 

[Erel]

Try it with the default settings.

 

[vfafou]

@dar2o3
Thank you for your reply! I already assign the connection to a variable, so this is not the problem!

@Erel
OK, but I think I need to set jo.RunMethod("setMaxPoolSize", ArrayAs Object(1012)), because I already have noticed that the status variable max_used_connections of MySQL have a value of 527 and every month increasing by ~12.

Update:
I have the server running for ~2 hours, after the changes I did, like leaving the defaults of DB pool connections (except maxconnections that I set it to 620 instead of 1012) etc.
I took a heap dump and I found some strange things into the classes analyser like:

You are checking a non-c3p0 PooledConnection implementation intoa c3p0 PooledConnectionPool instance that expects only c3p0-generated PooledConnections.This isn't good, and may indicate a c3p0 bug, or an unusual (and unspported) use of the c3p0 library.

c3p0 -- Uh oh... getConnection() was called on a PooledConnection when it had already provided a client with a Connection that has not yet been closed. This probably indicates a bug in the connection pool!!!

public synchronized void com.mchange.v2.c3p0.impl.WrapperConnectionPoolDataSourceBase.setConnectionTesterClassName(java.lang.String) throws java.beans.PropertyVetoException

public javax.sql.PooledConnection com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(java.lang.String,java.lang.String) throws java.sql.SQLException

A client attempted to work with a closed Statement cache, provoking a NullPointerException. c3p0 recovers, but this should be rare.

PreparedStatement created, but used 1 or fewer times. It is more efficient to prepare statements once, and re-use them many times

Apparently all replaced threads have either completed their tasks or been interrupted(). Replacement thread processing cancelled.

All of them are in the char or string class!
What do they mean all of them?

 

[jmon]

Did you make sure all your pool connections are properly closed each time you use them?

you can also try debugging your application with Visual VM:
https://docs.oracle.com/javase/8/docs/technotes/guides/troubleshoot/memleaks001.html
and

[edit] I just noticed that the dump you created are from VISUAL VM... ... forget that I suggested using visual vm...

 

[vfafou]

Did you make sure all your pool connections are properly closed each time you use them?

Hello jmon!
Thank you for your response!
I have passed at least 6 times my code and I have corrected some issues relative to the DB connections closing.
However, I see many connections to the database that are open and idle...
The MariaDB setting for connection handling is pool_of_threads.
I can't figure out what is wrong!

The following code samples are from my app (WebSocket Class PushB4A). All Subs with an underscore, are events called from devices:
Sample 1:

Try
     Private OSQL As SQL = Main.oPool.GetConnection
     MemberRow = DBUtils.ExecuteMap(OSQL,SQLQuery,Array As String(ExID))
     OSQL.Close
     MembID = MemberRow.Get("cd_exchg")
Catch
     OSQL.Close
     Log("Error Exchg: " & LastException.Message)
End Try

Sample 2:

Try
    id       = NZData.Get("id")
    NQStr = NZData.Get("NZStr")
 
    Private PSQL As SQL = Main.Pool.GetConnection
 
    If NQStr = "0" Or NQStr.Length = 0 Then
        c_zone = PSQL.ExecQuery2("select zone_id,zone_st_count from zones where zone_id < 80 order by zone_id asc", Null)
    Else
        If NQStr.Length > 0 Then
            c_zone = PSQL.ExecQuery2("select z.zone_id,z.zone_st_count from zones z where z.zone_id < 80 and find_in_set(z.zone_id,(Select near_zones from zones where zone_id = ?)) > 0 order by zone_id asc", Array As String(NQStr))
        End If
    End If
 
    If NQStr.Length > 0 Then
        Do While c_zone.NextRow
            dZone  = c_zone.GetInt2(0)
            dQueue = c_zone.GetInt2(1)
         
            ZQStr = ZQStr & dZone & ":" & dQueue & "#"
         
        Loop
        c_zone.Close
     
        If ZQStr.Length > 0 Then
            ZQStr = Str.Left(ZQStr,ZQStr.Length-1)
        End If
     
        If NQStr = "0" Then
            CallSubDelayed3(PushShared, "SendDirectMessage","ZR;" & ZQStr, id)
        Else
            CallSubDelayed3(PushShared, "SendDirectMessage","NZ;" & ZQStr, id)
        End If
     
    Else
        Try
            c_zone.Close
        Catch
            PSQL.Close
            Log("Error c_zone")
            Return
        End Try
    End If
    PSQL.Close
Catch
    PSQL.Close
    Return
End Try

Sample 3:

Public Sub Check_Illegal(ooData As Map)
   Dim rStatus  As String
   Dim rIllegal  As String
   Dim SQLSelect As String
 
   Try
     Private PSQL As SQL = Main.Pool.GetConnection
     id  = ooData.Get("id")
     rStatus  = ooData.Get("rStatus")
     rIllegal = ooData.Get("rIllegal")
   
     SQLSelect = "UPDATE rusers SET rdev = ?, illegal = ? WHERE id_device = ?"
 
     PSQL.BeginTransaction
     PSQL.ExecNonQuery2(SQLSelect,Array As String(rStatus,rIllegal,id))
     PSQL.TransactionSuccessful
     PSQL.close
   Catch
     PSQL.Rollback
     PSQL.Close
     Log("Error Ev_Illegal")
   End Try
 
End Sub

Sample 4:

Public Sub Accept_Cl(ACData As Map)
   Try
     Private PSQL As SQL = Main.Pool.GetConnection
     Private OSQL As SQL = Main.oPool.GetConnection
   
     AcceptCl(ACData,PSQL,OSQL) 'This Sub does all the SQL work.
     PSQL.Close
     OSQL.Close
   Catch
     PSQL.Close
     OSQL.Close
     Log("Error Ev_AcceptCl")
   End Try
 
End Sub

Am I missing something?