|
Garbage Collection
Part:
1
2
3
4
5
6
7
8
9
(Continued from previous part...)
....
142 8128 358 4% 5120 2176 2944 2650
143 8128 356 4% 5120 2048 3072 2652
143 8128 226 2% 5248 2176 3072 2654
144 8128 224 2% 5248 2048 3200 2656
144 8128 2614 32% 2176 2176 0 3338
145 8128 2612 32% 2176 2048 128 3340
145 8128 2482 30% 2304 2176 128 3342
146 8128 2481 30% 2304 2048 256 3343
146 8128 2351 28% 2432 2176 256 3345
147 8128 2349 28% 2432 2048 384 3347
....
161 8128 378 4% 4352 2176 2176 3398
162 8128 376 4% 4352 2048 2304 3400
162 8128 247 3% 4480 2176 2304 3401
163 8128 245 3% 4480 2048 2432 3403
163 8128 3382 41% 2176 2176 0 2570
164 8128 3380 41% 2176 2048 128 2572
164 8128 3251 39% 2304 2176 128 2573
165 8128 3249 39% 2304 2048 256 2575
165 8128 3119 38% 2432 2176 256 2577
166 8128 3117 38% 2432 2048 384 2579
....
186 8128 358 4% 5120 2176 2944 2650
187 8128 356 4% 5120 2048 3072 2652
187 8128 226 2% 5248 2176 3072 2654
188 8128 224 2% 5248 2048 3200 2656
188 8128 2614 32% 2176 2176 0 3338
189 8128 2612 32% 2176 2048 128 3340
189 8128 2482 30% 2304 2176 128 3342
190 8128 2481 30% 2304 2048 256 3343
190 8128 2351 28% 2432 2176 256 3345
191 8128 2349 28% 2432 2048 384 3347
....
205 8128 378 4% 4352 2176 2176 3398
206 8128 376 4% 4352 2048 2304 3400
206 8128 247 3% 4480 2176 2304 3401
207 8128 245 3% 4480 2048 2432 3403
207 8128 3382 41% 2176 2176 0 2570
208 8128 3380 41% 2176 2048 128 2572
208 8128 3251 39% 2304 2176 128 2573
209 8128 3249 39% 2304 2048 256 2575
209 8128 3119 38% 2432 2176 256 2577
210 8128 3117 38% 2432 2048 384 2579
....
230 8128 486 5% 4992 2048 2944 2650
231 8128 356 4% 5120 2176 2944 2652
231 8128 226 2% 5248 2176 3072 2654
232 8128 224 2% 5248 2048 3200 2656
232 8128 2614 32% 2176 2176 0 3338
233 8128 2612 32% 2176 2048 128 3340
233 8128 2482 30% 2304 2176 128 3342
234 8128 2481 30% 2304 2048 256 3343
234 8128 2351 28% 2432 2176 256 3345
235 8128 2349 28% 2432 2048 384 3347
....
250 8128 376 4% 4352 2048 2304 3400
250 8128 247 3% 4480 2176 2304 3401
251 8128 245 3% 4480 2048 2432 3403
251 8128 3382 41% 4608 2048 2560 138
252 8128 3380 41% 2176 2176 0 2572
252 8128 3379 41% 2176 2048 128 2573
253 8128 3249 39% 2304 2176 128 2575
253 8128 3247 39% 2304 2048 256 2577
254 8128 3117 38% 2432 2176 256 2579
254 8128 3116 38% 2432 2048 384 2580
....
As the output shows, the JVM (HotSpot) started with 2MB of total memory, with
about 87% of free memory. As the program starts to allocate objects during the
initialization phase, free memory starts to decrease. I don't know why.
When the free memory decreased to 14%, about 294KB, still enough for 2 more
objects, the JVM decided to request more total momory from the operating system.
At second 8, the program finished the initialization phase, and entered into
the loop testing phase. It started to allocate one object, then release the oldest
object from the list. The released objects became dead objects and waiting to
collected as garbage.
As you can see from the output, the dead objects were not immediately collected
by the garbage collector. The first collection of dead objects happened at second
14, when free memory descreased to 8%, about 275KB. The JVM collected the dead objects and
request more total memory at about the same time. I don't know why.
As the program continued to repeatedly allocate and release objects, dead objects
were accumulated again, and the free memory continued to decrease. When free memory
decreased to 3%, 197KB, at second 30, the JVM decided to collect dead objects and request more
total memory again.
The next time the JVM decided to collect dead objects and request more total memory
happened at second 56. Total memory reached 8128KB, about the same as the maximum
memory size specified by the command line otion, -Xmx8m.
When the free memory decreased again to 3% at second 75, the JVM could not get any
more total memory. It only collected the dead objects, and raised the free memory
back to 41%.
While reviewing the rest of the output, I noticed that at second 100, the JVM
collected the dead objects with 3200KB of memory. However, the free memory reported
by the JVM only increased by 2389KB (2614KB-225KB). So where is the other 800KB
collected from the dead objects? Can any one explain this?
19 seconds later, the JVM collected only 2432KB of dead objects, but the free memory
increased by 3137KB. This time, about 700KB more memory come out from no where.
May be certain amount of memory was reserved at the previous garbage collection
time.
After looking at the over head memory size, I found that each time the JVM collected
garbage, it also reserved the same amount of memory as the garbage collected.
This explains well why at second 100, 800KB of collected memory was not giving
back as free memory. At that time, 8128 (total memory) - 2176 (active objects)
- 3338 (reserved memory) = 2614 (free memory), where the reserved memory (3338KB)
is about the same as the collected memory (3200KB).
Couple of quick observations:
- When the free memory is low, the JVM will try go request more total memory,
and collect garbages at the same time.
- The JVM will let the free memory run as low as 2% of the total memory, before
collecting garbages.
- At the end of garbage collection, the same amount of memory as the collected
garbages will be reserved.
(Continued on next part...)
Part:
1
2
3
4
5
6
7
8
9
| 