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
Also generic syntax clean up and removing some unused aspects (sorting
the list and the TODO increasing performance based on this sorting).
Test: logging unit tests
Change-Id: I56bb3866c13cb4c28bd48665bf32ec620cf0278e
Initial commit for a SerializedLogBuffer. The intention here is for
the serialized data to be compressed (currently using zlib) to allow
for substantially longer logs in the same memory footprint.
Test: unit tests
Change-Id: I2528e4e1ff1cf3bc91130173a107f371f04d911a
Test that:
1) Logs are cleared
2) More logs can be added after clear
3) Well behaving blocking readers stay connected and can read new logs
after clear.
Test: this unit test
Change-Id: I8497896f5fb068b1e50ff0dcaab1cf79aebae2bb
Clear() and Prune() return a boolean indicating whether or not their
operations failed because the log buffer was 'busy'. This means that
they return false upon success and true upon failure, which is not
intuitive.
This change inverts their return value to simply be true if they were
successful or false otherwise. It also simplifies the return value of
ChattyLogBuffer::Prune() to true if the requested number of rows have
been pruned or if all rows in the log buffer have been pruned, and
otherwise return false.
Test: logging unit tests
Test: clearing works even under logging pressure
Change-Id: I346bb945496ef62bf8e973298f81c5163f49bc57
TagNameKey contains a pointer to a std::string and a std::string_view,
such it can both own a string or reference a different string. This
is meant to be a memory optimization.
This, however, is actually a net pessimization. Due to these three
below cases and typical usage pattern.
Cases:
1) In the case where TagNameKey owns the string, 3 words are wasted,
one for the pointer and two for the std::string_view.
2) In the case where TagNameKey references a short string, the same 3
words are wasted. This is because std::string has a feature called
"Short String Optimization" that means std::string does not allocate
for strings of sizes <= 10 on 32bit devices and <= 22 on 64bit
devices.
3) In the case where TagNameKey references a longer string than the
"Short String Optimization" limits, then this saves the string's
length in bytes.
Usage pattern:
After boot on 32 bit cuttlefish, there were 679 entries for the first
case, and only 69 in the third case. The 679 entries have an overhead
of 679 * 3 * sizeof(void*) = 679 * 12 = 8148 bytes. The 69 strings in
the third case have a total length and therefore savings of 1352
bytes. This is a net pessimization of 6796 bytes.
I expect this same ratio to be similar throughout the device's uptime.
This situation is worse on 64 bit devices. If cuttlefish were 64 bit,
then there would have been only 18 items in the third case due to the
larger "Short String Optimization" capacity, and the cost for the
first case would have doubled.
Given the above and the cost of maintaining extra code, this
optimization is removed and a std::string is used as the hash table
key instead.
Test: logging unit tests
Change-Id: I957c519b19edca4f7fc531d96b7144cf68bf4e16
The keys are already available when iterating through the maps, so
this only serves to waste memory.
Test: unit tests
Change-Id: Iaf4e389eb0f0990e7113cd78be1773e767a356d4
We can use libbase logging to output to the kernel log instead of the
'prdebug' function, so use that instead.
Bonus #1: we can now use CHECK().
Bonus #2: logging unit tests automatically output to stderr.
Bonus #3: We see dependent library's logs instead of losing them to
the void.
Test: logging unit tests
Test: logs show appropriately in dmesg / stderr
Test: CHECK() works
Change-Id: I92f8056b4820dc4998996cf46460568085299700
Other log buffers may not use LogBufferElement, so we should decouple
the two classes. This uses an intermediate LogStatisticsElement
structs instead of passing a large number of parameters to each
function.
This additionally moves IsBinary() and the GetTag() functions out into
LogUtils.h since they can be used generically by other users.
Test: logging unit tests
Change-Id: I71f53257342c067bcccd5aa00bae47f714cd7c66
This logic isn't generic, so it should not be in the generic
LogReaderThread.
Moreover, it's currently broken in essentially every case except when
filtering by UID, because it runs as in the filter functions before
the actual filtering by pid/etc takes place. For example, when
filtering by pid, it's possible to get leading chatty messages. The
newly added test was failing previously but is fixed by this change.
It's fundamentally broken in the tail case. Take this example:
1: Normal message
2: Chatty message
3: Normal message
4: Normal message
If you read that log buffer with a tail value of 3, there are three
possible outcomes:
1) Messages #2-4, however this would include a leading chatty message,
which is not allowed.
2) Messages #3-4, however this is only 2, not 3 messages.
3) Messages #1-4, however this is 4, more than the 3 requested
messages.
This code chooses 2) as the correct solution, in this case, we don't
need to account for leading chatty messages when counting the total
logs in the buffer. A test is added for this case as well.
Test: new unit test
Change-Id: Id02eb81a8e77390aba4f85aac659c6cab498dbcd
This has become useless after refactoring; we instead ensure that the
LOG_ID_SECURITY bit isn't set in log_mask, instead of having this
additional check.
Test: logging unit tests
Change-Id: Id47b288d056ebf2b5bd26be94006f17c24fafd31
ChattyLogBuffer::FlushTo() needs an array of pid_t's to differentiate
between deduplication and spam removal chatty messages, but that won't
be useful to other log buffers, so it doesn't deserve its own entry in
the abstruct LogBuffer::FlushTo() function.
Other log buffers may need their own data stored for each reader, so
we create an interface that the reader itself owns and passes to the
log buffer. It uses a unique_ptr, such that the when the reader is
destroyed, so will this state.
FlushToState will additionally contain the start point, that it will
increment itself and the log mask, which LogBuffers can use to
efficiently keep track of the next elements that will be read during a
call to FlushTo().
Side benefit: this allows ChattyLogBufferTests to correctly report
'identical' instead of 'expired' lines the deduplication tests.
Side benefit #2: This updates LogReaderThread::start() more
aggressively, which should result in readers being disconnected less
often, particularly readers who read only a certain UID.
Test: logging unit tests
Change-Id: I969565eb2996afb1431f20e7ccaaa906fcb8f6d1
SimpleLogBuffer::FlushTo() attempts to find the iterator matching a
given sequence number, but the logic is wrong and will always skip one
element forward. This change fixes this and adds a test for the
situation.
This likely contributed to some test instability in the past, but was
identified because subsequent changes that track the start value
closer exacerbated this issue.
Test: existing and new unit tests
Change-Id: Iba2e654e94234693dba20d4747a60bc79d195673
This was a typo; the enum corresponds to the result of the 'Filter'
function, not the 'FlushTo' function.
Test: build
Change-Id: Ib46f0646570b6dbaac17ae9fc95c990128cdbe72
Separate these tests such that future log buffer implementations can
be run against the generic tests. Use a parameterized fixture to
allow testing any number of log buffers.
Test: these unit tests
Change-Id: I6d90838e8efa019b934d08da25cab0c2405b66cd
This is required for tests that are aware of sequence numbers to pass;
each new LogBuffer instance should start from sequence = 1, which
isn't the case if the current sequence number is a static.
Test: unit tests
Change-Id: Ie488f8ac5e22b946b7e6237d1d5caf14929c0ec3
This saves 4 or 8 bytes off of each log message for 32 bit or 64 bit
devices respectively. In practice, this actually saves more, due to
avoiding heap fragmentation.
Averaging over 5 runs of the LogBufferTest.random_messages unit test
(32 bit), this change results in 8k less memory used when 1000 logs
are logged and results in 260k less memory used when 10000 logs are
logged.
Test: check memory usage during LogBufferTest.random_messages
Test: logging unit tests
Change-Id: Ia7953e3c4cb19631ef43bab1deb91bb336bc2520
This code and comment is hard to follow, despite the operation being
simple, so refactor the code to be easier to follow.
Also, use std::unique_ptr instead of raw pointers as appropriate.
Test: logging unit tests
Change-Id: Id1f29f4deeca730d1e3b6856e1581d0b840f883e
