I did some simple memory profiling of the testsuite wrt the Gz module.
Before testing Gz:
[...] 001CC000 64576K read/write/exec [ heap ] [...] total 116856K
After tests with constant strings, before tests with random strings:
[...] 001CC000 64576K read/write/exec [ heap ] [...] total 116856K
After all Gz tests:
[...] 001CC000 95936K read/write/exec [ heap ] [...] total 148216K
The last randomness test uses about 32 megs, so it's natural for the heap to grow to 96M if all the 64M that made up the previous heap is actually used. Question is, why would there be 64M used heap space at the entry to the tests? A freshly started pike has only 2.5M of heap, so the previous tests must have left 61M of now unused data still referenced somehow. (Some of it can be attributed to internal fragmentation of course, but considering the size of the block we shouldn't have _that_ much fragmentation.)
I'm going to try it again with some gc()'s sprinkled through the tests.
Should have included _memory_usage() of course.
Before Gz tests:
([ /* 18 elements */ "array_bytes":1905732, "callable_bytes":12300, "callback_bytes":2052, "frame_bytes":8766504, "mapping_bytes":12001375, "multiset_bytes":8672, "num_arrays":12609, "num_callables":347, "num_callbacks":4, "num_frames":3, "num_mappings":39106, "num_multisets":542, "num_objects":-345499, "num_programs":1492, "num_strings":33293, "object_bytes":2143552, "program_bytes":9366376, "string_bytes":2072876 ])
After Gz tests:
([ /* 18 elements */ "array_bytes":1904780, "callable_bytes":12300, "callback_bytes":2052, "frame_bytes":8766504, "mapping_bytes":12012607, "multiset_bytes":8672, "num_arrays":12609, "num_callables":347, "num_callbacks":4, "num_frames":3, "num_mappings":39145, "num_multisets":542, "num_objects":-345691, "num_programs":1492, "num_strings":33319, "object_bytes":2143552, "program_bytes":9366376, "string_bytes":2074170 ])
For some reason, there seems to be a very large number of mappings left over from something. What's frame_bytes? Should only 3 frames (whatever that is) really amount for 8.7M of data?
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Previous text:
2002-09-27 14:40: Subject: Gz testsuite memory usage
I did some simple memory profiling of the testsuite wrt the Gz module.
Before testing Gz:
[...] 001CC000 64576K read/write/exec [ heap ] [...] total 116856K
After tests with constant strings, before tests with random strings:
[...] 001CC000 64576K read/write/exec [ heap ] [...] total 116856K
After all Gz tests:
[...] 001CC000 95936K read/write/exec [ heap ] [...] total 148216K
The last randomness test uses about 32 megs, so it's natural for the heap to grow to 96M if all the 64M that made up the previous heap is actually used. Question is, why would there be 64M used heap space at the entry to the tests? A freshly started pike has only 2.5M of heap, so the previous tests must have left 61M of now unused data still referenced somehow. (Some of it can be attributed to internal fragmentation of course, but considering the size of the block we shouldn't have _that_ much fragmentation.)
I'm going to try it again with some gc()'s sprinkled through the tests.
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
"frame_bytes":8766504, "num_frames":3,
For some reason, there seems to be a very large number of mappings left over from something. What's frame_bytes? Should only 3 frames (whatever that is) really amount for 8.7M of data?
Note that block_alloc.h:count_memory_in_DATAs() doesn't adjust the byte count for free blocks. A struct pike_frame is ~88 bytes, so at some point in time ~100000 pike frames were used (probably during one of the stack exhaustion tests).
/ Henrik Grubbström (Lysator)
Previous text:
2002-09-27 15:49: Subject: Gz testsuite memory usage
Should have included _memory_usage() of course.
Before Gz tests:
([ /* 18 elements */ "array_bytes":1905732, "callable_bytes":12300, "callback_bytes":2052, "frame_bytes":8766504, "mapping_bytes":12001375, "multiset_bytes":8672, "num_arrays":12609, "num_callables":347, "num_callbacks":4, "num_frames":3, "num_mappings":39106, "num_multisets":542, "num_objects":-345499, "num_programs":1492, "num_strings":33293, "object_bytes":2143552, "program_bytes":9366376, "string_bytes":2072876 ])
After Gz tests:
([ /* 18 elements */ "array_bytes":1904780, "callable_bytes":12300, "callback_bytes":2052, "frame_bytes":8766504, "mapping_bytes":12012607, "multiset_bytes":8672, "num_arrays":12609, "num_callables":347, "num_callbacks":4, "num_frames":3, "num_mappings":39145, "num_multisets":542, "num_objects":-345691, "num_programs":1492, "num_strings":33319, "object_bytes":2143552, "program_bytes":9366376, "string_bytes":2074170 ])
For some reason, there seems to be a very large number of mappings left over from something. What's frame_bytes? Should only 3 frames (whatever that is) really amount for 8.7M of data?
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
It seems that the frame_bytes come from the main testsuite, and most of the mapping_bytes from the Gmp testsuite:
Doing tests in testsuite (10418 tests) NM: 56, MB: 57292, FB: 11268
Doing tests in modules/CommonLog/module_testsuite (0 tests) NM: 11763, MB: 3687563, FB: 8766504
Doing tests in modules/Gdbm/module_testsuite (65 tests) NM: 11763, MB: 3687563, FB: 8766504
Doing tests in modules/Gettext/module_testsuite (0 tests) NM: 11763, MB: 3687971, FB: 8766504
Doing tests in modules/Gmp/module_testsuite (28743 tests) NM: 11763, MB: 3687971, FB: 8766504
Doing tests in modules/Gz/module_testsuite (96 tests) NM: 39106, MB: 12003303, FB: 8766504
[...]
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Previous text:
2002-09-27 15:49: Subject: Gz testsuite memory usage
Should have included _memory_usage() of course.
Before Gz tests:
([ /* 18 elements */ "array_bytes":1905732, "callable_bytes":12300, "callback_bytes":2052, "frame_bytes":8766504, "mapping_bytes":12001375, "multiset_bytes":8672, "num_arrays":12609, "num_callables":347, "num_callbacks":4, "num_frames":3, "num_mappings":39106, "num_multisets":542, "num_objects":-345499, "num_programs":1492, "num_strings":33293, "object_bytes":2143552, "program_bytes":9366376, "string_bytes":2072876 ])
After Gz tests:
([ /* 18 elements */ "array_bytes":1904780, "callable_bytes":12300, "callback_bytes":2052, "frame_bytes":8766504, "mapping_bytes":12012607, "multiset_bytes":8672, "num_arrays":12609, "num_callables":347, "num_callbacks":4, "num_frames":3, "num_mappings":39145, "num_multisets":542, "num_objects":-345691, "num_programs":1492, "num_strings":33319, "object_bytes":2143552, "program_bytes":9366376, "string_bytes":2074170 ])
For some reason, there seems to be a very large number of mappings left over from something. What's frame_bytes? Should only 3 frames (whatever that is) really amount for 8.7M of data?
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Ok, now the frame_bytes are down to reasonable levels:
Doing tests in testsuite (10418 tests) NM: 56, MB: 57304, FB: 11280
Doing tests in modules/CommonLog/module_testsuite (0 tests) NM: 11763, MB: 3687851, FB: 56400
Doing tests in modules/Gdbm/module_testsuite (65 tests) NM: 11763, MB: 3687851, FB: 56400
Doing tests in modules/Gettext/module_testsuite (0 tests) NM: 11763, MB: 3688259, FB: 56400
Doing tests in modules/Gmp/module_testsuite (28743 tests) NM: 11763, MB: 3688259, FB: 56400
Doing tests in modules/Gz/module_testsuite (96 tests) NM: 39106, MB: 12004227, FB: 56400
[...]
The 12 MB mappings are still there though, and from the mapping count it looks like they are actually referenced. So somehow the Gmp testsuite is leaking mappings...
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Previous text:
2002-09-27 17:18: Subject: Gz testsuite memory usage
It seems that the frame_bytes come from the main testsuite, and most of the mapping_bytes from the Gmp testsuite:
Doing tests in testsuite (10418 tests) NM: 56, MB: 57292, FB: 11268
Doing tests in modules/CommonLog/module_testsuite (0 tests) NM: 11763, MB: 3687563, FB: 8766504
Doing tests in modules/Gdbm/module_testsuite (65 tests) NM: 11763, MB: 3687563, FB: 8766504
Doing tests in modules/Gettext/module_testsuite (0 tests) NM: 11763, MB: 3687971, FB: 8766504
Doing tests in modules/Gmp/module_testsuite (28743 tests) NM: 11763, MB: 3687971, FB: 8766504
Doing tests in modules/Gz/module_testsuite (96 tests) NM: 39106, MB: 12003303, FB: 8766504
[...]
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Performance: make testsuite uses 0.2% more user time, and 6.5% less system time with the new block allocator.
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Previous text:
2002-09-30 12:49: Subject: Gz testsuite memory usage
Ok, now the frame_bytes are down to reasonable levels:
Doing tests in testsuite (10418 tests) NM: 56, MB: 57304, FB: 11280
Doing tests in modules/CommonLog/module_testsuite (0 tests) NM: 11763, MB: 3687851, FB: 56400
Doing tests in modules/Gdbm/module_testsuite (65 tests) NM: 11763, MB: 3687851, FB: 56400
Doing tests in modules/Gettext/module_testsuite (0 tests) NM: 11763, MB: 3688259, FB: 56400
Doing tests in modules/Gmp/module_testsuite (28743 tests) NM: 11763, MB: 3688259, FB: 56400
Doing tests in modules/Gz/module_testsuite (96 tests) NM: 39106, MB: 12004227, FB: 56400
[...]
The 12 MB mappings are still there though, and from the mapping count it looks like they are actually referenced. So somehow the Gmp testsuite is leaking mappings...
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Ah-ha. Each time the compiler compiles an expression containing a literal Gmp.mpz creation, it leaks one mapping:
Pike v7.3 release 56 running Hilfe v3.5 (Incremental Pike Frontend)
gc(); _memory_usage()->num_mappings;
(1) Result: 3 (2) Result: 71
for(int i=0; i<1000; i++) compile_string("mixed x = Gmp.mpz(100);");
Ok.
gc(); _memory_usage()->num_mappings;
(3) Result: 0 (4) Result: 1071
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Previous text:
2002-09-30 12:49: Subject: Gz testsuite memory usage
Ok, now the frame_bytes are down to reasonable levels:
Doing tests in testsuite (10418 tests) NM: 56, MB: 57304, FB: 11280
Doing tests in modules/CommonLog/module_testsuite (0 tests) NM: 11763, MB: 3687851, FB: 56400
Doing tests in modules/Gdbm/module_testsuite (65 tests) NM: 11763, MB: 3687851, FB: 56400
Doing tests in modules/Gettext/module_testsuite (0 tests) NM: 11763, MB: 3688259, FB: 56400
Doing tests in modules/Gmp/module_testsuite (28743 tests) NM: 11763, MB: 3688259, FB: 56400
Doing tests in modules/Gz/module_testsuite (96 tests) NM: 39106, MB: 12004227, FB: 56400
[...]
The 12 MB mappings are still there though, and from the mapping count it looks like they are actually referenced. So somehow the Gmp testsuite is leaking mappings...
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
In fact, it seems unrelated to Gmp. It happens whenever a module is used with ".":
Pike v7.3 release 56 running Hilfe v3.5 (Incremental Pike Frontend)
gc(); _memory_usage()->num_mappings;
(1) Result: 3 (2) Result: 71
for(int i=0; i<1000; i++) compile_string("mixed x = Stdio.File();");
Ok.
gc(); _memory_usage()->num_mappings;
(3) Result: 0 (4) Result: 1071
for(int i=0; i<1000; i++) compile_string("mixed x = master()->resolv("Stdio")->File();");
Ok.
gc(); _memory_usage()->num_mappings;
(5) Result: 0 (6) Result: 1071
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Previous text:
2002-09-30 14:23: Subject: Gz testsuite memory usage
Ah-ha. Each time the compiler compiles an expression containing a literal Gmp.mpz creation, it leaks one mapping:
Pike v7.3 release 56 running Hilfe v3.5 (Incremental Pike Frontend)
gc(); _memory_usage()->num_mappings;
(1) Result: 3 (2) Result: 71
for(int i=0; i<1000; i++) compile_string("mixed x = Gmp.mpz(100);");
Ok.
gc(); _memory_usage()->num_mappings;
(3) Result: 0 (4) Result: 1071
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Interresting; as far as I can see, the only place mappings are used in the Gmp module, is in _sprintf(). My guess is that the leaked mapping is created by the compiler, and probably is used for symbol lookup cacheing.
/ Henrik Grubbström (Lysator)
Previous text:
2002-09-30 14:23: Subject: Gz testsuite memory usage
Ah-ha. Each time the compiler compiles an expression containing a literal Gmp.mpz creation, it leaks one mapping:
Pike v7.3 release 56 running Hilfe v3.5 (Incremental Pike Frontend)
gc(); _memory_usage()->num_mappings;
(1) Result: 3 (2) Result: 71
for(int i=0; i<1000; i++) compile_string("mixed x = Gmp.mpz(100);");
Ok.
gc(); _memory_usage()->num_mappings;
(3) Result: 0 (4) Result: 1071
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Yup. See 9104828. It's definitely the compiler since it makes a difference if it's the compiler that calls resolv or if you do it manually.
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Previous text:
2002-09-30 14:27: Subject: Gz testsuite memory usage
Interresting; as far as I can see, the only place mappings are used in the Gmp module, is in _sprintf(). My guess is that the leaked mapping is created by the compiler, and probably is used for symbol lookup cacheing.
/ Henrik Grubbström (Lysator)
Um, program.c line 5374:
#ifdef PIKE_DEBUG if (resolve_cache) free_mapping(resolve_cache); #endif resolve_cache = c->resolve_cache_save;
Why is there a #ifdef PIKE_DEBUG around the freeing of the old cache?
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Previous text:
2002-09-30 14:32: Subject: Gz testsuite memory usage
Yup. See 9104828. It's definitely the compiler since it makes a difference if it's the compiler that calls resolv or if you do it manually.
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Good question... Remove it.
/ Henrik Grubbström (Lysator)
Previous text:
2002-09-30 14:39: Subject: Gz testsuite memory usage
Um, program.c line 5374:
#ifdef PIKE_DEBUG if (resolve_cache) free_mapping(resolve_cache); #endif resolve_cache = c->resolve_cache_save;
Why is there a #ifdef PIKE_DEBUG around the freeing of the old cache?
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
The total size of the pike process when leaving the Gz testsuite is now 110K, as opposed to 148M before. I think reducing the memory footprint to less than one thousandth of the old one is pretty ok. :)
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Previous text:
2002-09-30 14:44: Subject: Gz testsuite memory usage
Done. (This fixed the leak, btw.)
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
Yes, that can't be bad. :)
/ Peter Bortas
Previous text:
2002-09-30 23:06: Subject: Gz testsuite memory usage
The total size of the pike process when leaving the Gz testsuite is now 110K, as opposed to 148M before. I think reducing the memory footprint to less than one thousandth of the old one is pretty ok. :)
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
I can't think of any valid reason whatsoever for doing so. PIKE_DEBUG should be side-effect free, with the exception of Pike_fatal calls, or else it'll become useless as a debug tool.
I know there are several occasions where that principle is violated, for instance you'll get a more accurate __FILE__ if you compile pike with --with-rtldebug. I think that too is wrong.
Are there any objections to this principle regarding PIKE_DEBUG? If not we can settle on it and regard the offending places as simple bugs.
/ Martin Stjernholm, Roxen IS
Previous text:
2002-09-30 14:39: Subject: Gz testsuite memory usage
Um, program.c line 5374:
#ifdef PIKE_DEBUG if (resolve_cache) free_mapping(resolve_cache); #endif resolve_cache = c->resolve_cache_save;
Why is there a #ifdef PIKE_DEBUG around the freeing of the old cache?
/ Marcus Comstedt (ACROSS) (Hail Ilpalazzo!)
pike-devel@lists.lysator.liu.se
-
Henrik Grubbstr�m (Lysator) ＠ Pike (-) developers forum -
Marcus Comstedt (ACROSS) (Hail Ilpalazzo!) ＠ Pike (-) developers forum
-
Martin Stjernholm, Roxen IS ＠ Pike developers forum
-
Peter Bortas ＠ Pike developers forum