search

komamitsu / fluency

High throughput data ingestion logger to Fluentd, AWS S3 and Treasure Data
Apache License 2.0
154 stars 33 forks source link

Possible Memory Leak in AsyncFlusher #15

Closed jondoe1337 closed 8 years ago

jondoe1337 commented 8 years ago

We notice a massive amount on recorded objects of the AsynchFlusher while using it as a LoggingAdapter.

We use the 0.0.8 maven artifact for an application that has not more than 10 messages per minute output.

Fluency is constructed using org.komamitsu.fluency.Fluency.defaultFluency(String host, int port) throws IOException

We counted the instances using YourKit:

bildschirmfoto_2016-03-21_17-04-39

komamitsu commented 8 years ago

@jondoe1337 Thanks for reporting it.

10 messages per minute sounds too small to trigger GC and I'd like to see if any young/minor GC has happened in your application. Can I ask you to check it using jstat or something like this?

[komamitsu@potato ~]$ jps
13954 Launcher
19588 Jps
19224 Main
19480 AppMain
19481 Launcher

[komamitsu@potato ~]$ jstat -gc 19480 1s 1000
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
5120.0 5120.0 3888.0  0.0   33280.0  25147.7   87552.0      48.0    13440.0 12934.9 1664.0 1453.5      4    0.036   0      0.000    0.036
5120.0 5120.0 3888.0  0.0   33280.0  25481.4   87552.0      48.0    13440.0 12934.9 1664.0 1453.5      4    0.036   0      0.000    0.036
5120.0 5120.0 3888.0  0.0   33280.0  25481.4   87552.0      48.0    13440.0 12934.9 1664.0 1453.5      4    0.036   0      0.000    0.036
5120.0 5120.0 3888.0  0.0   33280.0  25699.6   87552.0      48.0    13440.0 12934.9 1664.0 1453.5      4    0.036   0      0.000    0.036
  :

# ^ In this case, I want to know the value of YGC and FGC
jondoe1337 commented 8 years ago 
jstat -gc 18416 1s 1000
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
389632.0 379392.0  0.0   359609.3 2733568.0 2477993.9 1399296.0   463578.7  93312.0 91677.7 12416.0 12033.6    175    6.978   5      0.619    7.598
389632.0 379392.0  0.0   359609.3 2733568.0 2477993.9 1399296.0   463578.7  93312.0 91677.7 12416.0 12033.6    175    6.978   5      0.619    7.598
389632.0 379392.0  0.0   359609.3 2733568.0 2477993.9 1399296.0   463578.7  93312.0 91677.7 12416.0 12033.6    175    6.978   5      0.619    7.598
389632.0 379392.0  0.0   359609.3 2733568.0 2477998.0 1399296.0   463578.7  93312.0 91677.7 12416.0 12033.6    175    6.978   5      0.619    7.598
komamitsu commented 8 years ago

@jondoe1337 Thanks. Didn't the heap memory usage decrease when YGC or FGC incremented?

jondoe1337 commented 8 years ago

I think i have to collect the stats for a longer run-time. The stats i posted above where made after a runtime of a little bit more than one hour.

jondoe1337 commented 8 years ago

So here are my stats for the application, jmap -heap + jstat -gc directly after start, after 1 hour and after 4 hours:

Directly after start:

# jmap  -heap 10831
Attaching to process ID 10831, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.45-b02

using thread-local object allocation.
Parallel GC with 13 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 16840130560 (16060.0MB)
   NewSize                  = 350748672 (334.5MB)
   MaxNewSize               = 5613027328 (5353.0MB)
   OldSize                  = 702021632 (669.5MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 263716864 (251.5MB)
   used     = 106284616 (101.36090850830078MB)
   free     = 157432248 (150.13909149169922MB)
   40.302548114632515% used
From Space:
   capacity = 43515904 (41.5MB)
   used     = 12259456 (11.6915283203125MB)
   free     = 31256448 (29.8084716796875MB)
   28.172357398343372% used
To Space:
   capacity = 43515904 (41.5MB)
   used     = 0 (0.0MB)
   free     = 43515904 (41.5MB)
   0.0% used
PS Old Generation
   capacity = 702021632 (669.5MB)
   used     = 98344 (0.09378814697265625MB)
   free     = 701923288 (669.4062118530273MB)
   0.014008685134078604% used

5639 interned Strings occupying 505368 bytes.

# jstat -gc 10831 1s 1000
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
42496.0 42496.0  0.0   11972.1 257536.0 104365.9  685568.0     96.0    17152.0 16470.3 2048.0 1926.9      1    0.022   0      0.000    0.022

After 1 hour:

# jmap  -heap 10831
Attaching to process ID 10831, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.45-b02

using thread-local object allocation.
Parallel GC with 13 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 16840130560 (16060.0MB)
   NewSize                  = 350748672 (334.5MB)
   MaxNewSize               = 5613027328 (5353.0MB)
   OldSize                  = 702021632 (669.5MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 3728736256 (3556.0MB)
   used     = 1067240936 (1017.8002700805664MB)
   free     = 2661495320 (2538.1997299194336MB)
   28.622054839161034% used
From Space:
   capacity = 655360000 (625.0MB)
   used     = 473223248 (451.3008575439453MB)
   free     = 182136752 (173.6991424560547MB)
   72.20813720703126% used
To Space:
   capacity = 659554304 (629.0MB)
   used     = 0 (0.0MB)
   free     = 659554304 (629.0MB)
   0.0% used
PS Old Generation
   capacity = 1249378304 (1191.5MB)
   used     = 508442576 (484.8886260986328MB)
   free     = 740935728 (706.6113739013672MB)
   40.69564633643582% used

25517 interned Strings occupying 2673608 bytes.

# jstat -gc 10831 1s 1000
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
640000.0 644096.0 462132.1  0.0   3641344.0 1042442.4 1220096.0   496526.0  90408.0 88998.1 12328.0 12018.8     46    2.195   4      0.462    2.656

After 4 hours:

# jmap  -heap 10831
Attaching to process ID 10831, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.45-b02

using thread-local object allocation.
Parallel GC with 13 thread(s)

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 16840130560 (16060.0MB)
   NewSize                  = 350748672 (334.5MB)
   MaxNewSize               = 5613027328 (5353.0MB)
   OldSize                  = 702021632 (669.5MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 3464495104 (3304.0MB)
   used     = 3315912728 (3162.3008041381836MB)
   free     = 148582376 (141.6991958618164MB)
   95.71128341822589% used
From Space:
   capacity = 430440448 (410.5MB)
   used     = 276010848 (263.2244567871094MB)
   free     = 154429600 (147.27554321289062MB)
   64.12288837688413% used
To Space:
   capacity = 434634752 (414.5MB)
   used     = 0 (0.0MB)
   free     = 434634752 (414.5MB)
   0.0% used
PS Old Generation
   capacity = 1407713280 (1342.5MB)
   used     = 528180536 (503.7122116088867MB)
   free     = 879532744 (838.7877883911133MB)
   37.520462689674986% used

27026 interned Strings occupying 2826744 bytes.

# jstat -gc 10831 1s 1000
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
420352.0 424448.0 269541.8  0.0   3383296.0 3239586.1 1374720.0   515801.3  94376.0 92460.1 12456.0 12085.8    192    8.297   5      0.699    8.996
komamitsu commented 8 years ago

Thanks. Regarding the result of jmap command 4 hours after starting, the usage of to space, from space and old gen didn't increase while YGC and FGC increased. So it seems that GC reduced the heap memory usage well and memory leak didn't happen.

You may see a memory usage chart like this https://gyazo.com/080e444f95ead2ac6f4d10a8d609362a.png if you monitor the application for a while.

jondoe1337 commented 8 years ago

Oh well. So it seems like a false alarm. Thanks for help.

komamitsu commented 8 years ago

No problem :)