Java Garbage Collector unloading python package classes

Boing · Post by **Boing** » 19 Mar 2010, 12:04

We noticed that the Smartfox Server for our (action) game seems to halt every now and then for 2-5 seconds causing ugly delays for all players.
By turning on garbage collector logging we found out that these lags occur when a full garbage collection is done, mostly dealing with unloading about 1000 (dynamic?) python package classes.

We don't do anything with python. What is it?
Can we turn that off somehow?

Code: Select all

INFO   | jvm 1    | 2010/03/19 12:10:12 | 864 DEBUG [Loop_UserLevelLive-11124-1268941876660] GameLoop.handleSeriesExit (860): Zahma the Hedgehogg (null) just completed user level UserSeries-11124-1268941876660 (Leichte Checkpoints2)
INFO   | jvm 1    | 2010/03/19 12:10:13 | 9381.844: [GC [PSYoungGen: 125744K->528K(121920K)] 1057133K->932061K(1054016K), 0.0128690 secs] [Times: user=0.04 sys=0.00, real=0.01 secs]
INFO   | jvm 1    | 2010/03/19 12:10:13 | 682 DEBUG [ExtensionHandler-1] MainZoneExtension.saveUserSeriesRating (820): haka (null) rated series UserSeries-20866-1268923266034 (Ultimate) with 5 (old rating was null)
INFO   | jvm 1    | 2010/03/19 12:10:13 | 9382.310: [GC [PSYoungGen: 121872K->96K(145792K)] 1053405K->931869K(1077888K), 0.0148910 secs] [Times: user=0.04 sys=0.01, real=0.02 secs]
INFO   | jvm 1    | 2010/03/19 12:10:13 | 9382.325: [Full GC
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx568]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx410]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx317]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx511]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx491]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx514]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx365]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx117]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx15]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx135]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx318]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx162]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx876]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx380]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class sun.reflect.GeneratedConstructorAccessor22]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx963]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx555]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx19]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx967]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx826]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx697]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx211]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx51]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx112]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx669]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx1018]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class sun.reflect.GeneratedConstructorAccessor9]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class sun.reflect.GeneratedConstructorAccessor18]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx828]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx844]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx584]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx87]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx777]

[lots more...]

INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx595]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx589]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx388]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx806]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx348]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx314]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx295]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx810]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx415]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx86]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx578]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx485]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx49]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class registry$py]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx706]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx445]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx754]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx839]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx546]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx302]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx153]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx1040]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx888]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx650]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx576]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx29]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx336]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx98]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx937]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx885]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx747]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx9]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx886]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx737]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx728]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx721]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx672]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx494]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx274]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx943]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class sun.reflect.GeneratedMethodAccessor6]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx6]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx982]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx499]
INFO   | jvm 1    | 2010/03/19 12:10:14 | [Unloading class org.python.pycode._pyx225]
INFO   | jvm 1    | 2010/03/19 12:10:16 |  [PSYoungGen: 96K->0K(145792K)] [PSOldGen: 931773K->597087K(932096K)] 931869K->597087K(1077888K) [PSPermGen: 42142K->42142K(65536K)], 2.2992350 secs] [Times: user=2.29 sys=0.00, real=2.30 secs]
INFO   | jvm 1    | 2010/03/19 12:10:16 | 144 WARN  [Loop_Taygete_6_1] GameLoop.run (419): millisSinceLastUpdate: 2370, lastSleepTime: 50

Post by **Lapo** » 19 Mar 2010, 16:12

Interesting, but I have no clue.
Maybe you have some other Zones active (the default SFS example ones?) and someone is banging them with requests?

I have really have no other ideas besides this one, if you really are not doing anything in python.
The next thing to do would be to plug in a VisualVM and see what is creating Python object, but before that make sure that you don't have "garbage" Zones and maybe even eliminate the webserver example webapps.

lomriilod · Post by **lomriilod** » 06 Sep 2010, 08:26

Was there a solution for this problem? Because we are experiencing the same thing right now.

Thanks.

Dirk

Post by **Lapo** » 06 Sep 2010, 12:35

You can experiment with various GC algorithms provided with the JVM. The concurrent/parallel GC might help here.

See here:
http://www.oracle.com/technetwork/java/ ... 38395.html
(Section 5.4)
and a few comments here:
http://stackoverflow.com/questions/2203 ... 409#220409

lomriilod · Post by **lomriilod** » 06 Sep 2010, 12:51

Thanks for your answer. Intreresting topics. But I ment, that we have exactly the same problem: not running any phyton extensions and massive garbadge collection of phyton classes.

We know deleted the webapps like you suggested. But I was wondering if that helped in the above case.

Dirk

Post by **Lapo** » 06 Sep 2010, 14:28

Unfortunately my response remains along the lines of what I already said...
you should check your runtime memory allocations with VisualVM and check what's going on with these Python objects.

lomriilod · Post by **lomriilod** » 07 Sep 2010, 09:43

Ok, we will do so.

Thanks.

Tristan · Post by **Tristan** » 17 Sep 2010, 09:28

Hello,

I encounter the same kind of problem; the server create and never remove the references on python code.

I don't use at all python extensions I use only java extensions. The only other running extension is "$dmn". I spent lot of effort to have thousand connected users with very few memory usage (less than 200 MB). Unfortunately there are still memory used by Python classes.

Is there a way to disable at all python ? Looking at the code python core initialization seems to be hard coded, perhaps I miss something ?

Thanks for your help.

Post by **Lapo** » 17 Sep 2010, 12:10

Can you quantify the memory that seems to be used by Python?
Is it heap memory?

What SmartFoxServer do you use?

Did you remove all the example Zones from the config?
If not maybe some of them is using Python code.

Anyways in general Python is used for various tasks including dynamic web pages, the BlueBox admintool etc... so it's pretty normal to find Python objects in memory here and there.

According to what you say it seems that these Python objects are affecting your memory stats significantly. Can you provide any numbers?

Tristan · Post by **Tristan** » 17 Sep 2010, 12:40

I use smartfox pro 1.6.9

My server config file contains only my java extensions (I also removed from the Server directory all sample extensions; my Server directory contains only mandatories file and libs). I can confirm with the admin tool, only my zones are loaded and the extension tab is empty.

Here is the retained memory that I can see with VisualVM (It's only heap memory, it come from a Heap Dump):

Code: Select all

Class Name                                                Retained Size

org.python.core.SysPackageManager#1                           1 946 398
org.python.core.PyJavaPackage#14                              1 790 280
org.python.core.PyStringMap#63                                1 789 922
org.python.core.PyObject[]#104                                1 789 044
sun.misc.Launcher$AppClassLoader#1                            1 663 936
java.util.Vector#62                                           1 412 425
java.lang.Object[]#1428                                       1 412 389
org.python.core.PyJavaPackage#654                             1 002 196
org.python.core.PyStringMap#1385                              1 001 916
org.python.core.PyObject[]#1474                               1 001 434
org.python.core.PyJavaPackage#826                               827 496
org.python.core.PyStringMap#1734                                827 142
org.python.core.PyObject[]#1847                                 826 208
org.python.core.PyJavaPackage#15                                656 267
org.python.core.PyStringMap#64                                  655 987
org.python.core.PyObject[]#105                                  654 459
class org.springframework.beans.CachedIntrospectionResults      554 884
java.util.Collections$SynchronizedMap#17                        554 612
java.util.WeakHashMap#32                                        554 556
java.util.WeakHashMap$Entry[]#41                                554 428

Post by **Lapo** » 18 Sep 2010, 09:14

Well, yes if I run an Heap Dump I can slso see various dozens of Python classes in memory. I still don't understand where the problem is exactly. Since Python is used by the server for several tasks you will find related Objects in memory.

Are you having any specific memory problem with your server instance that can be tracked back to excessive instantiation of Python objects?

Tristan · Post by **Tristan** » 20 Sep 2010, 07:10

No I don't have any specific issue with those objects. But I thought that python was used only for python extension.

If the server needs python for it's own tasks, it's normal.

Thank you for your answer.