Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

when start()ing several times in a loop #5714

Closed
p6rt opened this issue Oct 1, 2016 · 11 comments
Closed

when start()ing several times in a loop #5714

p6rt opened this issue Oct 1, 2016 · 11 comments

Comments

@p6rt
Copy link

@p6rt p6rt commented Oct 1, 2016

Migrated from rt.perl.org#129781 (status was 'resolved')

Searchable as RT129781$

@p6rt
Copy link
Author

@p6rt p6rt commented Oct 1, 2016

From @MasterDuke17

await (for ^7 { start �/etc/hostname�.IO ~~ :e })

regular perl6-valgrind-m output here​:
https://gist.github.com/MasterDuke17/9ab9ec5bdbc483bfe63213bf26f82316

with --leak-check=full and --trace-children=yes here​:
https://gist.github.com/MasterDuke17/e47e797da08f6bfe57491ca973703698

@p6rt
Copy link
Author

@p6rt p6rt commented Oct 1, 2016

From @nwc10

On Sat, Oct 01, 2016 at 08​:14​:16AM -0700, Daniel Green wrote​:

# New Ticket Created by Daniel Green
# Please include the string​: [perl #​129781]
# in the subject line of all future correspondence about this issue.
# <URL​: https://rt-archive.perl.org/perl6/Ticket/Display.html?id=129781 >

await (for ^7 { start �/etc/hostname�.IO ~~ :e })

regular perl6-valgrind-m output here​:
https://gist.github.com/MasterDuke17/9ab9ec5bdbc483bfe63213bf26f82316

Nice catch. ASAN has fun​:

$ ./perl6-m -Ilib -e 'await (for ^7 { start �/etc/hostname�.IO ~~ :e })'

==9674==ERROR​: AddressSanitizer​: attempting double-free on 0x603000381040 in thread T4​:
  #​0 0x7fb46d651417 in __interceptor_free ../../.././libsanitizer/asan/asan_malloc_linux.cc​:62
  #​1 0x7fb46cc99075 in MVM_free src/core/alloc.h​:29
  #​2 0x7fb46cca388b in MVM_string_flatten src/strings/ops.c​:1241
  #​3 0x7fb46ca027ef in MVM_interp_run src/core/interp.c​:1601
  #​4 0x7fb46ca9776a in start_thread src/core/threads.c​:77
  #​5 0x7fb46cd6152d in uv__thread_start 3rdparty/libuv/src/unix/thread.c​:49
  #​6 0x7fb46bdcfaa0 in start_thread (/lib64/libpthread.so.0+0x7aa0)
  #​7 0x7fb46c2d5aac in __clone (/lib64/libc.so.6+0xe8aac)

0x603000381040 is located 0 bytes inside of 24-byte region [0x603000381040,0x603000381058)
freed by thread T1 here​:
  #​0 0x7fb46d651417 in __interceptor_free ../../.././libsanitizer/asan/asan_malloc_linux.cc​:62
  #​1 0x7fb46cc99075 in MVM_free src/core/alloc.h​:29
  #​2 0x7fb46cca388b in MVM_string_flatten src/strings/ops.c​:1241
  #​3 0x7fb46ca027ef in MVM_interp_run src/core/interp.c​:1601
  #​4 0x7fb46ca9776a in start_thread src/core/threads.c​:77
  #​5 0x7fb46cd6152d in uv__thread_start 3rdparty/libuv/src/unix/thread.c​:49
  #​6 0x7fb46bdcfaa0 in start_thread (/lib64/libpthread.so.0+0x7aa0)

previously allocated by thread T0 here​:
  #​0 0x7fb46d65162f in __interceptor_malloc ../../.././libsanitizer/asan/asan_malloc_linux.cc​:72
  #​1 0x7fb46cc98fef in MVM_malloc src/core/alloc.h​:2
  #​2 0x7fb46cc9b63c in allocate_strands src/strings/ops.c​:27
  #​3 0x7fb46cc9d384 in MVM_string_substring src/strings/ops.c​:294
  #​4 0x7fb46c9feb14 in MVM_interp_run src/core/interp.c​:1467
  #​5 0x7fb46ccf5bf4 in MVM_vm_run_file src/moar.c​:304
  #​6 0x401a4f in main src/main.c​:191
  #​7 0x7fb46c20bd1c in __libc_start_main (/lib64/libc.so.6+0x1ed1c)

Thread T4 created by T0 here​:
  #​0 0x7fb46d6206ea in __interceptor_pthread_create ../../.././libsanitizer/asan/asan_interceptors.cc​:183
  #​1 0x7fb46cd61632 in uv_thread_create 3rdparty/libuv/src/unix/thread.c​:66
  #​2 0x7fb46ca97b1b in MVM_thread_run src/core/threads.c​:129
  #​3 0x7fb46ca3b0a1 in MVM_interp_run src/core/interp.c​:3964
  #​4 0x7fb46ccf5bf4 in MVM_vm_run_file src/moar.c​:304
  #​5 0x401a4f in main src/main.c​:191
  #​6 0x7fb46c20bd1c in __libc_start_main (/lib64/libc.so.6+0x1ed1c)

Thread T1 created by T0 here​:
  #​0 0x7fb46d6206ea in __interceptor_pthread_create ../../.././libsanitizer/asan/asan_interceptors.cc​:183
  #​1 0x7fb46cd61632 in uv_thread_create 3rdparty/libuv/src/unix/thread.c​:66
  #​2 0x7fb46ca97b1b in MVM_thread_run src/core/threads.c​:129
  #​3 0x7fb46ca3b0a1 in MVM_interp_run src/core/interp.c​:3964
  #​4 0x7fb46ccf5bf4 in MVM_vm_run_file src/moar.c​:304
  #​5 0x401a4f in main src/main.c​:191
  #​6 0x7fb46c20bd1c in __libc_start_main (/lib64/libc.so.6+0x1ed1c)

SUMMARY​: AddressSanitizer​: double-free ../../.././libsanitizer/asan/asan_malloc_linux.cc​:62 __interceptor_free
==9674==ABORTING

Nicholas Clark

@p6rt
Copy link
Author

@p6rt p6rt commented Oct 1, 2016

The RT System itself - Status changed from 'new' to 'open'

@p6rt
Copy link
Author

@p6rt p6rt commented Oct 2, 2016

From @AlexDaniel

Surprisingly, this snippet is also buggy (but not segfaulty)​:

await (for ^7 { start say ‘/etc/hostname’.IO })

Note that we are not doing any actual file checks here, just creating an .IO object.

Running that program in an infinite loop (just wrap it in while :; do perl6 -e '…'; done ) will give you something like this​:

"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
Cannot invoke this object (REPR​: Null; VMNull)
  in block <unit> at -e line 1

"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO

Oops, Null!

@p6rt
Copy link
Author

@p6rt p6rt commented Oct 2, 2016

From @MasterDuke17

On Sun Oct 02 09​:59​:20 2016, alex.jakimenko@​gmail.com wrote​:

Surprisingly, this snippet is also buggy (but not segfaulty)​:

await (for ^7 { start say �/etc/hostname�.IO })

Note that we are not doing any actual file checks here, just creating
an .IO
object.

Running that program in an infinite loop (just wrap it in while :; do
perl6 -e
'â�¦'; done) will give you something like this​:

"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
Cannot invoke this object (REPR​: Null; VMNull)
in block <unit> at -e line 1

"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO

Oops, Null!

The valgrind output looks similar​:

This is Rakudo Perl 6 running in valgrind, a tool for debugging and profiling programs.
Running a program in valgrind usually takes *a lot* more time than running it directly,
so please be patient.
This Rakudo version is 2016.09.100.g.46.e.0.ede built on MoarVM version 2016.09.15.gc.8.b.4228,
running on arch (4.7.3.1.arch) / linux (4.7.4.1.ARCH)


==14799== Memcheck, a memory error detector
==14799== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==14799== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==14799== Command​: /home/dan/Source/perl6/install/bin/moar --full-cleanup --execname=./install/bin/perl6-valgrind-m --libpath=/home/dan/Source/perl6/install/share/nqp/lib --libpath=/home/dan/Source/perl6/install/share/perl6/lib --libpath=/home/dan/Source/perl6/install/share/perl6/runtime /home/dan/Source/perl6/install/share/perl6/runtime/perl6.moarvm -e await\ (for\ ^7\ {\ start\ say\ â��/etc/hostnameâ��.IO\ })
==14799==
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
==14799==
==14799== Process terminating with default action of signal 6 (SIGABRT)​: dumping core
==14799== at 0x54EF04F​: raise (in /usr/lib/libc-2.24.so)
==14799== by 0x54F0479​: abort (in /usr/lib/libc-2.24.so)
==14799== by 0x507B366​: uv_mutex_destroy (thread.c​:114)
==14799== by 0x4FFEDA1​: gc_free (ConcBlockingQueue.c​:72)
==14799== by 0x4FCC0C4​: MVM_gc_collect_free_nursery_uncopied (collect.c​:580)
==14799== by 0x4FC8B46​: MVM_gc_global_destruction (orchestrate.c​:511)
==14799== by 0x505CDF1​: MVM_vm_destroy_instance (moar.c​:391)
==14799== by 0x400D2D​: main (main.c​:194)
==14799==
==14799== HEAP SUMMARY​:
==14799== in use at exit​: 74,702,706 bytes in 168,549 blocks
==14799== total heap usage​: 219,362 allocs, 50,813 frees, 88,708,939 bytes allocated
==14799==
==14799== LEAK SUMMARY​:
==14799== definitely lost​: 10,398 bytes in 187 blocks
==14799== indirectly lost​: 22,368 bytes in 668 blocks
==14799== possibly lost​: 394,608 bytes in 7,033 blocks
==14799== still reachable​: 74,275,332 bytes in 160,661 blocks
==14799== suppressed​: 0 bytes in 0 blocks
==14799== Rerun with --leak-check=full to see details of leaked memory
==14799==
==14799== For counts of detected and suppressed errors, rerun with​: -v
==14799== ERROR SUMMARY​: 0 errors from 0 contexts (suppressed​: 0 from 0)

@p6rt
Copy link
Author

@p6rt p6rt commented Oct 3, 2016

From @MasterDuke17

On Sun Oct 02 13​:57​:34 2016, ddgreen@​gmail.com wrote​:

On Sun Oct 02 09​:59​:20 2016, alex.jakimenko@​gmail.com wrote​:

Surprisingly, this snippet is also buggy (but not segfaulty)​:

await (for ^7 { start say �/etc/hostname�.IO })

Note that we are not doing any actual file checks here, just creating
an .IO
object.

Running that program in an infinite loop (just wrap it in while :; do
perl6 -e
'â�¦'; done) will give you something like this​:

"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
Cannot invoke this object (REPR​: Null; VMNull)
in block <unit> at -e line 1

"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO

Oops, Null!

The valgrind output looks similar​:

This is Rakudo Perl 6 running in valgrind, a tool for debugging and
profiling programs.
Running a program in valgrind usually takes *a lot* more time than
running it directly,
so please be patient.
This Rakudo version is 2016.09.100.g.46.e.0.ede built on MoarVM
version 2016.09.15.gc.8.b.4228,
running on arch (4.7.3.1.arch) / linux (4.7.4.1.ARCH)
------------------------------------------------------------------------------------------------
==14799== Memcheck, a memory error detector
==14799== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et
al.
==14799== Using Valgrind-3.11.0 and LibVEX; rerun with -h for
copyright info
==14799== Command​: /home/dan/Source/perl6/install/bin/moar --full-
cleanup --execname=./install/bin/perl6-valgrind-m
--libpath=/home/dan/Source/perl6/install/share/nqp/lib
--libpath=/home/dan/Source/perl6/install/share/perl6/lib
--libpath=/home/dan/Source/perl6/install/share/perl6/runtime
/home/dan/Source/perl6/install/share/perl6/runtime/perl6.moarvm -e
await\ (for\ ^7\ {\ start\ say\ �/etc/hostname�.IO\ })
==14799==
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
==14799==
==14799== Process terminating with default action of signal 6
(SIGABRT)​: dumping core
==14799== at 0x54EF04F​: raise (in /usr/lib/libc-2.24.so)
==14799== by 0x54F0479​: abort (in /usr/lib/libc-2.24.so)
==14799== by 0x507B366​: uv_mutex_destroy (thread.c​:114)
==14799== by 0x4FFEDA1​: gc_free (ConcBlockingQueue.c​:72)
==14799== by 0x4FCC0C4​: MVM_gc_collect_free_nursery_uncopied
(collect.c​:580)
==14799== by 0x4FC8B46​: MVM_gc_global_destruction
(orchestrate.c​:511)
==14799== by 0x505CDF1​: MVM_vm_destroy_instance (moar.c​:391)
==14799== by 0x400D2D​: main (main.c​:194)
==14799==
==14799== HEAP SUMMARY​:
==14799== in use at exit​: 74,702,706 bytes in 168,549 blocks
==14799== total heap usage​: 219,362 allocs, 50,813 frees, 88,708,939
bytes allocated
==14799==
==14799== LEAK SUMMARY​:
==14799== definitely lost​: 10,398 bytes in 187 blocks
==14799== indirectly lost​: 22,368 bytes in 668 blocks
==14799== possibly lost​: 394,608 bytes in 7,033 blocks
==14799== still reachable​: 74,275,332 bytes in 160,661 blocks
==14799== suppressed​: 0 bytes in 0 blocks
==14799== Rerun with --leak-check=full to see details of leaked memory
==14799==
==14799== For counts of detected and suppressed errors, rerun with​: -v
==14799== ERROR SUMMARY​: 0 errors from 0 contexts (suppressed​: 0 from
0)

It's not just IO.

perl6-valgrind-m -e 'await (for ^7 { start { my $a = rand; say $a} })'

This is Rakudo Perl 6 running in valgrind, a tool for debugging and profiling programs.
Running a program in valgrind usually takes *a lot* more time than running it directly,
so please be patient.
This Rakudo version is 2016.09.108.g.3.a.6.cd.8.a built on MoarVM version 2016.09.15.gc.8.b.4228,
running on arch (4.7.3.1.arch) / linux (4.7.4.1.ARCH)


==9911== Memcheck, a memory error detector
==9911== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==9911== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==9911== Command​: /home/dan/Source/perl6/install/bin/moar --full-cleanup --execname=./install/bin/perl6-valgrind-m --libpath=/home/dan/Source/perl6/install/share/nqp/lib --libpath=/home/dan/Source/perl6/install/share/perl6/lib --libpath=/home/dan/Source/perl6/install/share/perl6/runtime /home/dan/Source/perl6/install/share/perl6/runtime/perl6.moarvm -e await\ (for\ ^7\ {\ start\ {\ my\ $a\ =\ rand;\ say\ $a}\ })
==9911==
0.127484896364438
0.763354571102502
0.00985479535521292
0.878131490298359
0.359453206308309
0.774801346753346
0.237011180057426
==9911==
==9911== Process terminating with default action of signal 6 (SIGABRT)​: dumping core
==9911== at 0x54EF04F​: raise (in /usr/lib/libc-2.24.so)
==9911== by 0x54F0479​: abort (in /usr/lib/libc-2.24.so)
==9911== by 0x507B366​: uv_mutex_destroy (thread.c​:114)
==9911== by 0x4FFEDA1​: gc_free (ConcBlockingQueue.c​:72)
==9911== by 0x4FCC0C4​: MVM_gc_collect_free_nursery_uncopied (collect.c​:580)
==9911== by 0x4FC8B46​: MVM_gc_global_destruction (orchestrate.c​:511)
==9911== by 0x505CDF1​: MVM_vm_destroy_instance (moar.c​:391)
==9911== by 0x400D2D​: main (main.c​:194)
==9911==
==9911== HEAP SUMMARY​:
==9911== in use at exit​: 74,237,008 bytes in 167,877 blocks
==9911== total heap usage​: 226,367 allocs, 58,490 frees, 88,750,025 bytes allocated
==9911==
==9911== LEAK SUMMARY​:
==9911== definitely lost​: 10,398 bytes in 187 blocks
==9911== indirectly lost​: 22,368 bytes in 668 blocks
==9911== possibly lost​: 394,608 bytes in 7,033 blocks
==9911== still reachable​: 73,809,634 bytes in 159,989 blocks
==9911== suppressed​: 0 bytes in 0 blocks
==9911== Rerun with --leak-check=full to see details of leaked memory
==9911==
==9911== For counts of detected and suppressed errors, rerun with​: -v
==9911== ERROR SUMMARY​: 0 errors from 0 contexts (suppressed​: 0 from 0)
./install/bin/perl6-valgrind-m​: line 11​: 9911 Killed valgrind /home/dan/Source/perl6/install/bin/moar --full-cleanup --execname="$0" --libpath="/home/dan/Source/perl6/install/share/nqp/lib" --libpath="/home/dan/Source/perl6/install/share/perl6/lib" --libpath="/home/dan/Source/perl6/install/share/perl6/runtime" /home/dan/Source/perl6/install/share/perl6/runtime/perl6.moarvm "$@​"

@p6rt
Copy link
Author

@p6rt p6rt commented Oct 3, 2016

From @MasterDuke17

On Sun Oct 02 17​:20​:42 2016, ddgreen@​gmail.com wrote​:

On Sun Oct 02 13​:57​:34 2016, ddgreen@​gmail.com wrote​:

On Sun Oct 02 09​:59​:20 2016, alex.jakimenko@​gmail.com wrote​:

Surprisingly, this snippet is also buggy (but not segfaulty)​:

await (for ^7 { start say �/etc/hostname�.IO })

Note that we are not doing any actual file checks here, just
creating
an .IO
object.

Running that program in an infinite loop (just wrap it in while :;
do
perl6 -e
'â�¦'; done) will give you something like this​:

"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
Cannot invoke this object (REPR​: Null; VMNull)
in block <unit> at -e line 1

"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO

Oops, Null!

The valgrind output looks similar​:

This is Rakudo Perl 6 running in valgrind, a tool for debugging and
profiling programs.
Running a program in valgrind usually takes *a lot* more time than
running it directly,
so please be patient.
This Rakudo version is 2016.09.100.g.46.e.0.ede built on MoarVM
version 2016.09.15.gc.8.b.4228,
running on arch (4.7.3.1.arch) / linux (4.7.4.1.ARCH)
------------------------------------------------------------------------------------------------
==14799== Memcheck, a memory error detector
==14799== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et
al.
==14799== Using Valgrind-3.11.0 and LibVEX; rerun with -h for
copyright info
==14799== Command​: /home/dan/Source/perl6/install/bin/moar --full-
cleanup --execname=./install/bin/perl6-valgrind-m
--libpath=/home/dan/Source/perl6/install/share/nqp/lib
--libpath=/home/dan/Source/perl6/install/share/perl6/lib
--libpath=/home/dan/Source/perl6/install/share/perl6/runtime
/home/dan/Source/perl6/install/share/perl6/runtime/perl6.moarvm -e
await\ (for\ ^7\ {\ start\ say\ �/etc/hostname�.IO\ })
==14799==
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
"/etc/hostname".IO
==14799==
==14799== Process terminating with default action of signal 6
(SIGABRT)​: dumping core
==14799== at 0x54EF04F​: raise (in /usr/lib/libc-2.24.so)
==14799== by 0x54F0479​: abort (in /usr/lib/libc-2.24.so)
==14799== by 0x507B366​: uv_mutex_destroy (thread.c​:114)
==14799== by 0x4FFEDA1​: gc_free (ConcBlockingQueue.c​:72)
==14799== by 0x4FCC0C4​: MVM_gc_collect_free_nursery_uncopied
(collect.c​:580)
==14799== by 0x4FC8B46​: MVM_gc_global_destruction
(orchestrate.c​:511)
==14799== by 0x505CDF1​: MVM_vm_destroy_instance (moar.c​:391)
==14799== by 0x400D2D​: main (main.c​:194)
==14799==
==14799== HEAP SUMMARY​:
==14799== in use at exit​: 74,702,706 bytes in 168,549 blocks
==14799== total heap usage​: 219,362 allocs, 50,813 frees,
88,708,939
bytes allocated
==14799==
==14799== LEAK SUMMARY​:
==14799== definitely lost​: 10,398 bytes in 187 blocks
==14799== indirectly lost​: 22,368 bytes in 668 blocks
==14799== possibly lost​: 394,608 bytes in 7,033 blocks
==14799== still reachable​: 74,275,332 bytes in 160,661 blocks
==14799== suppressed​: 0 bytes in 0 blocks
==14799== Rerun with --leak-check=full to see details of leaked
memory
==14799==
==14799== For counts of detected and suppressed errors, rerun with​:
-v
==14799== ERROR SUMMARY​: 0 errors from 0 contexts (suppressed​: 0 from
0)

It's not just IO.

perl6-valgrind-m -e 'await (for ^7 { start { my $a = rand; say $a} })'

This is Rakudo Perl 6 running in valgrind, a tool for debugging and
profiling programs.
Running a program in valgrind usually takes *a lot* more time than
running it directly,
so please be patient.
This Rakudo version is 2016.09.108.g.3.a.6.cd.8.a built on MoarVM
version 2016.09.15.gc.8.b.4228,
running on arch (4.7.3.1.arch) / linux (4.7.4.1.ARCH)
------------------------------------------------------------------------------------------------
==9911== Memcheck, a memory error detector
==9911== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et
al.
==9911== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright
info
==9911== Command​: /home/dan/Source/perl6/install/bin/moar --full-
cleanup --execname=./install/bin/perl6-valgrind-m
--libpath=/home/dan/Source/perl6/install/share/nqp/lib
--libpath=/home/dan/Source/perl6/install/share/perl6/lib
--libpath=/home/dan/Source/perl6/install/share/perl6/runtime
/home/dan/Source/perl6/install/share/perl6/runtime/perl6.moarvm -e
await\ (for\ ^7\ {\ start\ {\ my\ $a\ =\ rand;\ say\ $a}\ })
==9911==
0.127484896364438
0.763354571102502
0.00985479535521292
0.878131490298359
0.359453206308309
0.774801346753346
0.237011180057426
==9911==
==9911== Process terminating with default action of signal 6
(SIGABRT)​: dumping core
==9911== at 0x54EF04F​: raise (in /usr/lib/libc-2.24.so)
==9911== by 0x54F0479​: abort (in /usr/lib/libc-2.24.so)
==9911== by 0x507B366​: uv_mutex_destroy (thread.c​:114)
==9911== by 0x4FFEDA1​: gc_free (ConcBlockingQueue.c​:72)
==9911== by 0x4FCC0C4​: MVM_gc_collect_free_nursery_uncopied
(collect.c​:580)
==9911== by 0x4FC8B46​: MVM_gc_global_destruction
(orchestrate.c​:511)
==9911== by 0x505CDF1​: MVM_vm_destroy_instance (moar.c​:391)
==9911== by 0x400D2D​: main (main.c​:194)
==9911==
==9911== HEAP SUMMARY​:
==9911== in use at exit​: 74,237,008 bytes in 167,877 blocks
==9911== total heap usage​: 226,367 allocs, 58,490 frees, 88,750,025
bytes allocated
==9911==
==9911== LEAK SUMMARY​:
==9911== definitely lost​: 10,398 bytes in 187 blocks
==9911== indirectly lost​: 22,368 bytes in 668 blocks
==9911== possibly lost​: 394,608 bytes in 7,033 blocks
==9911== still reachable​: 73,809,634 bytes in 159,989 blocks
==9911== suppressed​: 0 bytes in 0 blocks
==9911== Rerun with --leak-check=full to see details of leaked memory
==9911==
==9911== For counts of detected and suppressed errors, rerun with​: -v
==9911== ERROR SUMMARY​: 0 errors from 0 contexts (suppressed​: 0 from
0)
./install/bin/perl6-valgrind-m​: line 11​: 9911 Killed
valgrind /home/dan/Source/perl6/install/bin/moar --full-cleanup
--execname="$0"
--libpath="/home/dan/Source/perl6/install/share/nqp/lib"
--libpath="/home/dan/Source/perl6/install/share/perl6/lib"
--libpath="/home/dan/Source/perl6/install/share/perl6/runtime"
/home/dan/Source/perl6/install/share/perl6/runtime/perl6.moarvm "$@​"

If I loop this with valgrind, no errors​: "my $a = rand; await (for ^7 { start { say $a } }); exit"

But if I leave off that exit, every single run says (after it prints the number 7 times)​:
==27323== Process terminating with default action of signal 6 (SIGABRT)​: dumping core
==27323== at 0x54EF04F​: raise (in /usr/lib/libc-2.24.so)
==27323== by 0x54F0479​: abort (in /usr/lib/libc-2.24.so)
==27323== by 0x507B366​: uv_mutex_destroy (thread.c​:114)
==27323== by 0x4FFEDA1​: gc_free (ConcBlockingQueue.c​:72)
==27323== by 0x4FCC0C4​: MVM_gc_collect_free_nursery_uncopied (collect.c​:580)
==27323== by 0x4FC8B46​: MVM_gc_global_destruction (orchestrate.c​:511)
==27323== by 0x505CDF1​: MVM_vm_destroy_instance (moar.c​:391)
==27323== by 0x400D2D​: main (main.c​:194)

@p6rt
Copy link
Author

@p6rt p6rt commented Nov 2, 2016

From @jnthn

So, an update on this one.

The first set of ASAN barf (involving rope flattening) and SEGVs were fixed last month by 5224878b2869. Now it can run for 10,000 iterations without trouble. Well, until it can't.

Seems that the Cannot Invoke thingy happens about 1 time in a few hundred thousand iterations​:

jnthn@​lviv​:~/dev/rakudo$ seq 20 | xargs -Iz ./perl6-m -e 'await (for ^10000 { start â��/etc/hostnameâ��.IO ~~ :e })'
Cannot invoke this object (REPR​: P6opaque; Scalar)
  in block <unit> at -e line 1

jnthn@​lviv​:~/dev/rakudo$ seq 20 | xargs -Iz ./perl6-m -e 'await (for ^10000 { start â��/etc/hostnameâ��.IO ~~ :e })'

jnthn@​lviv​:~/dev/rakudo$ seq 20 | xargs -Iz ./perl6-m -e 'await (for ^10000 { start â��/etc/hostnameâ��.IO ~~ :e })'

jnthn@​lviv​:~/dev/rakudo$ seq 20 | xargs -Iz ./perl6-m -e 'await (for ^10000 { start â��/etc/hostnameâ��.IO ~~ :e })'
Cannot invoke this object (REPR​: P6opaque; Scalar)
  in block <unit> at -e line 1

Fun debugging awaits...

Finally, the last set of ASAN barfage is about global destruction (as mentioned in the stack trace). This does want looking in to, but only happens when we pass the --full-cleanup flag. Thus, it's not related to the original problem, and won't happen when not running under valgrind (since we just leave cleanup to the OS in that case, which can no doubt do it far faster than we can).

So, to resolve this issue we should​:

1) Hunt down the cause of the rare invoke thing.
2) Add a spectest.

/jnthn

@p6rt
Copy link
Author

@p6rt p6rt commented Nov 5, 2016

From @MasterDuke17

On Wed, 02 Nov 2016 07​:53​:04 -0700, jnthn@​jnthn.net wrote​:

So, an update on this one.

The first set of ASAN barf (involving rope flattening) and SEGVs were
fixed last month by 5224878b2869. Now it can run for 10,000 iterations
without trouble. Well, until it can't.

Seems that the Cannot Invoke thingy happens about 1 time in a few
hundred thousand iterations​:

jnthn@​lviv​:~/dev/rakudo$ seq 20 | xargs -Iz ./perl6-m -e 'await (for
^10000 { start �/etc/hostname�.IO ~~ :e })'
Cannot invoke this object (REPR​: P6opaque; Scalar)
in block <unit> at -e line 1

jnthn@​lviv​:~/dev/rakudo$ seq 20 | xargs -Iz ./perl6-m -e 'await (for
^10000 { start �/etc/hostname�.IO ~~ :e })'

jnthn@​lviv​:~/dev/rakudo$ seq 20 | xargs -Iz ./perl6-m -e 'await (for
^10000 { start �/etc/hostname�.IO ~~ :e })'

jnthn@​lviv​:~/dev/rakudo$ seq 20 | xargs -Iz ./perl6-m -e 'await (for
^10000 { start �/etc/hostname�.IO ~~ :e })'
Cannot invoke this object (REPR​: P6opaque; Scalar)
in block <unit> at -e line 1

Fun debugging awaits...

Finally, the last set of ASAN barfage is about global destruction (as
mentioned in the stack trace). This does want looking in to, but only
happens when we pass the --full-cleanup flag. Thus, it's not related
to the original problem, and won't happen when not running under
valgrind (since we just leave cleanup to the OS in that case, which
can no doubt do it far faster than we can).

So, to resolve this issue we should​:

1) Hunt down the cause of the rare invoke thing.
2) Add a spectest.

/jnthn

dogbert@​dogbert-VirtualBox ~/repos/rakudo $ ./perl6 -v
This is Rakudo version 2016.10-178-gaedb8e7 built on MoarVM version 2016.10-37-gf769569
implementing Perl 6.c.
dogbert@​dogbert-VirtualBox ~/repos/rakudo $ ulimit -c unlimited
dogbert@​dogbert-VirtualBox ~/repos/rakudo $ seq 20 | xargs -Iz ./perl6-m --ll-exception -e 'await (for ^10000 { start â��/etc/hostnameâ��.IO ~~ :e })'
*** Error in `/home/dogbert/repos/rakudo/install/bin/moar'​: double free or corruption (fasttop)​: 0x0aff40a0 ***
xargs​: ./perl6-m​: terminated by signal 6

dogbert@​dogbert-VirtualBox /repos/rakudo $ gdb /home/dogbert/repos/rakudo/install/bin/moar core
GNU gdb (Ubuntu 7.7.1-0ubuntu5
14.04.2) 7.7.1
Copyright (C) 2014 Free Software Foundation, Inc.
License GPLv3+​: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software​: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law. Type "show copying"
and "show warranty" for details.
This GDB was configured as "i686-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see​:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at​:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /home/dogbert/repos/rakudo/install/bin/moar...done.
[New LWP 15991]
[New LWP 15990]
[New LWP 15989]
[New LWP 15993]
[New LWP 15992]
[New LWP 15994]
[New LWP 15995]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/i386-linux-gnu/libthread_db.so.1".
Core was generated by `/home/dogbert/repos/rakudo/install/bin/moar --execname=./perl6-m --libpath=/hom'.
Program terminated with signal SIGABRT, Aborted.
#​0 0xb76ebcb0 in ?? ()
(gdb) bt
#​0 0xb76ebcb0 in ?? ()
#​1 0xb72254ba in malloc_printerr (action=<optimized out>, str=0xb7317e80 "double free or corruption (fasttop)", ptr=0xaff40a0) at malloc.c​:4996
#​2 0xb722612d in _int_free (av=0xb735d420 <main_arena>, p=<optimized out>, have_lock=0) at malloc.c​:3840
#​3 0xb7228e33 in __GI___libc_free (mem=<optimized out>, mem@​entry=0xaff40a0) at malloc.c​:2946
#​4 0xb74c2edd in MVM_free (p=0xaff40a0) at src/core/alloc.h​:29
#​5 MVM_string_flatten (tc=tc@​entry=0xb123250, s=s@​entry=0xb6e4d238) at src/strings/ops.c​:1243
#​6 0xb745e590 in extract_key (key=0xb6e4d238, klen=<synthetic pointer>, kdata=<synthetic pointer>, tc=0xb123250) at src/6model/reprs/MVMHash.c​:21
#​7 at_key (tc=0xb123250, st=0x91aecd8, root=0xb4d0dd08, data=0xb4d0dd18, key=0xb6e4d238, result=0xb48fdc38, kind=8) at src/6model/reprs/MVMHash.c​:77
#​8 0xb7454a27 in MVM_repr_at_key_o (tc=tc@​entry=0xb123250, obj=0xb4d0dd08, key=key@​entry=0xb6e4d238) at src/6model/reprconv.c​:450
#​9 0xb7482484 in MVM_6model_find_method (tc=0xb123250, obj=0xb48ffe64, name=0xb6e4d238, res=0xa78cea0) at src/6model/6model.c​:91
#​10 0xb7417a85 in MVM_interp_run (tc=tc@​entry=0xb123250, initial_invoke=initial_invoke@​entry=0xb74278c0 <thread_initial_invoke>, invoke_data=0x0) at src/core/interp.c​:1697
#​11 0xb7427882 in start_thread (data=0xb0f5c88) at src/core/threads.c​:77
#​12 0xb7500807 in uv.thread_start () from //home/dogbert/repos/rakudo/install/lib/libmoar.so
#​13 0xb7155f72 in start_thread (arg=0xb48feb40) at pthread_create.c​:312
#​14 0xb729df8e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S​:129
(gdb) q

[11​:02] <dogbert17> it has to do with your bug RT #​129781
[11​:02] <synopsebot6> Link​: https://rt-archive.perl.org/perl6//Public/Bug/Display.html?id=129781
[11​:03] <dogbert17> I ran jnthn's stress script with core dump turned on and got itto generate a core file, moght that be of help?
[11​:03] <dogbert17> my spelling sucks
[11​:03] <MasterDuke> oooo, nice
[11​:04] <dogbert17> it points to something called MVM_string_flatten (among others)
[11​:04] <dogbert17> let me fix a gist ...
[11​:05] <MasterDuke> interesting. jnthn made some fixes to that recently, are you on moar HEAD?
[11​:05] <dogbert17> yes
[11​:05] <MasterDuke> cool
[11​:06] <jnthn> There's still some more fixing needed for that, alas...
[11​:06] <jnthn> Though I got rid of the most immediate cause of it
[11​:07] <dogbert17> here​: https://gist.github.com/dogbert17/819c787aed1c1cf4679bb74407e53149
[11​:07] <jnthn> Yup, inside of hash
[11​:07] <jnthn> That's the place that still needs attention

@p6rt
Copy link
Author

@p6rt p6rt commented Nov 16, 2016

From @jnthn

On Sat, 01 Oct 2016 11​:42​:20 -0700, nicholas wrote​:

On Sat, Oct 01, 2016 at 08​:14​:16AM -0700, Daniel Green wrote​:

# New Ticket Created by Daniel Green
# Please include the string​: [perl #​129781]
# in the subject line of all future correspondence about this issue.
# <URL​: https://rt-archive.perl.org/perl6/Ticket/Display.html?id=129781 >

await (for ^7 { start �/etc/hostname�.IO ~~ :e })

regular perl6-valgrind-m output here​:
https://gist.github.com/MasterDuke17/9ab9ec5bdbc483bfe63213bf26f82316

Nice catch. ASAN has fun​:

$ ./perl6-m -Ilib -e 'await (for ^7 { start �/etc/hostname�.IO ~~ :e
})'

==9674==ERROR​: AddressSanitizer​: attempting double-free on
0x603000381040 in thread T4​:
#​0 0x7fb46d651417 in __interceptor_free
../../.././libsanitizer/asan/asan_malloc_linux.cc​:62
#​1 0x7fb46cc99075 in MVM_free src/core/alloc.h​:29
#​2 0x7fb46cca388b in MVM_string_flatten src/strings/ops.c​:1241
#​3 0x7fb46ca027ef in MVM_interp_run src/core/interp.c​:1601
#​4 0x7fb46ca9776a in start_thread src/core/threads.c​:77
#​5 0x7fb46cd6152d in uv__thread_start
3rdparty/libuv/src/unix/thread.c​:49
#​6 0x7fb46bdcfaa0 in start_thread (/lib64/libpthread.so.0+0x7aa0)
#​7 0x7fb46c2d5aac in __clone (/lib64/libc.so.6+0xe8aac)

0x603000381040 is located 0 bytes inside of 24-byte region
[0x603000381040,0x603000381058)
freed by thread T1 here​:
#​0 0x7fb46d651417 in __interceptor_free
../../.././libsanitizer/asan/asan_malloc_linux.cc​:62
#​1 0x7fb46cc99075 in MVM_free src/core/alloc.h​:29
#​2 0x7fb46cca388b in MVM_string_flatten src/strings/ops.c​:1241
#​3 0x7fb46ca027ef in MVM_interp_run src/core/interp.c​:1601
#​4 0x7fb46ca9776a in start_thread src/core/threads.c​:77
#​5 0x7fb46cd6152d in uv__thread_start
3rdparty/libuv/src/unix/thread.c​:49
#​6 0x7fb46bdcfaa0 in start_thread (/lib64/libpthread.so.0+0x7aa0)

previously allocated by thread T0 here​:
#​0 0x7fb46d65162f in __interceptor_malloc
../../.././libsanitizer/asan/asan_malloc_linux.cc​:72
#​1 0x7fb46cc98fef in MVM_malloc src/core/alloc.h​:2
#​2 0x7fb46cc9b63c in allocate_strands src/strings/ops.c​:27
#​3 0x7fb46cc9d384 in MVM_string_substring src/strings/ops.c​:294
#​4 0x7fb46c9feb14 in MVM_interp_run src/core/interp.c​:1467
#​5 0x7fb46ccf5bf4 in MVM_vm_run_file src/moar.c​:304
#​6 0x401a4f in main src/main.c​:191
#​7 0x7fb46c20bd1c in __libc_start_main (/lib64/libc.so.6+0x1ed1c)

Thread T4 created by T0 here​:
#​0 0x7fb46d6206ea in __interceptor_pthread_create
../../.././libsanitizer/asan/asan_interceptors.cc​:183
#​1 0x7fb46cd61632 in uv_thread_create
3rdparty/libuv/src/unix/thread.c​:66
#​2 0x7fb46ca97b1b in MVM_thread_run src/core/threads.c​:129
#​3 0x7fb46ca3b0a1 in MVM_interp_run src/core/interp.c​:3964
#​4 0x7fb46ccf5bf4 in MVM_vm_run_file src/moar.c​:304
#​5 0x401a4f in main src/main.c​:191
#​6 0x7fb46c20bd1c in __libc_start_main (/lib64/libc.so.6+0x1ed1c)

Thread T1 created by T0 here​:
#​0 0x7fb46d6206ea in __interceptor_pthread_create
../../.././libsanitizer/asan/asan_interceptors.cc​:183
#​1 0x7fb46cd61632 in uv_thread_create
3rdparty/libuv/src/unix/thread.c​:66
#​2 0x7fb46ca97b1b in MVM_thread_run src/core/threads.c​:129
#​3 0x7fb46ca3b0a1 in MVM_interp_run src/core/interp.c​:3964
#​4 0x7fb46ccf5bf4 in MVM_vm_run_file src/moar.c​:304
#​5 0x401a4f in main src/main.c​:191
#​6 0x7fb46c20bd1c in __libc_start_main (/lib64/libc.so.6+0x1ed1c)

SUMMARY​: AddressSanitizer​: double-free
../../.././libsanitizer/asan/asan_malloc_linux.cc​:62
__interceptor_free
==9674==ABORTING

The need for string flattening is now gone, meaning the code path that caused this bug is also, happily, gone. In S17-promie/start.t I've added a test case that far more reliably provoked the bug (in fact, I've never seen it fail to provoke the bug).

About other notes on this ticket​:

* The "Could not invoke" issue that could also sometimes be triggered by the same code was fixed last week in MoarVM commit b4cd2a6555 (and is test covered)

* The abort reported at exit is a `--full-cleanup` issue and unrelated to the original issue, so doesn't block closing this ticket. Also, since we only use --full-cleanup when running under valgrind, ordinary users will never see this.

Thanks,

/jnthn

@p6rt p6rt closed this Nov 16, 2016
@p6rt
Copy link
Author

@p6rt p6rt commented Nov 16, 2016

@jnthn - Status changed from 'open' to 'resolved'

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
1 participant