A program leaking memory.

Fri Mar 17 03:08:31 PST 2006

Thomas Kuehne wrote:
> Johan Grýnqvist schrieb am 2006-03-13:
> 
> [snip]
> 

Before I start, my main loop now looks like

int iter = 0;
	while (iter < 500)
	{
		newEnergy = canti.step(lastEnergy);
		lastEnergy = newEnergy;
		iter++;
		fullCollect();
		getStats(gc);
           };

where I have removed lines only doing output to make it clearer.
As canti.step does not have access to the variable iter, I am confident
that all iterations should behave the same way as far as memory
management goes.

>>>[66] pool:16121856 used:25280 free:15680 FREE:300 PAGE:49
>>>[77] pool:22675456 used:5200 free:19376 FREE:276 PAGE:71
>>>
>>>So far everything is fine. Memory usage seems to fluctuate, steadily
>>>upwards with each iteration, and dropping to ~5200 with irregular intervals.
>>>
>>>From here on, however, it never reaches down to the same levels again,
>>>and (restricting to 200 iterations) the end of the output is
>>>
>>>[199] pool:99352576 used:35744 free:29792 FREE:930 PAGE:315
>>>[200] pool:99680256 used:38272 free:27264 FREE:862 PAGE:317
>>>
>>>I would like it to do gc before my system starts swapping.
>>>My interpretation of the above is that it does gc to rarely.
> 
> This isn't the only possible cause. What happens if you call
> fullCollect() after iteration 199?
> (no fullCollect() calls from your code between iteration 1 and 199)
> 

Ok: fullCollect after 200 and 400 iterations, running for a total of 500
iterations.

[197] pool:97124352 used:21520 free:44016 FREE:682 PAGE:311
[198] pool:97779712 used:24048 free:41488 FREE:694 PAGE:313
[199] pool:98435072 used:26576 free:38960 FREE:706 PAGE:315
Collecting garbage

[200] pool:99090432 used:13984 free:47456 FREE:719 PAGE:317
[201] pool:99418112 used:16496 free:44944 FREE:651 PAGE:319
[202] pool:100073472 used:19024 free:42416 FREE:663 PAGE:321

Hmmm... It no longer drops to close to 5000, and the pool is HUGE. I
assume tis is what my OS sees the program using, is that correct?

[260] pool:135462912 used:48416 free:21216 FREE:717 PAGE:437
[261] pool:136118272 used:50944 free:18688 FREE:729 PAGE:439

At this point (261 iterations) I get from top that

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 3611 johan     24   0  146m 131m  596 S  0.0 27.0   0:26.96 a.out
 7707 root      15   0  216m  81m 3076 S  2.1 16.7  16:16.29 Xorg

indicating that "pool" is what determines if my system swaps or not.

The pool continues to increase.

[397] pool:218365952 used:51552 free:42656 FREE:675 PAGE:711
[398] pool:219021312 used:54080 free:40128 FREE:687 PAGE:713
[399] pool:219676672 used:56608 free:37600 FREE:699 PAGE:715
Collecting garbage

[400] pool:220332032 used:50048 free:44160 FREE:711 PAGE:717
[401] pool:220987392 used:52576 free:41632 FREE:723 PAGE:719
[402] pool:221642752 used:55104 free:39104 FREE:735 PAGE:721

This collect after 400 iteration does almost nothing!!
And it does not release any memory to the system!

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
 3611 johan     18   0  228m 218m  596 S  0.0 44.7   0:49.88 a.out
 3097 johan     16   0 87904  38m  13m S  0.0  8.0   0:16.55 kpdf

Going on to the end...

[498] pool:279642112 used:96896 free:25984 FREE:680 PAGE:913
[499] pool:280297472 used:99424 free:23456 FREE:692 PAGE:915
[500] pool:280952832 used:101952 free:20928 FREE:704 PAGE:917

>>>After I insert a fullCollect() every iteration, my output ends with
Again using fullCollect after every iteration:

[11] pool:2031616 used:2672 free:17808 FREE:343 PAGE:2
[12] pool:2031616 used:2688 free:17792 FREE:343 PAGE:2
[13] pool:2031616 used:2688 free:17792 FREE:343 PAGE:2

[341] pool:3997696 used:2736 free:17744 FREE:823 PAGE:2
[342] pool:3997696 used:2736 free:17744 FREE:823 PAGE:2
[343] pool:3997696 used:2736 free:17744 FREE:823 PAGE:2

So far good, but something happens:

[350] pool:3997696 used:2736 free:17744 FREE:379 PAGE:8
[351] pool:3997696 used:2736 free:17744 FREE:231 PAGE:10
[352] pool:3997696 used:2736 free:17744 FREE:83 PAGE:12
[353] pool:4653056 used:3760 free:20816 FREE:94 PAGE:14
[354] pool:5308416 used:3760 free:20816 FREE:106 PAGE:16
[355] pool:5963776 used:3760 free:20816 FREE:118 PAGE:18
[356] pool:6619136 used:3760 free:20816 FREE:130 PAGE:20

and the end reads:

[497] pool:93126656 used:6896 free:21776 FREE:381 PAGE:302
[498] pool:93782016 used:6896 free:21776 FREE:393 PAGE:304
[499] pool:94437376 used:6896 free:21776 FREE:405 PAGE:306
[500] pool:95092736 used:6896 free:21776 FREE:417 PAGE:308

Thus, from iteration 13 to 341 the pool changes by a factor of 2.
>From iteration 341 to 500 it changes by a factor of 30, if I read it
correctly.

I see no reason why.

> 
> Let's try to make sure that the array is the cause.
> 
> Even better would be if you could use single allocation of the array.

With one single allocation for all arrys involved

EXCELLENT!!

[47] pool:1048576 used:120080 free:15088 FREE:1 PAGE:3
[48] pool:1048576 used:122592 free:16672 FREE:0 PAGE:3
[49] pool:1048576 used:5232 free:35728 FREE:24 PAGE:3
[50] pool:1048576 used:7744 free:33216 FREE:24 PAGE:3

[95] pool:1048576 used:120736 free:18528 FREE:0 PAGE:3
[96] pool:1048576 used:123248 free:16016 FREE:0 PAGE:3
[97] pool:1048576 used:5232 free:23440 FREE:27 PAGE:3
[98] pool:1048576 used:7728 free:20944 FREE:27 PAGE:3

[142] pool:1048576 used:118848 free:16320 FREE:1 PAGE:3
[143] pool:1048576 used:121376 free:17888 FREE:0 PAGE:3
[144] pool:1048576 used:123904 free:15360 FREE:0 PAGE:3
[145] pool:1048576 used:5424 free:31440 FREE:25 PAGE:3
[146] pool:1048576 used:7952 free:28912 FREE:25 PAGE:3
[147] pool:1048576 used:10480 free:30480 FREE:24 PAGE:3

....

[496] pool:1048576 used:48176 free:13264 FREE:19 PAGE:3
[497] pool:1048576 used:50704 free:14832 FREE:18 PAGE:3
[498] pool:1048576 used:53232 free:12304 FREE:18 PAGE:3
[499] pool:1048576 used:55760 free:13872 FREE:17 PAGE:3
[500] pool:1048576 used:58288 free:11344 FREE:17 PAGE:3

As soon as it reaches the pool-size, everything is collected, and the
used memory is small.

I do not see why. I thought the GC would find all forgotten arrays that
have been allocated at fullCollect time.

As the problem was not in the number of calls to the garbage collector,
I still do not understand this.

Thanks for the help!

/ johan