Bug #128222 for Future-AsyncAwait: Fix some memory leaks

$ debugperl5.26.2 Build && PERL_MEM_LOG=3sc debugperl5.26.2 -Mblib t/31destroy.t 3>perlmem.log Building Future-AsyncAwait PP_AWAIT resuming SvREFCNT(awaiting) == 2 PP_AWAIT resuming SvREFCNT(returning) == 1 SvREFCNT(SvRV(f)=0x55cba46df708) == 2 before PP_LEAVEASYNC SvREFCNT(SvRV(f)=0x55cba46df708) == 2 after PP_LEAVEASYNC ok 1 - $f1 should have one ref ok 2 - Not destroyed before $fret->get ok 3 - Not destroyed after $fret->get not ok 4 - $fret should have one ref # Failed test '$fret should have one ref' # at t/31destroy.t line 40. # expected 1 references, found 2 # SV address is 0x55cba46df708 # Writing heap dump to t/31destroy-4.pmat not ok 5 - Destroyed by dropping $fret # Failed test 'Destroyed by dropping $fret' # at t/31destroy.t line 44. 1..5 # Looks like you failed 2 tests of 5. $ pmat t/31destroy-4.pmat Perl memory dumpfile from perl 5.26.2 non-threaded Heap contains 21507 objects Show quoted text
HASH(2)=Future at 0x55cba46df708 with refcount 2 size 168 bytes blessed as Future 2 values (use 'values' command to show) Show quoted text
HASH(2)=Future at 0x55cba46df708 is: ├─(via RV) the lexical $fret at depth 1 of CODE() at 0x55cba41155c0=main_cv, which is: │ └─the main code └─the referrant of REF() at 0x55cba4250158, which is: └─not found $ grep -A5 55cba4250158 perlmem.log ... new_SV: sv.c:5680:Perl_newSV: 55cba4250158 frame[0]: 0x55cba30a1e11 Perl_newSV at /home/leo/perl5/perlbrew/perls/perl-5.26.2/bin/perl5.26.2 +0x153e11 frame[1]: 0x55cba3086447 Perl_leave_adjust_stacks at /home/leo/perl5/perlbrew/perls/perl-5.26.2/bin/perl5.26.2 +0x138447 frame[2]: 0x55cba3086b4a Perl_pp_leavesub at /home/leo/perl5/perlbrew/perls/perl-5.26.2/bin/perl5.26.2 +0x138b4a ... which isn't a lot of help. -- Paul Evans

On Tue Jan 15 14:06:56 2019, PEVANS wrote: Show quoted text
$ pmat-leakreport -1 t/32memory-growth-1{,-after,-after}.pmat LEAK[2] SCALAR(UV) at 0x562bcb3e7630 LEAK[2] HASH(0) at 0x562bcb3e7b10 LEAK[2] UNDEF() at 0x562bcb3e7798 LEAK[2] HASH(2) at 0x562bcb3e7528 LEAK[2] ARRAY(0) at 0x562bcb3e7438 LEAK[2] SCALAR(UV) at 0x562bcb3e7750 LEAK[2] REF() at 0x562bcb3e76f0 LEAK[2] UNDEF() at 0x562bcb3e7738 LEAK[2] SCALAR(UV,PV) at 0x562bcaf40210 Of these: Show quoted text
HASH(2)=Future at 0x562bcb3e7528 with refcount 1 size 168 bytes blessed as Future 2 values (use 'values' command to show) Show quoted text
{ready} SCALAR(UV) at 0x562bcb3e7750 = 1 {result} REF() at 0x562bcb3e76f0 => ARRAY(0) at 0x562bcb3e7438 Show quoted text
HASH(2)=Future at 0x562bcb3e7528 is: └─the referrant of REF() at 0x562bcb3e74f8, which is: └─not found Show quoted text
SCALAR(UV) at 0x562bcb3e7630 is: └─value {Future} of HASH(8) at 0x562bca866098=stashcache, which is: └─the stash cache Show quoted text
HASH(0) at 0x562bcb3e7b10 is: └─the lexical %params at depth 1 of CODE(PP) at 0x562bcaa3fb00, which is: └─the symbol '&Test2::Event::Bail::new' Show quoted text
UNDEF() at 0x562bcb3e7798 is: └─the lexical $f1 at depth 1 of CODE(PP) at 0x562bca8b0140, which is: ├─(via RV) the lexical $code at depth 1 of CODE(PP) at 0x562bcaebc4d8, which is: │ └─the symbol '&Test::MemoryGrowth::no_growth' ├─the lexical & at depth 1 of CODE() at 0x562bca866530=main_cv, which is: │ ├─the main code │ └─the scope of CODE(PP) at 0x562bcaf70df0, which is: │ └─the symbol '&main::identity' └─the referrant of REF() at 0x562bca889fb0, which is: └─not found Show quoted text
UNDEF() at 0x562bcb3e7738 is: └─the lexical $aborted at depth 1 of CODE(PP) at 0x562bcabb40f8, which is: └─the symbol '&Test::Builder::context' Show quoted text
SCALAR(UV,PV) at 0x562bcaf40210 with refcount 1 size 65 bytes UV=139665280621664 # 0x7f065b705c60 PV="139665280621664" PVLEN 15 Show quoted text
SCALAR(UV,PV) at 0x562bcaf40210 is: └─not found 0x7f065b705c60 is plausibly the &vtbl address and -might- be leakage from my new DMD_helper.h Thus the structure is: HASH(2) at 0x562bcb3e7528 -- the leaking Future itself SCALAR(UV) at 0x562bcb3e7750 REF() at 0x562bcb3e76f0 ARRAY(0) at 0x562bcb3e7438 SCALAR(UV) at 0x562bcb3e7630 -- stash cache; probably internals? HASH(0) at 0x562bcb3e7b10 -- %params lexical; probably test noise UNDEF() at 0x562bcb3e7798 -- $f1; might be test noise? UNDEF() at 0x562bcb3e7738 -- $aborted; more test noise SCALAR(UV,PV) at 0x562bcaf40210 -- DMD_helper.h leakage? But verymuch the focus here is in finding that leaking REF() at 0x562bcb3e74f8 -- Paul Evans

On Tue Jan 15 20:16:40 2019, PEVANS wrote: Show quoted text
Huh. $ pmat-diff A1.pmat A2.pmat A B SCALAR(UV,PV) at 0x555555886ac8 SCALAR(UV,PV) at 0x555555886b88 SCALAR(UV,PV) at 0x5555558929d0 SCALAR(UV,PV) at 0x555555e7eb18 Show quoted text
SCALAR(UV,PV) at 0x5555558929d0 with refcount 1 size 65 bytes UV=140737346427792 PV="140737346427792" PVLEN 15 Show quoted text
SCALAR(UV,PV) at 0x555555e7eb18 with refcount 1 size 65 bytes UV=140737346421136 PV="140737346421136" PVLEN 15 (gdb) info symbol 140737346427792 pp_await in section .text of /home/leo/src/perl/Future-AsyncAwait/blib/arch/auto/Future/AsyncAwait/AsyncAwait.so (gdb) info symbol 140737346421136 pp_leaveasync in section .text of /home/leo/src/perl/Future-AsyncAwait/blib/arch/auto/Future/AsyncAwait/AsyncAwait.so I am highly puzzled. Why do we have an SvUV with added PV containing the addresses of either pp_await or pp_leaveasync being leaked? -- Paul Evans

OK - progress. A lot of theabove confusion about UVs pointing at pp_await or pp_leaveasync comes down to a bug in Devel::MAT::Dumper, which gets confused by the new mortal SVs that the OP_CLASS() macro allocates. When it walks the optree for SVs, it allocates these mortal SVs as a side-effect of the way OP_CLASS() is implemented on custom ops (such as the await or leaveasync nodes in the optree). This caused it to dump those extra SVs, when they weren't actually part of the heap. With the appropriate SAVETMPS/FREETMPS pair inserted, these no longer appear. Instead, a somewhat more likely leak candidate turns up: $ pmat-diff t/32memory-growth-1{,-after}.pmat A B HASH(0) at 0x5555559d10f0 UNDEF() at 0x55555640a5f0 HASH(0) at 0x555556426598 UNDEF() at 0x5555564d4280 SCALAR(UV) at 0x55555654eb68 --- 2 unique to A 3 unique to B 30190 common That SCALAR(UV). $ pmat t/32memory-growth-1-after.pmat Perl memory dumpfile from perl 5.29.8 non-threaded Heap contains 30193 objects Show quoted text
SCALAR(UV) at 0x55555654eb68 with refcount 1 size 56 bytes debug serial 461304 created at t/32memory-growth.t:25 UV=93825008986928 Show quoted text
SCALAR(UV) at 0x55555654eb68 is: └─value {Future} of HASH(9) at 0x5555559a3cb8=stashcache, which is: └─the stash cache Now this gets weirder: in the -after file: Show quoted text
HASH(9) at 0x5555559a3cb8=stashcache with refcount 1 ... but in the -before file: Show quoted text
HASH(8) at 0x5555559a3cb8=stashcache with refcount 1 ... Comparing the values of them shows a lack of "Future" in the before file. But that "before" was simply before the final iteration of the code block for pmat-diff purposes. The code had been run many many times before that, and apparently the value was missing. Something, it seems, is removing values from the stash cache. -- Paul Evans

Further adjustment, capturing the heap before running the main count of iterations, and upping the count to 100k iterations, I now get: not ok 1 - async/await does not grow memory # Failed test 'async/await does not grow memory' # at t/32memory-growth.t line 31. # Lost 3108864 bytes of memory over 100000 calls, average of 31.09 per call # Writing heap dump to t/32memory-growth-1.pmat # Writing heap dump after one more iteration to t/32memory-growth-1-after.pmat # Tests were run but no plan was declared and done_testing() was not seen. It's very definitely leaking - I suspect the number to be around 32bytes per call give or take block-sized rounding. $ pmat-counts t/32memory-growth-1{-prior,-after}.pmat t/32memory-growth-1-prior.pmat Kind Count (blessed) Bytes (blessed) ARRAY 1751 2 238.2 KiB 224 bytes CODE 1940 303.1 KiB GLOB 2939 528.1 KiB HASH 333 8 385.7 KiB 3.4 KiB INVLIST 66 56.2 KiB IO 12 12 2.2 KiB 2.2 KiB PAD 1225 221.9 KiB REF 1249 68.3 KiB REGEXP 207 3 51.8 KiB 768 bytes SCALAR 20322 1.4 MiB STASH 188 205.7 KiB ------- ----- --------- --------- --------- (total) 30232 25 3.4 MiB 6.6 KiB t/32memory-growth-1-after.pmat Kind Count (blessed) Bytes (blessed) ARRAY 1752(+1) 2 239.1 KiB(+920 bytes) 224 bytes CODE 1940 303.1 KiB GLOB 2961(+22) 532.1 KiB(+4.0 KiB) HASH 334(+1) 8 384.9 KiB(-769 bytes) 3.5 KiB(+48 bytes) INVLIST 66 56.2 KiB IO 12 12 2.2 KiB 2.2 KiB PAD 1225 221.9 KiB REF 1252(+3) 68.5 KiB(+168 bytes) REGEXP 207 3 51.8 KiB 768 bytes SCALAR 20278(-44) 1.4 MiB(-886 bytes) STASH 188 206.4 KiB(+760 bytes) ------- ---------- --------- --------------------- -------------------- (total) 30215(-17) 25 3.5 MiB(+4.1 KiB) 6.7 KiB(+48 bytes) Using a mere 4.1KiB more memory in 17 fewer SVs after 100k iterations. I suspect this remaining leak is not at the perl SV level, but at the C malloc level. -- Paul Evans

This seems to be resolved now. Any newly discovered leaks can get their own bug tickets. -- Paul Evans