GC problem ?

[vettori]

Hi,

I have the following problem with JBoss 4.0.5GA :

I have an java app that using session beans performs some operations on entity beans.
One of this operation is to scan ALL the beans of a certain type and do an update.
The problem is the following.
On the first run of the app I can see the gc working (i suppose removing the entity beans). The memory usage is high but it's short in time.

For example the gc log is :
[INFO ][memory ] 6.229-6.420: GC 511614K->7974K (5242880K), 190.590 ms
[INFO ][memory ] 329.471: parallel nursery GC 1476387K->689203K (5242880K), 505.334 ms
[INFO ][memory ] 346.359: parallel nursery GC 1476003K->689203K (5242880K), 435.881 ms
[INFO ][memory ] 362.523: parallel nursery GC 1476003K->689075K (5242880K), 428.308 ms
[INFO ][memory ] 383.814: parallel nursery GC 1852701K->1065517K (5242880K), 434.963 ms

If I run a second time the app, the gc enter something like an infinite loop (look at the time elapsed between various call)

[INFO ][memory ] 493.644: parallel nursery GC 1852317K->1065069K (5242880K), 88.713 ms
[INFO ][memory ] 497.127: parallel nursery GC 1851869K->1064797K (5242880K), 31.096 ms
[INFO ][memory ] 500.167: parallel nursery GC 1851597K->1064493K (5242880K), 31.199 ms
[INFO ][memory ] 503.087: parallel nursery GC 1851293K->1064493K (5242880K), 28.628 ms
[INFO ][memory ] 505.881: parallel nursery GC 1851293K->1064382K (5242880K), 52.890 ms
[INFO ][memory ] 508.346: parallel nursery GC 1851182K->1064254K (5242880K), 88.999 ms
[INFO ][memory ] 510.823: parallel nursery GC 1851054K->1063870K (5242880K), 95.023 ms
[INFO ][memory ] 513.459: parallel nursery GC 1850670K->1063678K (5242880K), 86.064 ms
[INFO ][memory ] 516.031: parallel nursery GC 1850478K->1063678K (5242880K), 87.788 ms
[INFO ][memory ] 518.565: parallel nursery GC 1850478K->1063486K (5242880K), 86.779 ms
[INFO ][memory ] 521.069: parallel nursery GC 1850286K->1063102K (5242880K), 94.063 ms
[INFO ][memory ] 523.622: parallel nursery GC 1849902K->1063038K (5242880K), 88.928 ms
[INFO ][memory ] 526.108: parallel nursery GC 1849838K->1062590K (5242880K), 94.253 ms
[INFO ][memory ] 528.714: parallel nursery GC 1849390K->1062590K (5242880K), 83.759 ms
[INFO ][memory ] 531.211: parallel nursery GC 1849390K->1062590K (5242880K), 86.603 ms
[INFO ][memory ] 533.695: parallel nursery GC 1849390K->1062398K (5242880K), 91.240 ms
[INFO ][memory ] 536.522: parallel nursery GC 1849198K->1062398K (5242880K), 98.894 ms
[INFO ][memory ] 539.052: parallel nursery GC 1849198K->1062334K (5242880K), 97.539 ms
[INFO ][memory ] 541.558: parallel nursery GC 1849134K->1062014K (5242880K), 84.316 ms
[INFO ][memory ] 544.084: parallel nursery GC 1848814K->1061758K (5242880K), 86.974 ms
[INFO ][memory ] 546.661: parallel nursery GC 1848558K->1061503K (5242880K), 92.846 ms
[INFO ][memory ] 549.151: parallel nursery GC 1848303K->1061439K (5242880K), 86.954 ms
[INFO ][memory ] 551.812: parallel nursery GC 1848239K->1061183K (5242880K), 56.842 ms
[INFO ][memory ] 554.319: parallel nursery GC 1847983K->1060927K (5242880K), 77.107 ms
[INFO ][memory ] 556.832: parallel nursery GC 1847727K->1060543K (5242880K), 79.477 ms
[INFO ][memory ] 559.295: parallel nursery GC 1847343K->1060415K (5242880K), 88.774 ms
[INFO ][memory ] 561.766: parallel nursery GC 1847215K->1060223K (5242880K), 96.909 ms
[INFO ][memory ] 564.551: parallel nursery GC 1847023K->1060223K (5242880K), 40.048 ms
[INFO ][memory ] 567.003: parallel nursery GC 1847023K->1059967K (5242880K), 82.474 ms
[INFO ][memory ] 569.438: parallel nursery GC 1846767K->1059583K (5242880K), 85.952 ms
[INFO ][memory ] 572.178: parallel nursery GC 1846383K->1059455K (5242880K), 46.389 ms
[INFO ][memory ] 574.944: parallel nursery GC 1846255K->1059199K (5242880K), 31.293 ms
[INFO ][memory ] 577.722: parallel nursery GC 1845999K->1058879K (5242880K), 33.769 ms
[INFO ][memory ] 580.505: parallel nursery GC 1845679K->1058559K (5242880K), 28.919 ms
[INFO ][memory ] 583.288: parallel nursery GC 1845359K->1058339K (5242880K), 30.513 ms
[INFO ][memory ] 586.054: parallel nursery GC 1845139K->1058143K (5242880K), 32.064 ms
[INFO ][memory ] 588.831: parallel nursery GC 1844943K->1058143K (5242880K), 30.358 ms
[INFO ][memory ] 591.610: parallel nursery GC 1844943K->1058143K (5242880K), 28.526 ms
[INFO ][memory ] 594.390: parallel nursery GC 1844943K->1058065K (5242880K), 31.627 ms
[INFO ][memory ] 597.168: parallel nursery GC 1844865K->1057617K (5242880K), 35.818 ms
[INFO ][memory ] 599.941: parallel nursery GC 1844417K->1057617K (5242880K), 32.745 ms
[INFO ][memory ] 602.700: parallel nursery GC 1844417K->1057617K (5242880K), 35.947 ms
[INFO ][memory ] 605.488: parallel nursery GC 1844417K->1057425K (5242880K), 36.896 ms
[INFO ][memory ] 608.272: parallel nursery GC 1844225K->1056977K (5242880K), 33.302 ms
[INFO ][memory ] 611.056: parallel nursery GC 1843777K->1056721K (5242880K), 34.488 ms
[INFO ][memory ] 613.835: parallel nursery GC 1843521K->1056337K (5242880K), 30.651 ms
etc...


The STRANGE thing is that the gc continues running forever even after the app exited.

What's happening ???

Thank you

[vettori]

I updated Jboss to 4.2.0GA that has hibernate 3.2.3 (3.2.1 entitymanager).

Running the app three times now gives :

[INFO ][memory ] 3.737-3.893: GC 456014K->4945K (5242880K), 155.649 ms
[INFO ][memory ] 542.299: parallel nursery GC 1483183K->695999K (5242880K), 379.253 ms
[INFO ][memory ] 2113.122: parallel nursery GC 1862122K->1075130K (5242880K), 536.939 ms
[INFO ][memory ] 2732.543-2732.669: GC 1568837K->85502K (5242880K), 126.728 ms
[INFO ][memory ] 5160.667: parallel nursery GC 1543572K->760980K (5242880K), 867.616 ms
[INFO ][memory ] 5191.217: parallel nursery GC 1916236K->1131836K (5242880K), 811.969 ms
[INFO ][memory ] 5222.067: parallel nursery GC 1916236K->1182604K (5242880K), 807.395 ms
[INFO ][memory ] 5256.562: parallel nursery GC 2294636K->1509980K (5242880K), 813.308 ms
[INFO ][memory ] 5358.185: parallel nursery GC 2589543K->1807080K (5242880K), 826.695 ms
[INFO ][memory ] 5377.246: parallel nursery GC 2589480K->1857368K (5242880K), 832.857 ms
[INFO ][memory ] 5396.206: parallel nursery GC 2902380K->2119980K (5242880K), 818.478 ms
[INFO ][memory ] 5417.744: parallel nursery GC 3136880K->2352224K (5242880K), 826.093 ms
[INFO ][memory ] 5506.212: parallel nursery GC 3347309K->2564781K (5242880K), 827.195 ms
[INFO ][memory ] 5525.118: parallel nursery GC 3537258K->2777114K (5242880K), 829.615 ms
[INFO ][memory ] 5543.997: parallel nursery GC 3729963K->3010539K (5242880K), 836.042 ms
[INFO ][memory ] 5564.356: parallel nursery GC 3938352K->3239969K (5242880K), 833.441 ms


so it's a lot better.

I don't know if this is because of hibernate 3.2.3 or jboss and i really like to know.

Can anybody help me to understand ?

thank you

[vettori]

Bad news...

Even with the upgrade it only takes longer but it happens...

[INFO ][memory ] 41369.000-41369.141: GC 973949K->153965K (5242880K), 140.800 ms
[INFO ][memory ] 43678.758-43678.893: GC 876646K->145950K (5242880K), 135.191 ms
[INFO ][memory ] 46058.278-46058.425: GC 847984K->140040K (5242880K), 147.288 ms
[INFO ][memory ] 48400.393-48400.529: GC 973458K->152902K (5242880K), 136.187 ms
[INFO ][memory ] 50376.968-50377.117: GC 1008382K->171014K (5242880K), 148.453 ms
[INFO ][memory ] 52293.828-52293.963: GC 911852K->149894K (5242880K), 135.565 ms
[INFO ][memory ] 52766.219: parallel nursery GC 1597712K->819792K (5242880K), 1066.246 ms
[INFO ][memory ] 52785.264: parallel nursery GC 1963059K->1184403K (5242880K), 825.711 ms
[INFO ][memory ] 52805.516: parallel nursery GC 1962803K->1184947K (5242880K), 822.961 ms
[INFO ][memory ] 52828.219: parallel nursery GC 2290690K->1512290K (5242880K), 833.181 ms
[INFO ][memory ] 55071.548-55073.111: GC 1862290K->206785K (5242880K), 1563.780 ms
[INFO ][memory ] 57584.100-57584.879: GC 888041K->93430K (5242880K), 779.164 ms
[INFO ][memory ] 59435.050: parallel nursery GC 1552296K->766040K (5242880K), 219.950 ms
[INFO ][memory ] 59438.151: parallel nursery GC 1552040K->765260K (5242880K), 36.980 ms
[INFO ][memory ] 59441.070: parallel nursery GC 1551660K->765404K (5242880K), 39.158 ms
[INFO ][memory ] 59443.997: parallel nursery GC 1551404K->764556K (5242880K), 34.195 ms
[INFO ][memory ] 59446.923: parallel nursery GC 1550956K->764637K (5242880K), 32.322 ms
[INFO ][memory ] 59449.843: parallel nursery GC 1550637K->764237K (5242880K), 34.257 ms
[INFO ][memory ] 59452.738: parallel nursery GC 1550637K->764533K (5242880K), 36.508 ms
[INFO ][memory ] 59455.669: parallel nursery GC 1550533K->764133K (5242880K), 35.539 ms
[INFO ][memory ] 59458.597: parallel nursery GC 1550533K->764533K (5242880K), 33.265 ms
[INFO ][memory ] 59461.509: parallel nursery GC 1550533K->764133K (5242880K), 34.502 ms
[INFO ][memory ] 59464.414: parallel nursery GC 1550533K->764533K (5242880K), 32.673 ms
[INFO ][memory ] 59467.293: parallel nursery GC 1550533K->764133K (5242880K), 38.018 ms
[INFO ][memory ] 59470.192: parallel nursery GC 1550533K->764277K (5242880K), 33.602 ms
[INFO ][memory ] 59473.077: parallel nursery GC 1550277K->763877K (5242880K), 34.551 ms
[INFO ][memory ] 59475.945: parallel nursery GC 1550277K->764149K (5242880K), 39.169 ms
[INFO ][memory ] 59478.842: parallel nursery GC 1550149K->763365K (5242880K), 34.903 ms
[INFO ][memory ] 59481.727: parallel nursery GC 1549765K->763477K (5242880K), 32.807 ms
[INFO ][memory ] 59484.612: parallel nursery GC 1549477K->762629K (5242880K), 34.387 ms
[INFO ][memory ] 59487.473: parallel nursery GC 1549029K->763029K (5242880K), 36.790 ms
[INFO ][memory ] 59490.376: parallel nursery GC 1549029K->762437K (5242880K), 39.065 ms
[INFO ][memory ] 59493.275: parallel nursery GC 1548837K->762453K (5242880K), 33.966 ms
[INFO ][memory ] 59496.155: parallel nursery GC 1548453K->762053K (5242880K), 35.931 ms
[INFO ][memory ] 59499.040: parallel nursery GC 1548453K->762350K (5242880K), 36.593 ms
[INFO ][memory ] 59501.933: parallel nursery GC 1548350K->761950K (5242880K), 33.835 ms



ANYONE CAN HELP ?

I read everything but can't find nothing explaining this...