Skip Menu |

This queue is for tickets about the Future-AsyncAwait CPAN distribution.

Report information
The Basics
Id: 128176
Status: resolved
Priority: 0/
Queue: Future-AsyncAwait
People
Owner: Nobody in particular
Requestors: leonerd-cpan [...] leonerd.org.uk
Cc:
AdminCc:
Bug Information
Severity: (no value)
Broken in: 0.18
Fixed in: 0.19

History Show all quoted text
  Sat Jan 05 20:40:09 2019 leonerd-cpan [...] leonerd.org.uk - Ticket created
Subject: Out of memory! / Assertion `SvTYPE(TARG) == SVt_PVAV' failed
Unsure the root cause, but the reproduction case is found in an async/await-modified version of Device::Chip::SSD1306 $ ./Build && perl -Mblib examples/ssd1306.pl -A BusPirate:serial=/dev/ttyACM1 -i SPI4 -M dc=AUX Building Device-Chip-SSD1306 Out of memory! Out of memory! $ ./Build && debugperl -Mblib examples/ssd1306.pl -A BusPirate:serial=/dev/ttyACM1 -i SPI4 -M dc=AUX Building Device-Chip-SSD1306 debugperl: pp_hot.c:1854: Perl_pp_padav: Assertion `SvTYPE(TARG) == SVt_PVAV' failed. Aborted I suspect debugging this will require more debug trace support in Future/AsyncAwait.xs which I ought to be adding sometime soon, to work out when it happens. -- Paul Evans
  Sat Jan 05 21:32:29 2019 leonerd-cpan [...] leonerd.org.uk - Correspondence added
$ ./Build && perl -Mblib examples/ssd1306.pl -A BusPirate:serial=/dev/ttyACM1 -i SPI4 -M dc=AUX Building Device-Chip-SSD1306 ENTER await curcv=0x55d13e027f08 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] SUSPEND cloned CV->0x55d13e4ac390 LEAVE await curcv=0x55d13e4ac390 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] ENTER await curcv=0x55d13e032a88 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:274] SUSPEND cloned CV->0x55d13e4ac270 LEAVE await curcv=0x55d13e4ac270 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:274] ENTER await curcv=0x55d13e0334a8 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] SUSPEND cloned CV->0x55d13e4abd00 LEAVE await curcv=0x55d13e4abd00 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] ENTER await curcv=0x55d13e4ac390 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] RESUME READY LEAVE await curcv=0x55d13e4ac390 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] ENTER await curcv=0x55d13e4ac270 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:274] RESUME READY LEAVE await curcv=0x55d13e4ac270 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:274] ENTER await curcv=0x55d13e4abd00 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] RESUME READY LEAVE await curcv=0x55d13e4abd00 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] ENTER await curcv=0x55d13e027f08 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] SUSPEND cloned CV->0x55d13e4b3160 LEAVE await curcv=0x55d13e4b3160 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] ENTER await curcv=0x55d13e4abd00 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] SUSPEND reuse CV LEAVE await curcv=0x55d13e4abd00 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] Out of memory! ENTER await curcv=0x55d13e027f08 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] SUSPEND cloned CV->0x55d13e4a4f00 LEAVE await curcv=0x55d13e4a4f00 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] ENTER await curcv=0x55d13e032a88 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:274] SUSPEND cloned CV->0x55d13e49ee98 LEAVE await curcv=0x55d13e49ee98 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:274] Out of memory! $ ./Build && debugperl -Mblib examples/ssd1306.pl -A BusPirate:serial=/dev/ttyACM1 -i SPI4 -M dc=AUX Building Device-Chip-SSD1306 ENTER await curcv=0x55e8b2a4c428 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] SUSPEND cloned CV->0x55e8b2f0e168 LEAVE await curcv=0x55e8b2f0e168 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] ENTER await curcv=0x55e8b2a4c590 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:274] SUSPEND cloned CV->0x55e8b2f0e048 LEAVE await curcv=0x55e8b2f0e048 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:274] ENTER await curcv=0x55e8b2a4cfb0 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] SUSPEND cloned CV->0x55e8b2f0c330 LEAVE await curcv=0x55e8b2f0c330 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] ENTER await curcv=0x55e8b2f0e168 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] RESUME READY LEAVE await curcv=0x55e8b2f0e168 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] ENTER await curcv=0x55e8b2f0e048 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:274] RESUME READY LEAVE await curcv=0x55e8b2f0e048 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:274] ENTER await curcv=0x55e8b2f0c330 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] RESUME READY LEAVE await curcv=0x55e8b2f0c330 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] ENTER await curcv=0x55e8b2a4c428 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] SUSPEND cloned CV->0x55e8b2f171d8 LEAVE await curcv=0x55e8b2f171d8 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306/SPI4.pm:80] ENTER await curcv=0x55e8b2f0c330 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] SUSPEND reuse CV LEAVE await curcv=0x55e8b2f0c330 [/home/leo/src/perl/Device-Chip-SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] debugperl: pp_hot.c:1854: Perl_pp_padav: Assertion `SvTYPE(TARG) == SVt_PVAV' failed. Aborted -- Paul Evans
  Sat Jan 05 21:46:55 2019 leonerd-cpan [...] leonerd.org.uk - Correspondence added
On Sat Jan 05 21:32:29 2019, PEVANS wrote: Show quoted text
> SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] > SUSPEND reuse CV > LEAVE await curcv=0x55d13e4abd00 [/home/leo/src/perl/Device-Chip- > SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] > Out of memory!
and Show quoted text
> SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] > SUSPEND reuse CV > LEAVE await curcv=0x55e8b2f0c330 [/home/leo/src/perl/Device-Chip- > SSD1306/blib/lib/Device/Chip/SSD1306.pm:246] > debugperl: pp_hot.c:1854: Perl_pp_padav: Assertion `SvTYPE(TARG) == > SVt_PVAV' failed. > Aborted
suggesting that this is a problem relating to a second 'await' inside an 'async sub'; somehow the internal state of the PAD or such is getting upset. The function in question: async sub init { my $self = shift; await $self->display( 0 ); await $self->send_cmd( CMD_SET_CLOCKDIV, ( 8 << 4 ) | 0x80 ); await $self->send_cmd( CMD_SET_MUX_RATIO, $self->rows - 1 ); await $self->send_cmd( CMD_SET_DISPLAY_OFFS, 0 ); await $self->send_cmd( CMD_SET_DISPLAY_START | 0 ); await $self->send_cmd( CMD_SET_CHARGEPUMP, 0x14 ); await $self->send_cmd( CMD_SET_ADDR_MODE, MODE_HORIZONTAL ); await $self->send_cmd( CMD_SET_SEGMENT_REMAP | ( $self->{xflip} ? 1 : 0 ) ); await $self->send_cmd( CMD_SET_COM_SCAN_DIR | ( $self->{yflip} ? 1<<3 : 0 ) ); await $self->send_cmd( CMD_SET_COM_PINS, $self->{set_com_pins_arg} ); await $self->send_cmd( CMD_SET_CONTRAST, 0x9F ); await $self->send_cmd( CMD_SET_PRECHARGE, ( 0x0f << 4 ) | ( 1 ) ); await $self->send_cmd( CMD_SET_VCOMH_LEVEL, ( 4 << 4 ) ); } So yes, indeed many `await`s. -- Paul Evans
  Sun Jan 06 16:06:32 2019 leonerd-cpan [...] leonerd.org.uk - Correspondence added
A minimal test case turns out to be remarkably simple -- Paul Evans
Subject: rt128176.t
#!/usr/bin/perl use strict; use warnings; use Test::More; use Future; use Future::AsyncAwait; my @f; sub set_dc { push @f, my $f = Future->new; return $f; } sub readwrite { Future->done( $_[0] ) } # Inspired by Device::Chip::SSD1306::SPI4::send_cmd async sub send_cmd { my $self = shift; my @vals = @_; await set_dc(); await readwrite( join "", map { chr } @vals ); } # Inspired by Device::Chip::SSD1306::init async sub init { my $self = shift; await $self->send_cmd( 1, 2 ); await $self->send_cmd( 3, 4 ); } { my $f = __PACKAGE__->init; # Pump Futures ( shift @f )->done() while @f; $f->get; } done_testing;
  Sun Jan 06 20:29:19 2019 leonerd-cpan [...] leonerd.org.uk - Correspondence added
On Sun Jan 06 16:06:32 2019, PEVANS wrote: Show quoted text
> A minimal test case turns out to be remarkably simple
Some further observations: debugperl: pp_hot.c:1854: Perl_pp_padav: Assertion `SvTYPE(TARG) == SVt_PVAV' failed. Program received signal SIGABRT, Aborted. (gdb) p *my_perl->Icurcop $3 = {op_next = 0x55555600a868, op_sibparent = 0x55555600a7e8, op_ppaddr = 0x555555698d80 <Perl_pp_nextstate>, op_targ = 0, op_type = 195, op_opt = 1, op_slabbed = 1, op_savefree = 0, op_static = 0, op_folded = 0, op_moresib = 1, op_spare = 0, op_flags = 1 '\001', op_private = 0 '\000', cop_line = 24, cop_stashoff = 63, cop_file = 0x555555cf1f90 "t/rt128176.t", cop_hints = 133090, cop_seq = 6672, cop_warnings = 0x8, cop_hints_hash = 0x555556101a00} (gdb) p *my_perl->Iop $4 = {op_next = 0x55555600aa28, op_sibparent = 0x55555600aa28, op_ppaddr = 0x55555569df70 <Perl_pp_padav>, op_targ = 2, op_type = 10, op_opt = 1, op_slabbed = 1, op_savefree = 0, op_static = 0, op_folded = 0, op_moresib = 0, op_spare = 0, op_flags = 35 '#', op_private = 0 '\000'} So, op_targ == 2, that's the padix of the hoped-for AV that isn't. I suspect I'll be wanting some pad-printing code in F/AA.xs; but for now that looks to be the correct op at least. I suspect this op is the one trying to get @vals out of the pad, and failing because the pad contents are incorrect. More debug prints required... -- Paul Evans
  Tue Jan 08 11:30:21 2019 leonerd-cpan [...] leonerd.org.uk - Correspondence added
Exciting times When the CV is first cloned, the pad looks just fine: t/rt128176.t .. ENTER await curcv=0x55cdc946e950 [t/rt128176.t:23] Pad of original CV for clone: CV=0x55cdc946e950, CvDEPTH=1, PAD at depth=0x55cdc93c8358 pad[ 0]: name=< (null)> sv=0x55cdc92d7288{PVAV,refcnt=2} pad[ 1]: name=< $self> sv=0x55cdc92d6d90{PV,refcnt=1} pad[ 2]: name=< @vals> sv=0x55cdc92d6e38{PVAV,refcnt=1} ... Pad of newly cloned CV: CV=0x55cdc946e950, CvDEPTH=1, PAD at depth=0x55cdc93c8358 pad[ 0]: name=< (null)> sv=0x55cdc92d7288{PVAV,refcnt=2} pad[ 1]: name=< $self> sv=0x55cdc92d6d90{PV,refcnt=1} pad[ 2]: name=< @vals> sv=0x55cdc92d6e38{PVAV,refcnt=1} ... SUSPEND cloned CV->0x55cdc94b2320 LEAVE await curcv=0x55cdc94b2320 [t/rt128176.t:23] indeed pad[2] is a PVAV as we'd expect. It later gets resumed and all is still good: ENTER await curcv=0x55cdc94b2320 [t/rt128176.t:23] RESUME Pad of pad after resume: CV=0x55cdc94b2320, CvDEPTH=1, PAD at depth=0x55cdc92d7318 pad[ 0]: name=< (null)> sv=0x55cdc8d9c090{PVAV,refcnt=2} pad[ 1]: name=< $self> sv=0x55cdc92d6d90{PV,refcnt=1} pad[ 2]: name=< @vals> sv=0x55cdc92d6e38{PVAV,refcnt=1} ... READY LEAVE await curcv=0x55cdc94b2320 [t/rt128176.t:23] but then when we clone it a second time for the second await, the SV at padix 2 has become an IV: ENTER await curcv=0x55cdc946e950 [t/rt128176.t:23] Pad of original CV for clone: CV=0x55cdc946e950, CvDEPTH=1, PAD at depth=0x55cdc93c8358 pad[ 0]: name=< (null)> sv=0x55cdc92d7288{PVAV,refcnt=2} pad[ 1]: name=< $self> sv=0x55cdc94b2710{PV,refcnt=1} pad[ 2]: name=< @vals> sv=0x55cdc94b2728{IV,refcnt=1} ... whereupon it remains until getting resumed and continuing from that point, eventually hitting the OP_PADAV op which fails to fetch this slot, and aborts. -- Paul Evans
  Tue Jan 08 13:01:02 2019 leonerd-cpan [...] leonerd.org.uk - Correspondence added
Further discoveries: pad slot [2] appears to contain what was actually the first @_ value after the shift. After editing line 33 of the .t file to be await $self->send_cmd( "three", 4 ); I now get: ... ENTER await curcv=0x56363d2f3e78 [t/rt128176.t:23] Pad of original CV for clone: CV=0x56363d2f3e78, CvDEPTH=1, PAD at depth=0x56363d2dc5e0 pad[ 0]: name=< (null)> sv=0x56363d2f4418{PVAV,refcnt=2} pad[ 1]: name=< $self> sv=0x56363d2f3fc8{PV,refcnt=1} pad[ 2]: name=< @vals> sv=0x56363d322400{PV,refcnt=1} PAD[2] expected to be SVt_PVAV but isn't Aborted leo@shy:~/src/perl/Future-AsyncAwait [bzr] $ pmat xperl.pmat Perl memory dumpfile from perl 5.28.0 Heap contains 21685 objects Show quoted text
pmat> identify 0x56363d322400
SCALAR(PV) at 0x56363d322400 is: └─the lexical @vals at depth 1 of CODE(PP) at 0x56363d2f3e78, which is: └─the symbol '&main::send_cmd' Show quoted text
pmat> show 0x56363d322400
SCALAR(PV) at 0x56363d322400 with refcount 1 size 50 bytes PV="three" PVLEN 5 (various editing of the source code shows this PV correlates with the argument; it doesn't appear to have come from elsewhere) -- Paul Evans
  Tue Jan 08 17:51:28 2019 leonerd-cpan [...] leonerd.org.uk - Correspondence added
Further debug with a custom runops loop finds the exact op at which the SvTYPE()==SVt_PVAV invariant is broken. Expected @vars to be SVt_PVAV, got 0x560d13666030{PV,refcnt=1} PLCK failed at PL_op=0x560d135a7310 [aassign] CopFILE=<t/rt128176.t> CopLINE=21 21 my @vals = @_; Which does feel like a plausible place for this to be breaking. I wonder why `aassign` is overwriting the pad slot itself though. -- Paul Evans
  Tue Jan 08 18:26:54 2019 leonerd-cpan [...] leonerd.org.uk - Correspondence added
Turns out that OP_AASSIGN does a variety of different jobs; e.g. it does both of @arr = (...) ($x, $y) = (...) The way it can distinguish, is whether the final item on the stack is an SVt_PVAV or not. This means that all pad slots relating to arrays (or hashes) have to always be SVt_PVAV (or SVt_PVHV) types, even when empty. This means when we steal pad SVs during suspend, we have to replace arrays and hashes with newAV() / newHV() respectively. Patch attached. -- Paul Evans
Subject: rt128176.patch
=== modified file 'lib/Future/AsyncAwait.xs' --- lib/Future/AsyncAwait.xs 2019-01-08 23:18:23 +0000 +++ lib/Future/AsyncAwait.xs 2019-01-08 23:26:25 +0000 @@ -818,7 +818,20 @@ /* Don't fiddle refcount */ state->padslots[i-1] = PadARRAY(pad)[i]; - PadARRAY(pad)[i] = newSV(0); + switch(PadnamePV(pname)[0]) { + case '@': + PadARRAY(pad)[i] = MUTABLE_SV(newAV()); + break; + case '%': + PadARRAY(pad)[i] = MUTABLE_SV(newHV()); + break; + case '$': + PadARRAY(pad)[i] = newSV(0); + break; + default: + panic("TODO: unsure how to steal and switch pad slot with pname %s\n", + PadnamePV(pname)); + } } dounwind(cxix);
  Tue Jan 08 18:26:55 2019 leonerd-cpan [...] leonerd.org.uk - Status changed from 'new' to 'patched'
  Wed Jan 09 07:40:28 2019 leonerd-cpan [...] leonerd.org.uk - Correspondence added
Released in 0.19 -- Paul Evans
  Wed Jan 09 07:40:28 2019 leonerd-cpan [...] leonerd.org.uk - Status changed from 'patched' to 'resolved'
  Wed Jan 09 07:40:29 2019 leonerd-cpan [...] leonerd.org.uk - Fixed in 0.19 added