Commit Graph

15 Commits

Author SHA1 Message Date
Tom Cherry d2743ef5c9 liblog: don't cache property size values and move to own file
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
2020-08-03 13:17:12 -07:00
Tom Cherry f74503dd46 logd: optionally track the full size of log buffers
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
2020-07-01 14:35:33 -07:00
Tom Cherry b07e339b53 logd: fix use after resize of contents_ vector
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
2020-06-24 15:31:46 -07:00
Tom Cherry f2774a04ca logd: add fuzzer for SerializedLogBuffer and other improvements
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
2020-06-23 11:37:49 -07:00
Tom Cherry 0efb410013 logging: Use more inclusive language.
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
2020-06-16 14:31:31 -07:00
Tom Cherry 1a796bca57 logd: add a SerializedLogBuffer suitable for compression
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
2020-06-12 14:35:30 -07:00
Tom Cherry f93b4006e0 logd: use libbase logging
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
2020-06-03 16:29:48 -07:00
Tom Cherry d5b3838dbc logd: make LogBuffer an interface
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
2020-05-12 15:39:19 -07:00
Tom Cherry 68630a0dbe logd: refactor LastLogTimes a bit
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
2020-05-12 15:39:11 -07:00
Tom Cherry 64e9016351 logd: separate LogStatistics from LogBuffer
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
2020-05-11 07:55:52 -07:00
Tom Cherry 6ec71e9253 logd: rename LogTimes -> LogReaderThread
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
2020-05-04 17:37:08 -07:00
Tom Cherry 5a3db391b4 logd: separate PruneList from LogBuffer
logd needs a pointer to PruneList, but it should not own it and it
should not have initPrune() or formatPrune() functions.

Test: logging unit tests
Change-Id: Id1668c26d07eb5d1e4cf267f5748c20a79f711ae
2020-05-04 10:02:55 -07:00
Tom Cherry 1a12ae3a25 logd: decouple LogTags from LogBuffer
LogBuffer needs a pointer to LogTags, but it should not own the
instance.  It should not provide accessors into LogTags either.

Also, clean up CommandListener a bit.

Test: logging unit tests
Change-Id: Ic0c86a2bac0c4dd80262278588b9fdc2326dbe5b
2020-05-04 10:01:37 -07:00
Max Spector ace90bd945 Liblogd log fuzzer
Improvments to fuzzer for liblogd LogBuffer::log

Bug: 143107334
Test: Ran the fuzzer
Change-Id: Ibf9f21cd51ff7c0ef390a5e217be085a9a4976e0
2019-10-23 19:58:05 -07:00
Max Spector 0c9d488374 Liblogd log fuzzer
Basic fuzzer for liblogd LogBuffer::log

Bug: 143107334
Test: Ran the fuzzer
Change-Id: Ifaeef1410655cf57c58b2b78484b832dfea6333a
2019-10-21 18:26:59 -07:00