Chromium is not properly traced with -t 30us

[honggyukim]

As I mentioned in issue #41, headless chrome doesn't work properly when I run it with -t 30us.
There are 2 different problematic cases.

Case 1. the target program goes zombie process and does not finish.

$ uftrace record --no-pager -t 30us ./headless_shell --no-sandbox https://www.google.com
[1228/162649:INFO:fake_audio_manager.cc(23)] FakeAudioManager
[1228/162649:ERROR:child_process_launcher.cc(528)] Failed to launch child process
[1228/162650:WARNING:message_queue.cc(38)] Leaking 1 ports in unreceived messages
[1228/162650:WARNING:message_queue.cc(38)] Leaking 2 ports in unreceived messages
[1228/162650:WARNING:message_queue.cc(38)] Leaking 1 ports in unreceived messages

Case 2. the target program crashes and shows StackTrace messages.

$ uftrace record --no-pager -t 30us ./headless_shell --no-sandbox https://www.google.com
[1228/162441:INFO:fake_audio_manager.cc(23)] FakeAudioManager
Received signal 11 <unknown> 000000000000
#0 0x000007fa5e59 base::debug::StackTrace::StackTrace()
#1 0x000007fa597f base::debug::(anonymous namespace)::StackDumpSignalHandler()
#2 0x7f55de8fd340 <unknown>
#3 0x7f55e1050f66 record_ret_stack
#4 0x7f55e10512c1 record_trace_data
#5 0x7f55e104fc86 mcount_exit_filter_record
#6 0x7f55e105082c __cyg_profile_func_exit
#7 0x000000440a22 (anonymous namespace)::TCFree()
#8 0x00000043ee12 ShimFree
#9 0x7f55e10510f2 clear_shmem_buffer
#10 0x7f55e104fb6d atfork_child_handler
#11 0x7f55de5e9147 __libc_fork
#12 0x00000a96cea0 sandbox::Credentials::ForkAndDropCapabilitiesInChild()
#13 0x0000021ccfa5 content::Zygote::ForkWithRealPid()
#14 0x0000021ce4fa content::Zygote::ReadArgsAndFork()
#15 0x0000021cb8dd content::Zygote::HandleForkRequest()
#16 0x0000021cad41 content::Zygote::HandleRequestFromBrowser()
#17 0x0000021ca2fe content::Zygote::ProcessRequests()
#18 0x0000021da26b content::ZygoteMain()
#19 0x000007ab2b9a content::RunZygote()
#20 0x000007ab33b0 content::RunNamedProcessTypeMain()
#21 0x000007ab64d4 content::ContentMainRunnerImpl::Run()
#22 0x000007ab20bd content::ContentMain()
#23 0x000007e66744 headless::(anonymous namespace)::RunContentMain()
#24 0x000007e6650f headless::RunChildProcessIfNeeded()
#25 0x000000428d31 main
#26 0x7f55de549ec5 __libc_start_main
#27 0x000000428bf5 <unknown>
  r8: cdcdcdcdcdcdcdcd  r9: 0000000000000001 r10: 0000000030bc87ce r11: 00007f55de6afc70
 r12: 0013104eb6c5658e r13: 00007f55e145e790 r14: 0000000000000001 r15: 0000000000000000
  di: 000000000001fff0  si: 0000000000000000  bp: 00007f55e145e790  bx: 0000000000000000
  dx: 000023cca89573e0  ax: 000023cca8947d90  cx: 0000000000000000  sp: 00007ffc9c3cac10
  ip: 00007f55e1050f66 efl: 0000000000010213 cgf: 0000000000000033 erf: 0000000000000000
 trp: 000000000000000d msk: 0000000000010000 cr2: 0000000010d34a18
[end of stack trace]
[1228/162441:ERROR:zygote_communication_linux.cc(144)] Did not receive ping from zygote child
[1228/162441:FATAL:zygote_communication_linux.cc(145)] Check failed: false.
#0 0x000007fa5e59 base::debug::StackTrace::StackTrace()
#1 0x000008001f30 logging::LogMessage::~LogMessage()
#2 0x0000021c6183 content::ZygoteCommunication::ForkRequest()
#3 0x00000132b060 content::(anonymous namespace)::LaunchOnLauncherThread()
#4 0x0000013345ee _ZNK4base8internal15RunnableAdapterIPFvRKNS_8CallbackIFvPN7content19ZygoteCommunicationENS_7ProcessEiELNS0_8CopyModeE1EEENS3_13BrowserThread2IDEiPNS3_32SandboxedProcessLauncherDelegateEN4mojo3edk20ScopedPlatformHandleEP
NS_11CommandLineEEE3RunIJSB_RKSD_RKiRKSF_SI_RKSK_EEEvDpOT_
#5 0x000001334219 _ZN4base8internal12InvokeHelperILb0EvE8MakeItSoIRKNS0_15RunnableAdapterIPFvRKNS_8CallbackIFvPN7content19ZygoteCommunicationENS_7ProcessEiELNS0_8CopyModeE1EEENS6_13BrowserThread2IDEiPNS6_32SandboxedProcessLauncherDelegat
eEN4mojo3edk20ScopedPlatformHandleEPNS_11CommandLineEEEEJSE_RKSG_RKiRKSI_SL_RKSN_EEEvOT_DpOT0_
#6 0x0000013340ee _ZN4base8internal7InvokerINS0_9BindStateINS0_15RunnableAdapterIPFvRKNS_8CallbackIFvPN7content19ZygoteCommunicationENS_7ProcessEiELNS0_8CopyModeE1EEENS5_13BrowserThread2IDEiPNS5_32SandboxedProcessLauncherDelegateEN4mojo3
edk20ScopedPlatformHandleEPNS_11CommandLineEEEEJRSB_RSF_RiRSH_NS0_13PassedWrapperISK_EERSM_EEEFvvEE7RunImplIRKSP_RKSt5tupleIJSB_SF_iSH_SV_SM_EEJLm0ELm1ELm2ELm3ELm4ELm5EEEEvOT_OT0_NS_13IndexSequenceIJXspT1_EEEE
#7 0x00000133360f _ZN4base8internal7InvokerINS0_9BindStateINS0_15RunnableAdapterIPFvRKNS_8CallbackIFvPN7content19ZygoteCommunicationENS_7ProcessEiELNS0_8CopyModeE1EEENS5_13BrowserThread2IDEiPNS5_32SandboxedProcessLauncherDelegateEN4mojo3
edk20ScopedPlatformHandleEPNS_11CommandLineEEEEJRSB_RSF_RiRSH_NS0_13PassedWrapperISK_EERSM_EEEFvvEE3RunEPNS0_13BindStateBaseE
#8 0x000000523e6c base::Callback<>::Run()
#9 0x000008205670 base::debug::TaskAnnotator::RunTask()
#10 0x0000080201cf base::MessageLoop::RunTask()
#11 0x00000802058e base::MessageLoop::DeferOrRunPendingTask()
#12 0x0000080208ad base::MessageLoop::DoWork()
#13 0x00000803e4d6 base::MessagePumpDefault::Run()
#14 0x00000801fb20 base::MessageLoop::RunHandler()
#15 0x0000080cf382 base::RunLoop::Run()
#16 0x00000814d9d8 base::Thread::Run()
#17 0x000001258ca6 content::BrowserThreadImpl::ProcessLauncherThreadRun()
#18 0x0000012592fd content::BrowserThreadImpl::Run()
#19 0x00000814dd7e base::Thread::ThreadMain()
#20 0x0000081345ba base::(anonymous namespace)::ThreadFunc()
#21 0x7fd8bf944182 start_thread
#22 0x7fd8bf67147d clone

[0100/000000:FATAL:zygote_linux.cc(515)] Check failed: len > 0 (0 vs. 0)
#0 0x000007fa5e59 base::debug::StackTrace::StackTrace()
#1 0x000008001f30 logging::LogMessage::~LogMessage()
#2 0x0000021cd3f0 content::Zygote::ForkWithRealPid()
#3 0x0000021ce4fa content::Zygote::ReadArgsAndFork()
#4 0x0000021cb8dd content::Zygote::HandleForkRequest()
#5 0x0000021cad41 content::Zygote::HandleRequestFromBrowser()
#6 0x0000021ca2fe content::Zygote::ProcessRequests()
#7 0x0000021da26b content::ZygoteMain()
#8 0x000007ab2b9a content::RunZygote()
#9 0x000007ab33b0 content::RunNamedProcessTypeMain()
#10 0x000007ab64d4 content::ContentMainRunnerImpl::Run()
#11 0x000007ab20bd content::ContentMain()
#12 0x000007e66744 headless::(anonymous namespace)::RunContentMain()
#13 0x000007e6650f headless::RunChildProcessIfNeeded()
#14 0x000000428d31 main
#15 0x7f55de549ec5 __libc_start_main
#16 0x000000428bf5 <unknown>

Received signal 6
#0 0x000007fa5e59 base::debug::StackTrace::StackTrace()
#1 0x000007fa597f base::debug::(anonymous namespace)::StackDumpSignalHandler()
#2 0x7f55de8fd340 <unknown>
#3 0x7f55de55ecc9 gsignal
#4 0x7f55de5620d8 abort
#5 0x000007fa4819 base::debug::(anonymous namespace)::DebugBreak()
#6 0x000007fa47db base::debug::BreakDebugger()
#7 0x00000800227e logging::LogMessage::~LogMessage()
#8 0x0000021cd3f0 content::Zygote::ForkWithRealPid()
#9 0x0000021ce4fa content::Zygote::ReadArgsAndFork()
#10 0x0000021cb8dd content::Zygote::HandleForkRequest()
#11 0x0000021cad41 content::Zygote::HandleRequestFromBrowser()
#12 0x0000021ca2fe content::Zygote::ProcessRequests()
#13 0x0000021da26b content::ZygoteMain()
#14 0x000007ab2b9a content::RunZygote()
#15 0x000007ab33b0 content::RunNamedProcessTypeMain()
#16 0x000007ab64d4 content::ContentMainRunnerImpl::Run()
#17 0x000007ab20bd content::ContentMain()
#18 0x000007e66744 headless::(anonymous namespace)::RunContentMain()
#19 0x000007e6650f headless::RunChildProcessIfNeeded()
#20 0x000000428d31 main
#21 0x7f55de549ec5 __libc_start_main
#22 0x000000428bf5 <unknown>
  r8: 0000000000000030  r9: 0000000000000001 r10: 0000000000000008 r11: 0000000000000206
 r12: 0000000000428bcc r13: 00007ffc9c3d53b0 r14: 0000000000000000 r15: 0000000000000000
  di: 0000000000005d99  si: 0000000000005d99  bp: 00007ffc9c3ca8b0  bx: 00007ffc9c3d2f20
  dx: 0000000000000006  ax: 0000000000000000  cx: 00007f55de55ecc9  sp: 00007ffc9c3ca778
  ip: 00007f55de55ecc9 efl: 0000000000000206 cgf: 0000000000000033 erf: 0000000000000007
 trp: 000000000000000e msk: 0000000000010000 cr2: 0000000010d34a18
[end of stack trace]
child terminated by signal: 6: Aborted
^C

Please have a look at it!

[namhyung]

Could you please try below patch?

diff --git a/libmcount/mcount.c b/libmcount/mcount.c
index c5ccd81..de5ef28 100644
--- a/libmcount/mcount.c
+++ b/libmcount/mcount.c
@@ -660,12 +660,15 @@ static void atfork_child_handler(void)
                assert(mtdp);
        }
 
-       mtd.tid = 0;
+       mtdp->tid = 0;
+       mtdp->recursion_guard = true;
 
-       clear_shmem_buffer(&mtd);
-       prepare_shmem_buffer(&mtd);
+       clear_shmem_buffer(mtdp);
+       prepare_shmem_buffer(mtdp);
 
        ftrace_send_message(FTRACE_MSG_FORK_END, &tmsg, sizeof(tmsg));
+
+       mtdp->recursion_guard = false;
 }
 
 static void build_debug_domain(char *dbg_domain_str)

[honggyukim]

It works fine for record command.

$ uftrace record --no-pager -t 30us ./headless_shell --no-sandbox https://www.google.com
[1229/143623:INFO:fake_audio_manager.cc(23)] FakeAudioManager
[1229/143637:INFO:fake_audio_manager.cc(27)] ~FakeAudioManager

But it seems to be the recorded data is a bit strange. I will create another issue. Thanks!