The first time should_trace() returns true, bionic_trace_begin() calls
open() on trace_marker.
The problem is that open() can call bionic_trace_begin(). We've observed
this happening, for example when:
* fdtrack is enabled. dlopen("libfdtrack.so") can be used to enable
fdtrack on a process.
* ThreadA is busy unwinding inside fdtrack and is holding an fdtrack
internal mutex.
* ThreadB calls bionic_trace_begin() for the first time since the
property "debug.atrace.tags.enableflags" contains ATRACE_TAG_BIONIC.
* ThreadB calls open("/sys/kernel/tracing/trace_marker"). Since fdtrack
is enabled, ThreadB tries to do unwinding as well.
* ThreadB, inside fdtrack's unwinding tries to grab the same mutex that
ThreadA is holding.
* Mutex contention is reported using bionic_systrace, therefore
bionic_trace_begin() is called again on ThreadB.
* ThreadB tries to grab g_lock in bionin_systrace.cpp, but that's
already held by ThreadB itself, earlier on the stack. Therefore
ThreadB is stuck.
I managed to reproduce the above scenario by manually pausing ThreadA
inside unwinding with a debugger and letting ThreadB hitting
bionic_trace_begin() for the first time.
We could avoid using g_lock while calling open() (either by releasing
g_lock and reacquiring it later, or by using atomics), but
bionic_trace_begin() would try to call open() again. In my tests, open()
does not call bionic_trace_begin() a third time, because fdtrack has
reentrancy protection, but there might be another code path inside open
that calls bionic_trace_begin again (it could be racy or only happen in
certain configurations).
This commit fixes the problem by implementing reentrancy protection in
bionic_systrace.
Sample callstack from ThreadA deadlocked before the fix:
```
* frame #0: 0x0000007436db077c libc.so`syscall at syscall.S:41
frame #1: 0x0000007436db0ba0 libc.so`bionic_trace_begin(char const*) [inlined] __futex(ftx=0x000000743737a548, op=<unavailable>, value=2, timeout=0x0000000000000000, bitset=-1) at bionic_futex.h:45:16
frame #2: 0x0000007436db0b8c libc.so`bionic_trace_begin(char const*) [inlined] __futex_wait_ex(ftx=0x000000743737a548, value=2) at bionic_futex.h:66:10
frame #3: 0x0000007436db0b78 libc.so`bionic_trace_begin(char const*) [inlined] Lock::lock(this=0x000000743737a548) at bionic_lock.h:67:7
frame #4: 0x0000007436db0b74 libc.so`bionic_trace_begin(char const*) [inlined] should_trace() at bionic_systrace.cpp:38:10
frame #5: 0x0000007436db0b74 libc.so`bionic_trace_begin(message="Contending for pthread mutex") at bionic_systrace.cpp:59:8
frame #6: 0x0000007436e193e4 libc.so`NonPI::MutexLockWithTimeout(pthread_mutex_internal_t*, bool, timespec const*) [inlined] NonPI::NormalMutexLock(mutex=0x0000007296cae9f0, shared=0, use_realtime_clock=false, abs_timeout_or_null=0x0000000000000000) at pthread_mutex.cpp:592:17
frame #7: 0x0000007436e193c8 libc.so`NonPI::MutexLockWithTimeout(mutex=0x0000007296cae9f0, use_realtime_clock=false, abs_timeout_or_null=0x0000000000000000) at pthread_mutex.cpp:719:16
frame #8: 0x0000007436e1912c libc.so`::pthread_mutex_lock(mutex_interface=<unavailable>) at pthread_mutex.cpp:839:12 [artificial]
frame #9: 0x00000071a4e5b290 libfdtrack.so`std::__1::mutex::lock() [inlined] std::__1::__libcpp_mutex_lock(__m=<unavailable>) at __threading_support:256:10
frame #10: 0x00000071a4e5b28c libfdtrack.so`std::__1::mutex::lock(this=<unavailable>) at mutex.cpp:31:14
frame #11: 0x00000071a4e32634 libfdtrack.so`unwindstack::Elf::Step(unsigned long, unwindstack::Regs*, unwindstack::Memory*, bool*, bool*) [inlined] std::__1::lock_guard<std::__1::mutex>::lock_guard(__m=0x0000007296cae9f0) at __mutex_base:104:27
frame #12: 0x00000071a4e32618 libfdtrack.so`unwindstack::Elf::Step(this=0x0000007296cae9c0, rel_pc=66116, regs=0x0000007266ca0470, process_memory=0x0000007246caa130, finished=0x0000007ff910efb4, is_signal_frame=0x0000007ff910efb0) at Elf.cpp:206:31
frame #13: 0x00000071a4e2b3b0 libfdtrack.so`unwindstack::LocalUnwinder::Unwind(this=0x00000071a4ea1528, frame_info=<unavailable>, max_frames=34) at LocalUnwinder.cpp:102:22
frame #14: 0x00000071a4e2a3ec libfdtrack.so`fd_hook(event=<unavailable>) at fdtrack.cpp:119:18
frame #15: 0x0000007436dbf684 libc.so`::__open_2(pathname=<unavailable>, flags=<unavailable>) at open.cpp:72:10
frame #16: 0x0000007436db0a04 libc.so`bionic_trace_begin(char const*) [inlined] open(pathname=<unavailable>, flags=524289) at fcntl.h:63:12
frame #17: 0x0000007436db09f0 libc.so`bionic_trace_begin(char const*) [inlined] get_trace_marker_fd() at bionic_systrace.cpp:49:25
frame #18: 0x0000007436db09c0 libc.so`bionic_trace_begin(message="pthread_create") at bionic_systrace.cpp:63:25
```
Bug: 213642769
Change-Id: I10d331859045cb4a8609b007f5c6cf2577ff44df
When calling write on an FD for trace_marker, it is expected that the
pointer passed will be paged into memory. If this isn't the case, the
kernel will ignore the string passed and instead write "<faulted>" to
the ring buffer.
For end events, we were passing a constant string which resides in
the rodata section of the ELF file. If this section is paged out, we
end up not closing atrace stacks correctly leading to very broken traces.
For even more context, see the associated bug.
Fix this issue by reading the constant string to the stack first
which should mean the string is always paged in.
Bug: 197620214
Change-Id: I6a444ac6fe83a6a9fb696c5621e392eca7e9437a
Revert submission 1403568-sysprop_trace
Reason for revert: makes property get/set non-reentrant
Reverted Changes:
I6f85f3f52:Add systrace tag for system property
Id2b93acb2:Adding system property tracing
Id78992d23:Add systrace tag for system property
I1ba9fc7bd:Add systrace tag for system property
Bug: 193050299
Test: build and boot a device
Change-Id: Ic7a83fb01a39113d408ed0c95d27f694d5a2649c
Merged-In: Ic7a83fb01a39113d408ed0c95d27f694d5a2649c
(cherry picked from commit 61a5a8380d)
This reverts commit 1e1c7845aa.
Reason for revert: makes property get/set non-reentrant
Bug: 193050299
Test: build and boot a device
Change-Id: If59e3dc25684a3c2b1d3ff74f995311afe6c6e89
Merged-In: If59e3dc25684a3c2b1d3ff74f995311afe6c6e89
(cherry picked from commit 3ec21f527a)
Some global static variables are only used within a single function,
so moving them inside the function which requires them. This also
ensures those static variables of class types are initialized before
they are being used.
For example, this is needed for CachedProperty(), as some of the
member method, e.g., CachedProperty().Get(), might be invoked,
e.g., in __libc_preinit(), before the constructor is invoked.
This happens after we added property trace points in commit
Id2b93acb2ce02b308c0e4889f836159151af3b46.
For g_lock, we don't move them because it can be initialized by setting
its memory to 0. And it's used in two functions.
https://android.googlesource.com/platform/bionic/+/refs/heads/master/libc/private/bionic_lock.h
Bug: 147275573
Test: atest CtsBionicTestCases
Test: adb shell perfetto -o /data/misc/perfetto-traces/test_trace -t 10s bionic sysprop
Change-Id: I99565ce2442d34f33830778915c737eed834f8b3
Introducing a new systrace tag, TRACE_TAG_SYSPROP, for use with
system property.
For property set, the tracing is added in __system_property_set() instead of
__system_property_update() / __system_property_add() so we can record
control properties like ctl.*, sys.powerctl.*, etc.., which won't be
updated via the latter two functions.
Bug: 147275573
Test: atest CtsBionicTestCases
Test: adb shell perfetto -o /data/misc/perfetto-traces/test_trace -t 10s bionic
Test: adb shell perfetto -o /data/misc/perfetto-traces/test_trace -t 10s sysprop
Test: adb shell /data/benchmarktest64/bionic-benchmarks/bionic-benchmarks \
--benchmark_filter=BM_property --bionic_cpu=4, then compares the results
of property benchmarks before and after the change, didn't see
significant difference.
Change-Id: Id2b93acb2ce02b308c0e4889f836159151af3b46
Merged-In: Id2b93acb2ce02b308c0e4889f836159151af3b46
(cherry picked from commit 26970c3493)
tracefs will be mounted at /sys/kernel/tracing when debugfs
is not mounted.
Bug: 134669095
Test: atest bionic-unit-tests-static
Change-Id: Ic224cf13500efc570da8b6a27ce925bbcf068fdd
snprintf always calls free (on a null pointer) in its epilogue, which
results in infinite recursion if free calls a function that calls
bionic_trace_begin (e.g. when perfetto attempts to lock a mutex in
RecordFree).
Bug: http://b/137284735
Test: treehugger
Change-Id: I51c5b32e8f4e394be4602e06c7b94797df73c37b
Add | to make bionic's trace end print match other trace end prints.
Test: took systrace with bionic tag enabled
Change-Id: Ieabb139dd224aa8045be914f21c0432d42a93755
Static variable initialization calls pthread_mutex_lock() and may lead to
deadlock if should_trace() is called in pthread_mutex_lock context.
Here is a stack of blocked init process:
__cxa_guard_acquire ->
should_trace ->
bionic_trace_begin ->
__pthread_mutex_lock_with_timeout ->
__cxa_guard_release ->
should_trace ->
bionic_trace_begin ->
__pthread_mutex_lock_with_timeout ->
mutex::lock ->
LogMessage::~LogMessage
......
So we need to move it out
Test: 1 Compiled and booted.
2 Reboot pressure test for more than 30000 times.
Change-Id: I8d97745161f1aa8942b63338208ea74830768ae1
Signed-off-by: Wei Li <sirius.liwei@huawei.com>
Signed-off-by: Jinguang Dong <dongjinguang@huawei.com>
This library is used by a number of different libraries in the system.
Make it easy for platform libraries to use this library and create
an actual exported include file.
Change the names of the functions to reflect the new name of the library.
Run clang_format on the async_safe_log.cpp file since the formatting is
all over the place.
Bug: 31919199
Test: Compiled for angler/bullhead, and booted.
Test: Ran bionic unit tests.
Test: Ran the malloc debug tests.
Change-Id: I8071bf690c17b0ea3bc8dc5749cdd5b6ad58478a
This is the last bionic caller that was manually trying to cache
property values.
Bug: N/A
Test: builds and boots
Change-Id: Id66c0a05d8448f08c39dbf7189241e75615d44b4
Currently, if the debug.atrace.tags.enableflags property is not found,
it is set to a safe value such that a pointer to this property can be
stored for later access. This may result in selinux denials because not
all processes write permissions for this property or permission to
connect to the property write socket at all.
Change I6d953c0c281fd72ad3eba8a479fd258023579b5b writes this property to
a safe value upon boot, which greatly decreases the cases in which this
property will not be accessible and removes the need to write it here.
This commit removes this write.
Bug 26115803
Change-Id: Ief72c5f731d3a1231b5080eb531fa0a491a8b1d1
<signal.h> shouldn't get you the contents of <errno.h>, and <fcntl.h>
shouldn't get you the contents of <unistd.h>.
Change-Id: I347499cd8671bfee98e6b8e875a97cab3a3655d3
bionic_systrace.h contains an implementation of tracing that
can be used with systrace.py and its associated viewer. pthread_mutex
now uses this tracing to track pthread_mutex contention, which can be
enabled by using the "bionic" command line option to systrace.
Bug: 15116468
Change-Id: I30ed5b377c91ca4c36568a0e647ddf95d4e4a61a
