A program leaking memory.

[Thomas Kuehne]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Johan Grönqvist schrieb am 2006-03-17:
> Thomas Kuehne wrote:
>> Johan Grýnqvist schrieb am 2006-03-13:

[snip]

> 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. 

[snip]

> [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!

[snip]

> 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.

The small increase of "used" and "free" doesn't seem critical.
Something else seems odd: the statistic gathering of the GC

iteration 11:
pool / (FREE + PAGE) -> 5888
(free + used) / (FREE + PAGE) -> 59
pool / (free + used) -> 99

iteration 350:
pool / (FREE + PAGE) -> 10329
(free + used) / (FREE + PAGE) -> 52
pool / (free + used) -> 195

iteration 500:
pool / (FREE + PAGE) -> 13116
(free + used) / (FREE + PAGE) -> 39
pool / (free + used) -> 331

Part of the problem might be that B_PAGEPLUS isn't handled in getStats
(-> internal/gc/gcx.d:665). This would only explain why the numbers above
don't add up for "free", "used", "FREE" and "PAGE" - "pool" seems to be
correct.

>> 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.
It should. The location of the allocations might cause a small jump of the
pool size within the first few iterations.

single allocation:
> [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

collect after every iteration: 
> [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

collect before iteration 200 and 400:
> [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

(keep the odd statistic gathering in mind (see above))

As the length of the array doesn't change between iteration
I assume that 2 arrays are newed - both containing at least
4097(PAGESIZE+1) bytes of data and in sum between
589826(PAGESIZE*145+2) and 598016(PAGESIZE*146) bytes of data.
Thus in average 72 B_PAGEPLUS pages per B_PAGE page.

single allocation (iteration 5000):
pool / (FREE + (72 + 1) * PAGE) -> 4443

collect after every iteration(iteration 500):
pool / (FREE + (72 + 1) * PAGE) -> 4152

collect before iteration 200 and 400(iteration 500):
pool / (FREE + (72 + 1) * PAGE) -> 4153

It doesn't look like there are any hidden increases of the
array length during repeated calls to the "step" function or 
within the "step" function.

Seems like large allocations aren't collected properly under some
circumstances:

collect after every iteration: 
> [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

This is certanly the interresting point. Either some of your data begins
to look like a pointer into managed memory somewhere around iteration
348 or there is some serious issue with the GC.

Checking the "pointer lookalike" issue isn't trivial. As a start ensure
that all your "data" numbers(array, temporaries, etc) are between 0 and 1024
while withing the iteration loop.

If the gigantic pool size remains you should file a bug
(http://d.puremagic.com/bugzilla) with attached minimal but runnable testcase
sources or - if there are any IP issues with your code - read
http://www.digitalmars.com/bugs.html and send Walter the bug.

Thomas


-----BEGIN PGP SIGNATURE-----

iD8DBQFEHJlf3w+/yD4P9tIRAhuXAJwIZiLGomTusBJGKXhH/AtazHe5HACfZluJ
nybaz2n1i1jeXWgr/cANXls=
=Q/4U
-----END PGP SIGNATURE-----