VM: deadlock resulting in timeout with get_vm_timeline_rpc_test

[fsc8000]

This seems to be a deadlock:

FAILED: none-vm release_ia32 service/get_vm_timeline_rpc_test
Expected: Pass
Actual: Timeout
CommandOutput[vm]:

stdout:
** Launching out/ReleaseIA32/dart --error_on_bad_type --error_on_bad_override --complete_timeline --optimization-counter-threshold=5 --ignore-unrecognized-flags --package-root=out/ReleaseIA32/packages/ --enable-vm-service:0 /mnt/data/b/build/slave/vm-linux-release-optcounter-threshold-be/build/sdk/runtime/observatory/tests/service/get_vm_timeline_rpc_test.dart --testee-mode
Observatory listening on http://127.0.0.1:47814
** Signaled to run test queries on 47814

Command[vm]: DART_CONFIGURATION=ReleaseIA32 out/ReleaseIA32/dart --error_on_bad_type --error_on_bad_override --complete_timeline --optimization-counter-threshold=5 --ignore-unrecognized-flags --package-root=out/ReleaseIA32/packages/ /mnt/data/b/build/slave/vm-linux-release-optcounter-threshold-be/build/sdk/runtime/observatory/tests/service/get_vm_timeline_rpc_test.dart
Took 0:01:00.017000

Short reproduction command (experimental):
python tools/test.py -mrelease -aia32 --write-debug-log --write-test-outcome-log --copy-coredumps --vm-options --optimization-counter-threshold=5 --exclude-suite pkg -t60 service/get_vm_timeline_rpc_test

[fsc8000]

A GC happens during deoptimization (materialization of heap objects). The offending thread tries to relock the time line lock that it already holds itself.

(gdb) bt
#0 0xf772a440 in __kernel_vsyscall ()
#1 0xf76ed9e2 in __lll_lock_wait () from /lib/i386-linux-gnu/libpthread.so.0
#2 0xf76e9267 in _L_lock_847 () from /lib/i386-linux-gnu/libpthread.so.0
#3 0xf76e90a0 in pthread_mutex_lock () from /lib/i386-linux-gnu/libpthread.so.0
#4 0x083db2f4 in ThreadBlockStartEvent (this=0x9996500) at runtime/vm/timeline.cc:677
#5 dart::TimelineEventEndlessRecorder::StartEvent (this=0x9996500) at runtime/vm/timeline.cc:988
#6 0x083dc727 in StartEvent (this=0x99f73bc) at runtime/vm/timeline.cc:484
#7 dart::TimelineDurationScope::~TimelineDurationScope (this=0xf5cfdcc0, __in_chrg=) at runtime/vm/timeline.cc:525
#8 0x0826f680 in dart::Heap::CollectGarbage (this=this@entry=0x99c4b90, space=space@entry=dart::Heap::kNew, api_callbacks=api_callbacks@entry=dart::Heap::kInvokeApiCallbacks,
reason=reason@entry=dart::Heap::kNewSpace) at runtime/vm/heap.cc:360
#9 0x0827023a in CollectGarbage (space=dart::Heap::kNew, this=0x99c4b90) at runtime/vm/heap.cc:388
#10 dart::Heap::AllocateNew (this=0x99c4b90, size=size@entry=48) at runtime/vm/heap.cc:82
#11 0x082de957 in Allocate (space=dart::Heap::kNew, size=48, this=) at runtime/vm/heap.h:83
#12 dart::Object::Allocate (cls_id=65, size=48, space=dart::Heap::kNew) at runtime/vm/object.cc:1837
#13 0x082f6c8d in dart::OneByteString::New (len=len@entry=35, space=space@entry=dart::Heap::kNew) at runtime/vm/object.cc:19785
#14 0x082f7c54 in dart::OneByteString::Concat (str1=..., str2=..., space=space@entry=dart::Heap::kNew) at runtime/vm/object.cc:19896
#15 0x082f9cb8 in dart::String::Concat (str1=..., str2=..., space=dart::Heap::kNew) at runtime/vm/object.cc:19257
#16 0x082f9f71 in dart::Function::QualifiedUserVisibleNameCString (this=this@entry=0xf5cfe3c4) at runtime/vm/object.cc:6861
#17 0x081e2a33 in dart::DeoptContext::~DeoptContext (this=0xf50ae588, __in_chrg=) at runtime/vm/deopt_instructions.cc:152
#18 0x081e2b42 in dart::DeoptContext::~DeoptContext (this=0xf50ae588, __in_chrg=) at runtime/vm/deopt_instructions.cc:165
#19 0x084143eb in DRT_HelperDeoptimizeMaterialize (thread=, zone=, isolate=0x99f7038, arguments=...) at runtime/vm/code_generator.cc:1810
#20 dart::DRT_DeoptimizeMaterialize (arguments=...) at runtime/vm/code_generator.cc:1806
#21 0xf678026a in ?? ()
#22 0xf67807d5 in ?? ()
#23 0xf585ae87 in ?? ()
#24 0xf585acfc in ?? ()

[fsc8000]

@johnmccutchan @iposva-google

Proposed fix (excl. Windows): https://codereview.chromium.org/1515553003

I use a recursive mutex for the time line block lock, so that the current thread does not block when a nested time line events are nested (e.g. deopt What is the reason for not using a recursive mutex by default? Is there a noticable performance cost?

Another possibility for this specific instance would be to stop the "Deoptimize" time line event before MaterializeDeferredObjects (where a GC may occur). But I don't think we have a general restriction that time line events can not be nested, right?

[rmacnak-google]

f887b03