Intermittent failure when running S17-supply/return-in-tap.t

[dogbert17]

Noticed this a couple a days ago when doing a spectest run. The problem doesn't occur very often, which is probably why it has slipped through the cracks. The easiest way to reproduce the error is to run, e.g.

while ./perl6 --ll-exception t/spec/S17-supply/return-in-tap.t; do :; done

A run will typically look like this

dogbert@dogbert-VirtualBox ~/repos/rakudo $ ./perl6 -v
This is Rakudo version 2019.03.1-664-g2dc68c9 built on MoarVM version 2019.05-95-g065b2b4
implementing Perl 6.d.
dogbert@dogbert-VirtualBox ~/repos/rakudo $ while ./perl6 --ll-exception t/spec/S17-supply/return-in-tap.t; do :; done
1..1
ok 1 - return in a Supply quit handler works fine
1..1
ok 1 - return in a Supply quit handler works fine
1..1
ok 1 - return in a Supply quit handler works fine
1..1
... [a few or sometimes many iterations skipped]
ok 1 - return in a Supply quit handler works fine
1..1
Cannot find method 'sink' on 'BOOTCode': no method cache and no .^find_method
   at t/spec/S17-supply/return-in-tap.t:30  (<ephemeral file>:)
 from t/spec/S17-supply/return-in-tap.t:29  (<ephemeral file>:<unit>)
 from t/spec/S17-supply/return-in-tap.t:1  (<ephemeral file>:<unit-outer>)
 from gen/moar/stage2/NQPHLL.nqp:1835  (/home/dogbert/repos/rakudo/install/share/nqp/lib/NQPHLL.moarvm:eval)
 from gen/moar/stage2/NQPHLL.nqp:2039  (/home/dogbert/repos/rakudo/install/share/nqp/lib/NQPHLL.moarvm:evalfiles)
 from gen/moar/stage2/NQPHLL.nqp:1999  (/home/dogbert/repos/rakudo/install/share/nqp/lib/NQPHLL.moarvm:command_eval)
 from src/Perl6/Compiler.nqp:52  (/home/dogbert/repos/rakudo/blib/Perl6/Compiler.moarvm:command_eval)
 from gen/moar/stage2/NQPHLL.nqp:1924  (/home/dogbert/repos/rakudo/install/share/nqp/lib/NQPHLL.moarvm:command_line)
 from gen/moar/main.nqp:82  (/home/dogbert/repos/rakudo/perl6.moarvm:MAIN)
 from gen/moar/main.nqp:47  (/home/dogbert/repos/rakudo/perl6.moarvm:<mainline>)
 from <unknown>:1  (/home/dogbert/repos/rakudo/perl6.moarvm:<main>)
 from <unknown>:1  (/home/dogbert/repos/rakudo/perl6.moarvm:<entry>)

Using gdb and some clever tricks from timotimo++ reveals the following

Thread 1 "moar" hit Breakpoint 1, MVM_6model_find_method (tc=0x604a70, obj=0x35bd200, name=0x3880b30, res=0x3365aa8, throw_if_not_found=1) at src/6model/6model.c:137
137	            char *c_name  = MVM_string_utf8_encode_C_string(tc, name);
(gdb) bt
#0  MVM_6model_find_method (tc=0x604a70, obj=0x35bd200, name=0x3880b30, res=0x3365aa8, throw_if_not_found=1) at src/6model/6model.c:137
#1  0x00007ffff7504664 in MVM_interp_run (tc=0x604a70, initial_invoke=0x7ffff767f1d6 <toplevel_initial_invoke>, invoke_data=0x6a1888) at src/core/interp.c:1822
#2  0x00007ffff767f33b in MVM_vm_run_file (instance=0x604010, filename=0x7fffffffe1b5 "/home/dogbert/repos/rakudo/perl6.moarvm") at src/moar.c:444
#3  0x00000000004016e7 in main (argc=10, argv=0x7fffffffdd38) at src/main.c:302
(gdb) info threads
  Id   Target Id         Frame 
* 1    Thread 0x7ffff7fdb700 (LWP 3211) "moar" MVM_6model_find_method (tc=0x604a70, obj=0x35bd200, name=0x3880b30, res=0x3365aa8, throw_if_not_found=1) at src/6model/6model.c:137
  2    Thread 0x7ffff621c700 (LWP 3212) "moar" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
(gdb) f 1
#1  0x00007ffff7504664 in MVM_interp_run (tc=0x604a70, initial_invoke=0x7ffff767f1d6 <toplevel_initial_invoke>, invoke_data=0x6a1888) at src/core/interp.c:1822
1822	                MVM_6model_find_method(tc, obj, name, res, 1);
(gdb) l
1817	                /* Increment PC first, as we may make a method call. */
1818	                MVMRegister *res  = &GET_REG(cur_op, 0);
1819	                MVMObject   *obj  = GET_REG(cur_op, 2).o;
1820	                MVMString   *name = MVM_cu_string(tc, cu, GET_UI32(cur_op, 4));
1821	                cur_op += 8;
1822	                MVM_6model_find_method(tc, obj, name, res, 1);
1823	                goto NEXT;
1824	            }
1825	            OP(findmeth_s):  {
1826	                /* Increment PC first, as we may make a method call. */
(gdb) p name
$1 = (MVMString *) 0x3880b30
(gdb) p *name
$2 = {common = {header = {sc_forward_u = {forwarder = 0x0, sc = {sc_idx = 0, idx = 0}, st = 0x0}, owner = 1, flags = 16, size = 48}, st = 0x66dc60}, body = {storage = {blob_32 = 0x3875860, blob_ascii = 0x3875860 "sink\377\177", blob_8 = 0x3875860 "sink\377\177", strands = 0x3875860, any = 0x3875860}, storage_type = 2, num_strands = 0, num_graphs = 4, cached_hash_code = 2038966319858089314}}
(gdb) f 0
#0  MVM_6model_find_method (tc=0x604a70, obj=0x35bd200, name=0x3880b30, res=0x3365aa8, throw_if_not_found=1) at src/6model/6model.c:137
137	            char *c_name  = MVM_string_utf8_encode_C_string(tc, name);
(gdb) p MVM_dump_bytecode(tc)
00000      checkarity         1, 1
00001      param_rp_o         loc_0_obj, 0
00002      paramnamesused     
     annotation: t/spec/S17-supply/return-in-tap.t:30
00003      const_s            loc_1_str, '&try-it'
00004      getlexstatic_o     loc_2_obj, loc_1_str
00005      decont             loc_2_obj, loc_2_obj
00006      prepargs           Callsite_2
00007      invoke_o           loc_2_obj, loc_2_obj
00008   -> decont             loc_4_obj, loc_2_obj
00009      findmeth           loc_3_obj, loc_4_obj, 'sink'
00010      prepargs           Callsite_0
00011      arg_o              0, loc_2_obj
00012      invoke_o           loc_3_obj, loc_3_obj
00013      return_o           loc_3_obj
$3 = 

Manual bisection points towards rakudo/rakudo@8d65276 being the change which introduced this behavior.

btw, it should also be noted that if the test is run with MVM_SPESH_DISABLE=1 the problem goes away.

[dogbert17]

Still present in:
This is Rakudo version 2020.02-27-gcb7be78cd built on MoarVM version 2020.02

[dogbert17]

Still present in:
This is Rakudo version 2020.09-3-gf74950c51 built on MoarVM version 2020.09-3-gcd8e18280

[dogbert17]

Still present in:

Welcome to Rakudo(tm) v2021.03-113-gdfae76010. Built on MoarVM version 2021.03-24-g1538f98da