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
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
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
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
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 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
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
We don't want to fake socket credentials if they were not provided by
the kernel. If there is a bug preventing us from reading the
credentials then it must be solved directly.
Test: logd, liblog unit tests
Test: boot and ensure overflow uid doesn't show up
This reverts commit c4e4823b00.
Change-Id: I683129a8a214637635f163ae25c39bb8a47cd50f
- android::pidToUid() additional checking. Make sure if we have to
convert a PID to an UID that the parse of /proc/<pid>/status
requires a trailing space after the number
- android::tidToPid() added, in the same vein as android::pidToUid().
- stats.tidToPid() added
- If no credentials, set PID to 0 and UID to DEFAULT_OVERFLOWUID
- If credentialed PID is 0, use stats.tidToPid()
- If credentialed UID is DEFAULT_OVERFLOWUID, use stats.pidToUid()
Test: remove +passcred from logd.rc for daemon and confirm very few
UID=65534 or PID=0 cases actually show up
Bug: 37985222
Change-Id: I7d20506e70e67beb3043d1537cf9450ab58dc278
Switch to a reader writer lock for the Element List lock. Also setup
for a reader writer lock for the Times list, but continue to use a
mutex where rdlock() and wrlock() are the same implementation for now.
This should improve general reader performance and prevent blocking of
other reader operations or exit by a single hung logd.reader.per
thread. For example, a full length logcat of an empty buffer (eg:
crash log buffer) will hold a lock while the iterator scans the entire
list.
Test: gTest liblog-unit-tests, logd-unit-tests, logcat-unit-tests
Bug: 37378309
Bug: 37483775
Change-Id: If5723ff4a978e17d828a75321e8f0ba91d4a09e0
Logspan down to the millisecond. Show a percentage if trimmed by
Chatty messages, a subspan from the newest to the newest chatty in
the log buffer. Sniff stats.add(elem), stats.subtract(elem) and
stats.dropped(elem) to generate the logspan data.
Test: gTest liblog-unit-tests, logd-unit-tests and logcat-unit-tests
Test: manual check Logspan statistics for being in range, added
temporary internal instrumentation to confirm expectations.
Bug: 37254265
Change-Id: I09c0d9375d5580315543c747b37976f9eeb9e408
Replace stats.add(elem) + stats.subtract(elem) with a new more
efficient method stats.addTotal(elem).
Test: gTest liblog-unit-test, logd-unit-tests and logcat-unit-tests
Bug: 37254265
Change-Id: I2b3c2ac44209772b38f383ae46fe6c4422b542cf
Prefix long truncated names with an ellipse (...). Shift left as
much as possible when doing so, but keep spaces between command
name and other tabular fields.
Test: manual/visual
Bug: 37254265
Change-Id: I185b1e121ba911a9410a8b6624e013d5a531962b
Switch _all_ file's coding style to match to ease all future changes.
SideEffects: None
Test: compile
Bug: 35373582
Change-Id: I470cb17f64fa48f14aafc02f574e296bffe3a3f3
Will register a new event tag by name and format, and return an
event-log-tags format response with the newly allocated tag.
If format is not specified, then nothing will be recorded, but
a pre-existing named entry will be listed. If name and format are
not specified, list all dynamic entries. If name=* list all
event log tag entries.
Stickiness through logd crash will be managed with the tmpfs file
/dev/event-log-tags and through a reboot with add_tag entries in
the pmsg last logcat event log. On debug builds we retain a
/data/misc/logd/event-log-tags file that aids stickiness and that
can be picked up by the bugreport.
If we detect truncation damage to /dev/event-log-tags, or to
/data/misc/logd/event-log-tags, rebuild file with a new first line
signature incorporating the time so mmap'd readers of the file can
detect the possible change in shape and order.
Manual testing:
Make sure nc (netcat) is built for the target platform on the host:
$ m nc
Then the following can be used to issue a request on the platform:
$ echo -n 'getEventTag name=<name> format="<format>"\0EXIT\0' |
> nc -U /dev/socket/logd
Test: gTest logd-unit-test --gtest_filter=getEventTag*
Bug: 31456426
Change-Id: I5dacc5f84a24d52dae09cca5ee1a3a9f9207f06d
Caused +/- field data to land under the Pruned column
This reverts commit 0adcc3e3e8.
Test: manual
Bug: 30118730
Change-Id: Ic75ce3a90baded19f3efc0cc77474fe5d9a8accd
If a series of messages arrive from a single source with identical
message content payload, then suppress them and generate a chatty
report. The checking is done on a per log id basis.
This alters the assumption that chatty messages are always at the
oldest entries, they now show up in the middle too. To address this
change in behavior we print the first line, a chatty reference
which internally takes little space, then the last line in the series.
This does not conserve processing time in logd, and certainly has no
impact on the long path of formatting and submitting log messages from
from the source, but it may contribute to memory space and signal to
noise savings under heavy spammy loads.
Test: gTest liblog-unit-tests, logd-unit-tests & logcat-unit-tests
Bug: 33535908
Change-Id: I3160c36d4f4e2f8216f528605a1b3993173f4dec
To support upcoming disk usage calculation optimizations, this change
creates a new GID for each app that will be used to mark its cached
data. We're allocating these unique GIDs so that we can use
quotactl() to track cached data on a per-app basis.
This change also tightens up the implementation of both the cache
and shared GID calculation to ensure that they stay inside the valid
ranges, and includes tests to verify.
Test: builds, boots, tests pass
Bug: 27948817
Change-Id: Ie4377e5aae267f2da39a165888139228995987cb
Move existing fast<str*cmp> templates for general use, pulled from
the implementation used in logd that dealt with speed through cache
locality and subroutine call mitigation. Rename to fastcmp.
Test: logd-benchmarks and based on manual profiling from the past
Bug: 31456426
Change-Id: Ic62f4a437fc3e06ffdeaae73a6f34e197957a6b0
Add in to the Total Overhead the amount of storage we are
using to hold on to the statistics.
Test: see that the Total Overhead accounts for about 100K
Bug: 31942525
Change-Id: Ibe241c0bccc5a9df52395802338c8a7fc3b64104
log/logger.h pieces moved into log/log.h. Correct for some
minor Android Coding standards.
Test: gTests liblog-unit-tests, logd-unit-tests and logcat-unit-tests
Bug: 19235719
Bug: 26552300
Bug: 31289077
Bug: 31456426
Change-Id: I0a19fd8788eec20a582e72e4c62c04534bdb1b9a
On 64 bit system, calculates to roughly 80 bytes of metadata and
list overhead for each entry.
In unit test example, we report 3388987 bytes of logging data and
overhead total, showmap reports 4652K of dirty data. We still want
to account for the remainder (fragmentation, other sources of
internal allocations etc).
Test: see values and check math
Bug: 31942525
Change-Id: I75f3162ce691faf1ae5a5dec18939fea535ede7e
Allows us to mitigate the impact of MAP_PRIVATE and copy on write by
calling android_lookupEventTag_len instead of android_lookupEventTag,
and delaying the copy on write impact to the later. We return a
string length in a supplied location along with the string pointer
with android_lookupEventTag_len(const EventTagMap* map, size_t* len,
int tag). The string is not guaranteed to be nul terminated. Since
android_lookupEventTag() called even once can cause the memory
impact, we will mark it as deprecated, but we currently have no
timeframe for removal since this is a very old interface.
Add an API for __android_log_is_loggable_len() that accepts the non
null terminated content and fixup callers that would gain because the
length is known prior to the call either in the compiler or at
runtime. Tackle transition to android_lookupEventTag_len() and
fixup callers.
On any application that performs logging (eg: com.android.phone)
/proc/<pid>/smaps before:
xxxxxxxxxx-xxxxxxxxxx rw-p 00000000 fd:00 463 /system/etc/event-log-tags
Size: 20 kB
Rss: 20 kB
Pss: 1 kB
Shared_Clean: 0 kB
Shared_Dirty: 20 kB
Private_Clean: 0 kB
Private_Dirty: 0 kB
Referenced: 0 kB
Anonymous: 20 kB
AnonHugePages: 0 kB
Swap: 0 kB
SwapPss: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
Locked: 0 kB
VmFlags: rd wr mr mw me ac
/proc/<pid>/smaps after:
xxxxxxxxxx-xxxxxxxxxx rw-p 00000000 fd:00 1773 /system/etc/event-log-tags
Size: 20 kB
Rss: 20 kB
Pss: 1 kB
Shared_Clean: 20 kB (was 0kB)
Shared_Dirty: 0 kB (was 20kB)
Private_Clean: 0 kB
Private_Dirty: 0 kB
Referenced: 20 kB (was 0kB)
Anonymous: 0 kB (was 20kB)
AnonHugePages: 0 kB
Swap: 0 kB
SwapPss: 0 kB
KernelPageSize: 4 kB
MMUPageSize: 4 kB
Locked: 0 kB
VmFlags: rd wr mr mw me ac
Added liblog-unit-tests --gtest_filter=liblog.event_log_tags to
check for Shared_Clean: to not be 0 and Anonymous: to be 0 for
all processes referencing event-log-tags. Which can include multiple
references to /system/etc/event-log-tags and future possible refs to
/data/misc/logd/event-log-tags and /dev/event-log-tags. We want
failure messages to help point to errant code using the deprecated
interface.
This change saves 1/4MB of memory or more on a typical system.
Test: gTest liblog-unit-tests
Bug: 31456426
Change-Id: I9e08e44d9092bd96fe704b5709242e7195281d33
- Add drop logistics to TagTable
- replace uid references to a key reference since it
is an UID for most buffers, but a TAG for the
events and security buffer
- template the find worst entry mechanics into LogFindWorst class
Bug: 30118730
Change-Id: Ibea4be2c50d6ff4b39039e371365fed2453f17a2
- Add a new statistic that reports per pid and log_id for AID_SYSTEM
- Add a new pruning filter ~1000/! boolean
- Use this new statistic to prune on worst pid within AID_SYSTEM
Bug: 26029733
Bug: 21615139
Bug: 22855208
Change-Id: Iab5dd28f807dcf03d276372853883f3b6afa8294
Primarily gives access to the Chattiest TIDs and TAGs
associated with a pid.
Has a secondary effect of allowing us to pull out the
command line, comm and in some cases the associated
PACKAGE for a specific pid while the logs are still
present even if the executable is gone.
Bug: 26029733
Bug: 21615139
Change-Id: I1ea63165a680a9318360579b70b1512078ed5682
Report the ESTIMATED instantaneous percentage decrease or increase
that an UID has to the logs as a result of the chatty filtration.
Bug: 22855208
Change-Id: If1e77afb81a2739a72b39bc7c57071763c1d64d8
Chatty logs would distort the average log size by elevating the
elements, but not the size. Add statistical collection for the
number of elements that report chatty, and subtract that from
the number of elements to improve the pruning estimate. Pick
minElements as 1% rather than 10% of the total with this more
accurate number of elements, to a minumum of 4.
Bug: 24511000
Change-Id: I3f36558138aa0b2a50e4fac6440c3a8505d95276
Simplify table generation by placing the line and header formatting
into each type's (UID, PID, TID) object. Switch to const return
values for the ownership passing functions (*ToName() functions
and methods). Use longer variable names to reduce confusion.
Switch from LINES To NUM for pruned column as that more accurately
reflects what is dropped since one entry can contain several lines.
Bug: 22855208
Change-Id: Ib110dce98a68cf5f844eb30f8a192a1f691eeba2
Discovered that we had a few libc hotspots. Adjust code to generally
reduce or nullify the number of calls to malloc, free, strlen,
strcmp, strncmp, memcmp & strncasecmp. Total gain looks to be about
3% of logd's processing time. malloc still contributes to 3%, but all
others are now total 0.5%.
Bug: 23685592
Change-Id: Ife721121667969260cdb8b055524ae90f5911278
BasicHashtable is relatively untested, move over to
a C++ template library that has more bake time.
Bug: 20419786
Bug: 21590652
Bug: 20500228
Change-Id: I926aaecdc8345eca75c08fdd561b0473504c5d95
- Add a klogd to collect the kernel logs and place them into a
new kernel log buffer
- Parse priority, tag and message from the kernel log messages.
- Turn off pruning for worst UID for the kernel log buffer
- Sniff for 'PM: suspend exit', 'PM: suspend enter' and
'Suspended for' messages and correct the internal definition
time correction against monotonic dynamically.
- Discern if we have monotonic or real time (delineation 1980) in
audit messages.
- perform appropriate math to correct the timestamp to be real time
- filter out any external sources of kernel logging
Change-Id: I8d4c7c5ac19f1f3218079ee3a05a50e2ca55f60d
Tom Cherry