YGC time increasing suddenly
Luciano Molinari
lucmolinari at gmail.com
Thu Dec 19 10:05:43 PST 2013
Hi,
I used thread dump to find out that...I have ~315 threads..
It would be great to read your letter and check if the solution can be
applied to my case.
Thanks.
On Thu, Dec 19, 2013 at 3:26 PM, Мамонтов Иван <ivan.mamontov at gmail.com>wrote:
> I am very interested in the number of created threads since the beginning
> of the application.
> If you use an executor, you can tell a static sequence number, for example
> *coreLoadExecutor-3-thread-3*
>
>
> 2013/12/19 Мамонтов Иван <ivan.mamontov at gmail.com>
>
>> Hi,
>>
>> I had the same problem as you describe, but first I need to know one
>> thing:
>>
>> - How many threads have been created at runtime?
>>
>>
>> I am writing a letter describing the same issue and its solution.
>>
>> 2013/12/19 Luciano Molinari <lucmolinari at gmail.com>
>>
>>> Bernd and Wolfgang, thanks for your quick answers. I took some time to
>>> answer them because I was running some tests based on your comments.
>>>
>>> *Bernd:* I would look at the finalizer queue first.
>>> *A: *From what I could find in the code, it doesn't seem to have
>>> explicit finalizers. Is there any way to check this queue?I found some
>>> articles about the problems finalize() method may cause, but I wasn't able
>>> to find something related to monitoring this queue.
>>>
>>> *Bernd:* And if that does not cut it, take a heapdump and inspect it
>>> for unexpected large dominators (maybe cached softreferences - not
>>> sure about RMI DGC havent seen problems with it, but it sure can be a
>>> problem if it only cleans up once an hour.).
>>> *A:* Regarding RMI, I ran some tests replacing it by JeroMQ but
>>> unfortunately I got the same results. About heapdump, Eclipse MAT shows
>>> almost nothing (only ~50mb) because the majority of objects are unreachable.
>>>
>>> *Bernd:* How often do you see YGC at the beginning and then over time?
>>> It looks like every 2s? You might want to resize YGC by larger
>>> factors (but with the yg already at 4g I guess something else is a
>>> problem here).
>>> *A*: After I start my tests, YGC occurs once or twice every 3 seconds,
>>> as the following log shows:
>>> jstat -gcutil 29331 3000
>>> S0 S1 E O P YGC YGCT FGC FGCT GCT
>>> 1.40 0.00 89.74 2.13 11.86 602 12.126 1 0.086
>>> 12.212
>>> 1.64 0.00 66.92 2.13 11.86 604 12.166 1 0.086
>>> 12.252
>>> 1.38 0.00 41.10 2.13 11.86 606 12.204 1 0.086
>>> 12.290
>>> 1.47 0.00 10.86 2.13 11.86 608 12.244 1 0.086
>>> 12.330
>>> 0.00 1.47 89.35 2.13 11.86 609 12.265 1 0.086
>>> 12.351
>>> 0.00 1.51 62.11 2.13 11.86 611 12.305 1 0.086
>>> 12.391
>>> 0.00 1.38 32.83 2.14 11.86 613 12.346 1 0.086
>>> 12.432
>>> 0.00 0.96 11.06 2.21 11.86 615 12.386 1 0.086
>>> 12.472
>>> 0.97 0.00 72.35 2.22 11.86 616 12.406 1 0.086
>>> 12.492
>>> It keeps this rate during the whole time, the only difference is that
>>> collections start to last longer.
>>>
>>> *Bernd:* You claim that most of the data only lives for 100ms, that
>>> does not match with the age-size distribution (not at the beginning not at
>>> the end).
>>> *A:* I said that for 2 reasons. Firstly, you can see by the log bellow
>>> that most transactions last < 25 ms:
>>>
>>> | interval | number of transactions | % |
>>> |------------------------+---------------------------+-------------------------|
>>> | 0 ms <= n < 25 ms : 7487644 : 97.704
>>> |
>>> | 25 ms <= n < 50 ms : 137146 : 1.790 |
>>> | 50 ms <= n < 75 ms : 26422 : 0.345 |
>>> | 75 ms <= n < 100 ms : 8086 : 0.106
>>> |
>>> | 100 ms <= n < 200 ms : 4081 : 0.053
>>> |
>>> | 200 ms <= n < 500 ms : 216 : 0.003
>>> |
>>> | 500 ms <= n < 1000 ms : 0 : 0.000
>>> |
>>>
>>> And secondly, very few objects are promoted to old gen.
>>>
>>> *Wolfgang*, what you said about survivor also seems to make sense, but
>>> I ran some tests with survivorRation=8 and survivorRation=16 and the
>>> results were pretty much the same.
>>>
>>> I also collected some data using "sar -B" and vmstat commands in order
>>> to try to find out something else.
>>>
>>> sar -B
>>>
>>> 12:58:33 PM pgpgin/s pgpgout/s fault/s majflt/s
>>> 12:58:43 PM 0.00 5.19 16.98 0.00
>>> 12:58:53 PM 0.00 6.80 20.70 0.00
>>> 12:59:03 PM 0.00 12.81 16.72 0.00
>>> 12:59:13 PM 0.00 3.60 17.98 0.00
>>> 12:59:23 PM 0.00 14.81 118.42 0.00
>>> 12:59:33 PM 0.00 11.20 90.70 0.00
>>> 12:59:43 PM 0.00 5.20 662.60 0.00 (here GC started to
>>> take longer)
>>> 12:59:53 PM 0.00 5.20 1313.10 0.00
>>> 01:00:03 PM 0.00 20.42 960.66 0.00
>>> 01:00:13 PM 0.00 17.18 620.78 0.00
>>> 01:00:23 PM 0.00 3.60 725.93 0.00
>>> 01:00:33 PM 0.00 15.18 465.13 0.00
>>> 01:00:33 PM pgpgin/s pgpgout/s fault/s majflt/s
>>> 01:00:43 PM 0.00 12.01 508.31 0.00
>>> 01:00:53 PM 0.00 6.00 588.50 0.00
>>> 01:01:03 PM 0.00 20.00 660.80 0.00
>>> 01:01:13 PM 0.00 6.79 553.05 0.00
>>>
>>> Page faults start to increase along with the degradation problem, but
>>> I'm not 100% sure about this relation, mainly because there's a lot of free
>>> memory, as vmstat shows bellow. However, I saw some people saying that
>>> page faults may occur even when there is free memory.
>>>
>>> vmstat
>>>
>>> procs -----------memory---------- ---swap-- -----io---- --system-- -----
>>> cpu------
>>> r b swpd free buff cache si so bi bo in cs us syid
>>> wa st
>>> 34 0 0 10803608 196472 925120 0 0 0 4 64804 109417
>>> 49 7 45 0 0
>>> 17 0 0 10802604 196472 925120 0 0 0 14 66130 111493
>>> 52 7 41 0 0
>>> 22 0 0 10795060 196472 925120 0 0 0 12 65331 110577
>>> 49 7 45 0 0
>>> 20 0 0 10758080 196472 925120 0 0 0 4 65222 111041
>>> 48 7 45 0 0
>>> 23 0 0 10712208 196472 925120 0 0 0 7 64759 110016
>>> 49 7 45 0 0
>>> 8 0 0 10682828 196472 925140 0 0 0 33 64780 109899
>>> 49 7 44 0 0
>>> 17 0 0 10655280 196472 925140 0 0 0 5 64321 109619
>>> 50 7 44 0 0
>>> procs -----------memory---------- ---swap-- -----io---- --system-- -----
>>> cpu------
>>> r b swpd free buff cache si so bi bo in cs us syid
>>> wa st
>>> 17 0 0 10636300 196472 925140 0 0 0 12 64574 108885
>>> 50 7 44 0 0
>>> 4 0 0 10614888 196472 925140 0 0 0 5 63384 107379
>>> 49 7 44 0 0
>>> 18 0 0 10595172 196472 925140 0 0 0 14 65450 110004
>>> 50 7 43 0 0
>>> 28 0 0 10576420 196472 925140 0 0 0 4 64720 109119
>>> 48 7 45 0 0
>>> 29 0 0 10554908 196472 925140 0 0 0 25 64051 108606
>>> 51 7 42 0 0
>>> 33 0 0 10537584 196472 925140 0 0 0 11 64501 109765
>>> 50 7 43 0 0
>>> 24 0 0 10521128 196472 925140 0 0 0 5 64439 109538
>>> 51 7 42 0 0
>>>
>>> It seems that vmstat doesn't show anything problematic.
>>>
>>> Any other advice?
>>>
>>> Thanks again.
>>>
>>>
>>> On Wed, Dec 18, 2013 at 5:57 PM, Wolfgang Pedot <
>>> wolfgang.pedot at finkzeit.at> wrote:
>>>
>>>> Hi,
>>>>
>>>> this is the first time I write an answer on this mailing-list so this
>>>> could be totally useless but here goes:
>>>>
>>>> Your survivor-space seems to be quite empty, is the usage that low on
>>>> all collects during your test? If so you could increase your survivor-ratio
>>>> to gain more eden-space and if not many objects die in survivor you could
>>>> also reduce the tenuring threshold. Total survivor usage has grown 6-fold
>>>> from first to last GC and survivor space needs to be copied on each young
>>>> gc. I admit it should probably not take that long to copy 60MB though...
>>>>
>>>> Here is a young-gc from one of my logs for comparison:
>>>>
>>>> 30230.123: [ParNew
>>>> Desired survivor size 524261784 bytes, new threshold 12 (max 15)
>>>> - age 1: 113917760 bytes, 113917760 total
>>>> - age 2: 86192768 bytes, 200110528 total
>>>> - age 3: 59060992 bytes, 259171520 total
>>>> - age 4: 59319272 bytes, 318490792 total
>>>> - age 5: 45307432 bytes, 363798224 total
>>>> - age 6: 29478464 bytes, 393276688 total
>>>> - age 7: 27440744 bytes, 420717432 total
>>>> - age 8: 27947680 bytes, 448665112 total
>>>> - age 9: 27294496 bytes, 475959608 total
>>>> - age 10: 32830144 bytes, 508789752 total
>>>> - age 11: 7490968 bytes, 516280720 total
>>>> - age 12: 10723104 bytes, 527003824 total
>>>> - age 13: 4549808 bytes, 531553632 total
>>>> : 4306611K->731392K(4388608K), 0.1433810 secs]
>>>> 10422356K->6878961K(14116608K)
>>>>
>>>> This is with MaxNewSize 5500m and a Survivor-Ratio of 8. You can see
>>>> that GC-time is higher than yours (6core 3.33GHz Xeon), survivor-usage is
>>>> way higher though.
>>>>
>>>> Hope I could help
>>>> Wolfgang
>>>>
>>>>
>>>> Am 18.12.2013 19:58, schrieb Luciano Molinari:
>>>>
>>>>> Hi everybody,
>>>>>
>>>>> We have a standalone Java app that receives requests through RMI and
>>>>> almost all the objects created by it are short (< ~100ms) lived
>>>>> objects.
>>>>> This app is running on a 24 cores server with 16 GB RAM (Red Hat
>>>>> Linux).
>>>>> During our performance tests (10k requests/second) we started to face a
>>>>> problem where the throughput decreases suddenly just a few minutes
>>>>> after the app was started.
>>>>> So, I started to investigate GC behaviour and to make some adjustments
>>>>> (increase memory, use CMS...) and now we are able to run our app
>>>>> properly for about 35 minutes. At this point the time spent during
>>>>> young
>>>>> collections grows sharply although no Full GC is executed (old gen is
>>>>> only ~4% full).
>>>>>
>>>>> I've done tests with many different parameters, but currently I'm using
>>>>> the following ones:
>>>>> java -server -verbose:gc -XX:+PrintGCDetails
>>>>> -XX:+PrintTenuringDistribution -XX:+PrintGCTimeStamps
>>>>> -XX:PrintFLSStatistics=1 -XX:SurvivorRatio=4
>>>>> -XX:ParallelGCThreads=8 -XX:PermSize=256m -XX:+UseParNewGC
>>>>> -XX:MaxPermSize=256m -Xms7g -Xmx7g -XX:NewSize=4608m
>>>>> -XX:MaxNewSize=4608m
>>>>> -XX:MaxTenuringThreshold=15 -Dsun.rmi.dgc.client.gcInterval=3600000
>>>>> -Dsun.rmi.dgc.server.gcInterval=3600000
>>>>> -Djava.rmi.server.hostname=IP_ADDRESS
>>>>>
>>>>> If I use this same configuration (without CMS) the same problem occurs
>>>>> after 20minutes, so it doesn't seem to be related to CMS. Actually, as
>>>>> I
>>>>> mentioned above, CMS (Full GC) isn't executed during the tests.
>>>>>
>>>>> Some logs I've collected:
>>>>>
>>>>> 1992.748: [ParNew
>>>>> Desired survivor size 402653184 bytes, new threshold 15 (max 15)
>>>>> - age 1: 9308728 bytes, 9308728 total
>>>>> - age 2: 3448 bytes, 9312176 total
>>>>> - age 3: 1080 bytes, 9313256 total
>>>>> - age 4: 32 bytes, 9313288 total
>>>>> - age 5: 34768 bytes, 9348056 total
>>>>> - age 6: 32 bytes, 9348088 total
>>>>> - age 15: 2712 bytes, 9350800 total
>>>>> : 3154710K->10313K(3932160K), 0.0273150 secs]
>>>>> 3215786K->71392K(6553600K)
>>>>>
>>>>> //14 YGC happened during this window
>>>>>
>>>>> 2021.165: [ParNew
>>>>> Desired survivor size 402653184 bytes, new threshold 15 (max 15)
>>>>> - age 1: 9459544 bytes, 9459544 total
>>>>> - age 2: 3648200 bytes, 13107744 total
>>>>> - age 3: 3837976 bytes, 16945720 total
>>>>> - age 4: 3472448 bytes, 20418168 total
>>>>> - age 5: 3586896 bytes, 24005064 total
>>>>> - age 6: 3475560 bytes, 27480624 total
>>>>> - age 7: 3520952 bytes, 31001576 total
>>>>> - age 8: 3612088 bytes, 34613664 total
>>>>> - age 9: 3355160 bytes, 37968824 total
>>>>> - age 10: 3823032 bytes, 41791856 total
>>>>> - age 11: 3304576 bytes, 45096432 total
>>>>> - age 12: 3671288 bytes, 48767720 total
>>>>> - age 13: 3558696 bytes, 52326416 total
>>>>> - age 14: 3805744 bytes, 56132160 total
>>>>> - age 15: 3429672 bytes, 59561832 total
>>>>> : 3230658K->77508K(3932160K), 0.1143860 secs]
>>>>> 3291757K->142447K(6553600K)
>>>>>
>>>>> Besides the longer time to perform collection, I also realized that all
>>>>> 15 ages started to have larger values.
>>>>>
>>>>> I must say I'm a little confused about this scenario. Does anyone have
>>>>> some tip?
>>>>>
>>>>> Thanks in advance,
>>>>> --
>>>>> Luciano
>>>>>
>>>>>
>>>>> _______________________________________________
>>>>> hotspot-gc-use mailing list
>>>>> hotspot-gc-use at openjdk.java.net
>>>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>>>>
>>>>>
>>>>
>>>
>>>
>>> --
>>> Luciano Davoglio Molinari
>>>
>>> _______________________________________________
>>> hotspot-gc-use mailing list
>>> hotspot-gc-use at openjdk.java.net
>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>>>
>>>
>>
>>
>> --
>> С уважением,
>> Мамонтов И.А.
>>
>
>
>
> --
> Thanks,
> Ivan
>
--
Luciano Davoglio Molinari
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20131219/d417cefc/attachment.html
More information about the hotspot-gc-use
mailing list