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
Fix a subtle bug that liblog event messages have a payload of int32_t,
not uint32_t, so they should only be summed to int32_t max.
Make a bunch of test improvements as well to support these.
Test: these tests
Change-Id: I4069cc546240bfffec5b19f34ebec913799674e8
Add a standalone test of log buffers that does not interact with the
logd running on the device.
Test: this new test
Change-Id: Ie4ecc50289ef164aa47cc72ddeeb9b28e776db94
One of the reasons that logcat and logd statically include liblog is
to access the symbols in log_time.cpp, which we do not expose
otherwise. Except for strptime(), which will be handled in a separate
CL, these symbols are either small enough to inline in the header or
unused and can be removed.
Test: logging unit tests
Change-Id: I1f8cfbb779aef79fc7d5b6d0050438fe5f0e0e2c
liblogd: LogBuffer classes and their support, LogReaderList and
LogReaderThread
logd: liblogd + the socket code that connects liblogd to liblog and
therefore the world.
The goal here is to test liblogd offline of the socket connections or
the device.
Also, convert libaudit.c -> libaudit.cpp and modernize a bit.
Test: build
Change-Id: If5adf5e775a251d9a703c0583be0988f48017347
class LogCommand isn't needed, so remove it. Since the rest of
LogCommand.cpp only has to do with permissions, rename it
appropriately.
Test: logging unit tests
Change-Id: I32d09c74d00b6e50083e46832eca3dd886b46682
In the future, we'll want to be able to write to outputs that are not
necessarily a libsysutils SocketClient, for example host tests of
LogBuffer. Therefore, we add a LogWriter class to be used instead of
SocketClient.
Test: logging unit tests
Change-Id: I4385be65e14e83a635691a7ba79e9bf060e49484
We may use different implementations of LogBuffer in the future, so we
make it interface and create a concrete ChattyLogBuffer class that
implements it.
Test: logging unit tests
Change-Id: I5731d6404640664c9acc26b7c677dff3110c6a11
There's still plenty of work that can be done here, particularly
re-doing the locking so each LogReaderThread does not mutually exclude
the others, but that's out of the scope here.
This change primarily removes the public 'mTimes' from LogBuffer and
creates a new LogReaderList class instead. It would have merged this
into LogReader, but that creates a circular dependency.
This change also removes the need to reference LogReader or
LogReaderList from LogAudit, LogKLog, and LogListener, instead relying
on LogBuffer()::log() to call LogReaderList::NotifyNewLog().
Test: logging unit tests
Change-Id: Ia874b57a9ec1254af1295bfa6f7af2f92a75755b
ThreadFunction() will only be entered once, so there's no worry that
we'll call prctl() multiple times.
Test: logging unit tests
Change-Id: Id2a02c2ab807f1565e3d625424e040481b3aa1a3
LogStatistics is intertwined with LogBuffer, even relying on it for
thread safety. This needs to change to have a proper
LogBufferInterface, so this CL separates them. Specifically:
1) Adding a lock to LogStatistics and adding thread annotations to
ensure that data structures are protected appropriately.
2) Moving prune_rows calculation into LogStatistics so it is done
while holding this lock.
3) Using LogStatistics instead of LogBuffer where appropriate.
Note that there should not be a significant performance regression
with this lock, as it will almost always been uncontended. If
anything, it should alleviate pressure from LogBuffer's lock.
Test: logging unit tests
Change-Id: I9d6dde2c96c9f024fa0341711c7bc63379e8e406
LogStatistics relies on LogBuffer's lock for thread safety, but that
will be cleaned up in future CLs. It won't be possible to return a
'LogFindWorst' object that references internal LogStatistics pointers
in a thread safe way, so we remove this and provide a more simple
interface.
This also removes unnecessary allocations; std::array of 2 or 32
entries is small enough to allocate on the stack.
Test: logging unit tests
Change-Id: I38bfcba5b08c640ffd3af5c078bc716688f6edf8
LogListener uses the libsysutils SocketListener class to read incoming
log messages, which means that it poll()'s to wait for new data then
calls recvmsg() when this data is available. That is unnecessary,
since this is a blocking socket, it already has a dedicated thread,
and we're not using any other SocketListner features, so a tight loop
of recvmsg() is sufficient.
Below are the stats from simpleperf during a framework restart. To
get an apples to apples comparison, these stats calculate the overhead
of receiving the message as 1 - (<number of perf events dispatching
the logs in logd>/<total number of perf events for the listener thread>).
With SocketListener / poll()
378563153 total events for the listener thread - SocketListener::runListener()
245799364 events for reading and dispatching logs + recvmsg() - LogListener::onDataAvailable()
67622952 events for recvmsg() inside LogListener::onDataAvailable()
=> (378563153 - 245799364) = 132763789 SocketListener + poll() overhead
=> (132763789 + 67622952) = 200386741 total overhead to for recvmsg() + poll() + SocketListener
=> (200386741 / 378563153) = 52.9% overhead to read each log message.
Without SocketListener / poll()
324802401 total events for the new listener thread - LogListener::ThreadFunction()
133208105 events for recvmsg()
=> (133208105 / 324802401) = 41% overhead to read each log message.
This shows a 22.5% = (41 - 52.9)/52.9 reduction in cost spent for each log message.
Test: logging unit tests
Test: simpleperf
Change-Id: I1f93b7a06fac6adce8e64e727bf6d8c5935c77c9
This is the last isMonotonic() user and can go away. This timestamp
is set in the kernel source in either the audit_get_stamp() or
__audit_syscall_entry() functions. In both cases, the value used is
from ktime_get_coarse_real_ts64(), which is a realtime timestamp.
Test: audit messages show in the log correctly.
Change-Id: Ife6c09dd97fccdfc7a8f07ee63161079ae2eccc4
This has been around for ~5 years but there has been roughly no
adoption, so remove this as we clean up the logging code.
Future efforts may track the monotonic timestamp in all cases.
Test: logging unit tests
Change-Id: I55ed565669f923988e741f6b384141bba893630d
1) We can use real member functions with std::thread and
std::function, so use those instead of the 'me' pointer.
2) Don't expose member variables directly.
3) Rename and document member variables, since all of their references
are being touched anyway.
Test: logging unit tests
Change-Id: I9a357a3ea8691433d58687c95356b984b83e9c36
LogTimes has evolved from being simply a store of the last timestamp
that each reader has read to being a class representing an individual
reader thread, including the thread function, so name it
appropriately.
Test: logging unit tests
Change-Id: I6914824376a6ff1f7509e657fa4dc044ead62954
