There are only three places where the log buffer lock is not already
held when the reader lock is taken:
1) In LogReader, when a new reader connects
2) In LogReader, when a misbehaving reader disconnects
3) LogReaderThread::ThreadFunction()
1) and 2) happen sufficiently rarely that there's no impact if they
additionally held a global lock.
3) is refactored in this CL. Previously, it would do the below in a loop
1) Lock the reader lock then wait on a condition variable
2) Unlock the reader lock
3) Lock the log buffer lock in LogBuffer::FlushTo()
4) In each iteration in the LogBuffer::FlushTo() loop
1) Lock then unlock the reader lock in FilterSecondPass()
2) Unlock the log buffer lock to send the message, then re-lock it
5) Unlock the log buffer lock when leaving LogBuffer::FlushTo()
If these locks are collapsed into a single lock, then this simplifies to:
1) Lock the single lock then wait on a condition variable
2) In each iteration in the LogBuffer::FlushTo() loop
1) Unlock the single lock to send the message, then re-lock it
Collapsing both these locks into a single lock simplifes the code and
removes the overhead of acquiring the second lock, in the majority of
use cases where the first lock is already held.
Secondly, this lock will be a plain std::mutex instead of a RwLock.
RwLock's are appropriate when there is a substantial imbalance between
readers and writers and high contention, neither are true for logd.
Bug: 169736426
Test: logging unit tests
Change-Id: Ia511506f2d0935a5321c1b2f65569066f91ecb06
SerializedLogChunk.three_logs assumes that log buffers are
zero-initialized, but they are not. This causes test failures on
host.
Test: this test passes
Change-Id: I0dfa282bdc36eaa4e8e39d85c5227f717b45ec2a
This accesses shared resources in SerializedLogBuffer and therefore
requires a lock.
Bug: 169736426
Test: malloc_debug_system_tests
Change-Id: I807c65f4719481f933b4917a50f83f933b1929fb
These logs are not generally useful and can be considered to be spam
by some. Drop them to VERBOSE so that we can be selectively enabled
when debugging logd.
Test: these logs do not appears by default.
Change-Id: Ic2bb12552d6f191478777c21f500794de29c8b0a
I didn't expect this to ever be hit, but apparently it is, so add
additional logging to track it down.
Bug: 168870781
Test: build
Change-Id: Ia472bc7458a3727e4d407365672f7394426ae515
android_filesystem_config.h is found since system/core/include is on
the include path for all projects and contains a symlink to the real
android_filesystem_config.h. This is fragile and the below bug seeks
to remove this symlink and have users correctly depend on
libcutils_headers.
Bug: 165825252
Test: build
Change-Id: I1aad6a2e8fbe87635e97b0ac1be3414403353382
There was a bug in SerializedFlushToState::Prune() caused by an access
to a SerializedLogEntry raw pointer as a member of a MinHeapElement,
which was deleted earlier in the function.
Instead of just fixing the order of the access and the deletion, I
sought out to remove the raw pointer entirely. In doing so, I noticed
that the min heap doesn't provide significant benefit, since we'll
only ever have 8 log buffers so scalability is not an issue.
Therefore this change removes the min heap entirely and uses the
existing log_position_ and logs_needed_from_next_position_ members to
keep track of which are the next unread logs.
It also adds a smoke test for SerializedFlushToState::Prune() and
additional CHECK() statements to help prevent future errors.
Bug: 168869299
Test: unit tests
Change-Id: Id4d5fdbaff2fe6dc49c38f01e73f900f84d3696b
Previously ClearUidLogs() would Compress() the log buffer in all
cases, however that is the wrong behavior when writer_active_ is true
and would leave the SerializedLogChunk object in an invalid state. If
more logs are written to the log, then write_offset() will be higher
than the compressed size of the log, violating a CHECK() when later
decompressing the log.
This change does not call Compress() in ClearUidLogs() if
writer_active_ is true. It upgrades a check in Compress() from a
simple if statement to a CHECK() to prevent against this happening in
the future.
It adds a test that exercises the previously failing path.
Bug: 166187079
Test: unit tests
Change-Id: Ic5fbcf16f724af1c20170b8f4e6e2daadf6a9529
We're trying to remove the implicit dependency on libsysutils that *all*
code has via the symlink in system/core/include/, but netd and logd have
code that #includes the headers without declaring the dependency (which
works out in the end because their executables declare the dependency).
Bug: http://b/165825252
Test: treehugger
Change-Id: I8c582e427d9dbe7d9f8172c445f38ae2737a9049
Previously, chatty had logic that would skip a certain number of log
entries to satify pruning, but otherwise keep the reader connected.
This was a best-effort attempt at helping pruning and had additional
logic that handled further disruptions, if logd's memory was 2x the
allotted memory.
The new logic has two components:
1) memcpy() each individual log message in FlushTo() such that there
are no references to the underlying log data without a lock held.
Note, that this memcpy is completely negligible for performance.
2) In Prune(), immediately delete all log chunks required to reduce
memory to the allotted amount, which is now safe given 1). If readers
will lose logs, continue to print a warning.
This additionally makes the Clear() logic deterministic. It was
previously best effort in chatty, but will immediately and always
clear all logs for SerializedLogBuffer.
Bug: 163617910
Test: logging unit tests
Test: Prune() immediately frees buffers during high log pressure
Test: Clear() immediately frees buffers during high log pressure
Change-Id: I40fe9b791312af3dc256b166e5c34425f4ca51ac
See the comment in the code for more details. 'wrapped' readers are
uncommon and error prone, and this change makes them more reliable.
Its side effect is that wrapped readers will wake more often, but
they'll still be batched to a large degree.
Bug: 163617910
Test: logging unit tests
Test: logcat --wrap does the right thing
Change-Id: I4b6f8331ff7854787c97f821b2a5bf8d7da321c6
Open README.compression.md in a markdown viewer for details.
Test: vscode and gitiles render this correctly
Change-Id: Iaa0093dc565b5c6bb016c9e97248375f0906d0c8
Now that libsysutils sockets do not ignore SIGPIPE, logd itself must
ignore it and we therefore add a test that it is ignored properly.
Test: this test passes
Test: this test fails if logd doesn't ignore SIGPIPE
Change-Id: I65474967f40291a7abd11cfd279c8cde2d2bca14
Consolidate command handling for commands that take a buffer ID as
their first argument. Further use ParseUint instead of atoi(), since
atoi("bad string") returns `0` is the same as LOG_ID_MAIN.
Test: these commands are handled property
Test: `echo -n 'getLogSize ignoreme!\0' | nc -U /dev/socket/logd`
returns an error
Change-Id: I3e84a6157e16f4c110681da453e1ae1a920da7c4
liblog exposed __android_logger_get_buffer_size() which queries log
size properties, but that should not be a generic library function.
Logd should be the only process that queries these properties and
other processes should query the actual used log sizes from logd via
the android_logger_get_log_*_size() functions.
Also, always use 1MB for log buffer tests, instead of just on host and
various other clean up related to improper types.
Test: log buffers are correctly sized
Merged-In: I9b7c86bf58e569618737afe9097cf1c4d4e61d95
Change-Id: I9b7c86bf58e569618737afe9097cf1c4d4e61d95
There is an existing API, android_logger_get_log_readable_size() which
historically reported the consumed amount of data for the chatty log
buffer, since consumed and readable are synonymous with that buffer
type.
With log compression, readable and consumed are not synonymous, since
the readable log size is the uncompressed log size whereas the
consumed log size is the compressed log size.
This change adds android_logger_get_log_consumed_size() which returns
the consumed log size and makes android_logger_get_log_readable_size()
return the readable log size. Note that these values are identical if
compression is not used.
It adds both statistics to logcat:
main: ring buffer is 1 MiB (429 KiB consumed, 817 KiB readable)
radio: ring buffer is 1 MiB (339 KiB consumed, 715 KiB readable)
...
Test: logcat prints the right values with compression and chatty
Change-Id: I8b9688a987736204e2e6026e8635fbd1a5e68bb7
Don't cache the property size values since they're only queried at the
start of logd and only once during dumpstate. Initializing
SerializedLogBuffer, which includes all of the logd queries, takes
under 100us without the cache, certainly fast enough that this cache
is unneeded.
Move these functions to their own file in preparation for removing
them from liblog.
Test: log sizes set appropriately
Change-Id: I15a2fd687dcffb4eab2f22ee0825ca86e40cdba3
1) All current users are better off ignoring SIGPIPE at the beginning
of their process instead of ignoring it just for SocketClient
2) This isn't thread safe if users did want it, since sigaction()
ignores SIGPIPE for the entire process
3) This costs 5-10% of logd CPU time when logcat is reading logs
Also clean up the error handling in SocketClient::sendDataLockedv().
Test: kill logcat and see that logd doesn't crash
Test: run simpleperf and see that no cycles are going to sigaction
Change-Id: I6532c8a0d71338e534411707b9a9bd785145c730
Add 'print_all_logs' which is equivalent to running `logcat` from the
beginning of the captured log buffers.
Test: all logs can be replayed from the start
Change-Id: If0e25513fb294e61c834f82fbf90468c4b767424
__android_logger_property_get_bool() has a clunky API and doesn't
belong in liblog, since a vast majority of liblog users will never
query this property.
Specifically
1) Replace with GetBoolProperty() when completely equivalent.
2) Remove checking if property values are 'eng' or 'svelte', since
there's no evidence that those values were ever used.
3) Remove checking 'persist.logd.statistics' and 'ro.logd.statistics',
since there's no evidence that those values were ever used.
4) Set ro.logd.kernel explicitly, so other processes don't need to
replicate the defaults that logd uses.
Test: build
Change-Id: I7c37af64ba7754e839185f46da66bf077f09d9c3
The serialized log buffer along with compression results in:
* ~3.5x more logs than chatty
* Less CPU usage
* Less memory usage
* Equivalent log range
Also, delete tests that assume that the device logd implementation is
chatty. There are actual unit tests for this same behavior that don't
rely on the device logd.
Test: serialized log buffer is used
Change-Id: Ie12898617429a75b6caff92725aa7145650f8fc6
To profile different log buffer types and configuration, this change
adds the ability to record log messages and adds a tool that will
replay those log messages through different log buffer implementations
and collect stats about the execution.
Test: log messages replay correctly
Change-Id: I0dc6c545b782fa7732e325dde109c496b137d0dd
When calculating the space used for pruning, if a log chunk is
compressed, that size is used otherwise the uncompressed size is
used. This is intended to reach a steady state where 1/4 of the log
buffer is the uncompressed log chunk that is being written to and the
other 3/4 of the log buffer is compressed logs.
If we wait until there are no readers referencing the log chunk before
compressing it, we end up with 2 uncompressed logs (the one that was
just filled, that readers are still referencing, and the new one that
was allocated to fit the most recent log), which take up 1/2 of the
log buffer's allotted size and will thus cause prune to delete more
compressed logs than it should.
Instead, we should always compress the log chunks in FinishWriting()
such that the compressed size will always be used for log chunks other
than the one that is not actively written to.
Decompressed logs due to readers are ephemeral by their nature and
thus don't add to the log buffer size for pruning.
Test: observe that log buffers can be filled in the presence of a reader.
Change-Id: Ie21ccff032e41c4a0e51710cc435c5ab316563cb
This was a premature optimization. Profiling shows that decompressing
and deleting these logs is rather fast and overall CPU utilization is
lower without the added thread.
Test: profile logd with/without this thread
Change-Id: I31bd52077b495d562dd5797585191dc200ad3859
A previous change included sizeof(SerializedLogChunk) to the size of a
log chunk to more accurately track logd's log usage, but did not
update the tests that check this value, so this change updates them
appropriately.
Bug: 161179582
Test: logd-unit-tests
Change-Id: Ic37f07fff98c260dcf39b7cc79504c1c3fc2149d
ChattyLogBuffer ignores the metadata (timestamp, pid, std::list<>
iterators, etc) of log entries when calculating the size used by a
given log buffer. For example, if 1MB is the specified size of the
'main' log buffer, logd will use between ~1.3MB and ~2MB of overall
memory for 'main' log buffer. LogStatistics does track the overall
memory used and labels it 'Overhead', however this 'Overhead' is only
informative and is not used for Pruning or Chatty calculations.
This is problematic, since it makes logd's memory usage inconsistent:
depending on the pattern of logging, there can be substantially more
memory used than the specified log buffer size. This is further
complicated by the fact that chatty messages are entirely metadata and
therefore not counted as contributing to the log buffer size.
This change would switch logd to always track the full size of log
buffers, but there are two problems with this approach:
1) Unless users double their buffer sizes, then they'd have
substantially fewer logs after the change
2) Chatty logic would change and it's difficult to evaluate.
Therefore this change only provides the framework to track the full
size of log buffers. This allows an apples to apples comparison of
ChattyLogBuffer and SerializedLogBuffer. With this option enabled,
logd reports the following values:
ChattyLogBuffer:
Total log size (logcat -g), 'Total' / 'Now' (logcat -S), and
'Overhead' (logcat -S) all report the full size of log entries
including metadata.
SerializedLogBuffer:
Total log size (logcat -g) and 'Overhead' (logcat -S) report the
compressed size of the log entries including metadata.
'Total' / 'Now' (logcat -S) reports the uncompressed size of the log
entries that are available including metadata.
Test: logging statistics are correct
Change-Id: If17682af8bb605f31387d7b210b69a301dd48f07
Turns out std::vector::resize() and std::vector::clear() don't
actually deallocate any memory. std::vector::shrink_to_fit() can be
used for this but isn't a 'guarantee'. Instead of trying to get
std::vector to play nice, this change replaces std::vector<uint8_t>
with std::unique_ptr<uint8_t[]>, which is more accurate to how I'm
using this memory anyway.
Test: logging unit tests
Change-Id: I9638e90bbf50bcf316c5aa172c8278ea945d27e7
SerializedFlushToState::PopNextUnreadLog() was calling
AddMinHeapEntry() to replenish the element that was just popped off of
the heap, however AddMinHeapEntry() also manages reference counts for
the buffers, and this resulting in the following scenario:
PopNextUnreadLog() returns a pointer referencing log buffer #1
AddMinHeapEntry() sees that all logs from buffer #1 has been read, so
it decrements the reference count
The caller of PopNextUnreadLog() uses the result which references
invalid memory.
This calls CheckForNewLogs() within HasUnreadLogs() instead of
requiring a separate call, which fixes an additional issue where
continuing from the loop in SerializedLogBuffer::FlushTo() may not
pick up subsequent logs in a given log buffer, since CheckForNewLogs()
wouldn't be called. This was exacerbated by the above change.
This adds a test to check the reference counts for this case and fixes
an argument mismatch in SerializedFlushToStateTest.
This adds the corpus that surfaced the issue.
Bug: 159753229
Bug: 159783005
Test: these unit tests, run fuzzer without error
Change-Id: Ib2636dfc14293b7e2cd00876b9def6e9dbbff4ce
1) Add fuzzer for SerializedLogBuffer
2) Enable fuzzing on host
3) Read logs after writing them
4) Silence log tags error on host
Test: run these fuzzers
Change-Id: Id5f0394546ecbccf5281e3d8855853be90dee3f0
Logd never deletes SerializedLogBuffer, so it seemed reasonable to
detach the deleter thread, however unit tests and fuzzers do delete
SerializedLogBuffer, so we must safely join the deleter thread in the
destructor.
This simplifies the deleter thread code and ensures that only one
deleter thread will be running at a time.
Test: fuzzing works
Change-Id: I69c7447109898a1bb7038a03337cadacb1213281
Fix a bug that was causing cap_set_flag() fail and logd to exit.
Bug: 159588327
Test: caps are set correctly and logd functions with both, one of, or
none of klogd and auditd enabled.
Change-Id: Ia51f078ad848535ce1ac29edd8a56a2b686a12cc
In order of severity:
1) Add a CHECK() that a pointer is not nullptr, where the analyzer
believes this is possible.
2) Add `final` appropriately to functions called from constructors.
3) Add missing cloexec flags.
4) Add missing `noexcept` and other subtle performance warnings
Test: build with clang-tidy
Change-Id: Ifd9a1299a51027a47382926b2224748b5750d6cf
