logd suffers performance degradation when multiple blocking
readers connect to it. Each time when the writer thread log
new entries, all of the readers are notified regardless of
which log id they are watching.
In this case, only give notification to the readers who are
actually watching new entries' log id. This decreases logd
CPU consumption by skipping unnecessary LogBuffer::flushTo
loops.
Test: liblog-unit-tests, logd-unit-tests & CtsLiblogTestCases
logcat-unit-tests
Test: manual:
1.'logcat –b all' at constant heavy logging load level
2.simultaneously 'logcat –b crash' in another session,
a healthy crash buffer usually keep empty
3.logd CPU consumption doesn't increase after step 2
Change-Id: I4ffc045c9feb7a0998f7e47ae2173f8f6aa28e8a
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
A mixture of fixes and cleanup for LogKlog.cpp and friends.
- sscanf calls strlen. Check if the string is missing a nul
terminator, if it is, do not call sscanf.
- replace NULL with nullptr for stronger typechecking.
- pass by reference for simpler code.
- Use ssize_t where possible to check for negative values.
- fix FastCmp to add some validity checking since ASAN reports that
callers are not making sure pre-conditions are met.
- add fasticmp templates for completeness.
- if the buffer is too small to contain a meaningful time, do not
call down to log_time::strptime() because it does not limit its
accesses to the buffer boundaries, instead stopping at a
terminating nul or invalid match.
- move strnstr to LogUtils.h, drop size checking of needle and
clearly report the list of needles used with android::strnstr
- replace 'sizeof(static const char[]) - 1' with strlen.
Test: gTest liblog-unit-test, logd-unit-tests & logcat-unit-tests
Bug: 30792935
Bug: 36536248
Bug: 35468874
Bug: 34949125
Bug: 34606909
Bug: 36075298
Bug: 36608728
Change-Id: I161bf03ba029050e809b31cceef03f729d318866
Better keep the right order, or ASAN will complain when you read
out of bounds.
Bug: 36234128
Test: m
Test: m && m SANITIZE_TARGET=address
Test: Sanitized device boots without ASAN crashes
Change-Id: Ifc09cb0ece6835d2b636a3ad2128e09ca9aa45c9
Switch _all_ file's coding style to match to ease all future changes.
SideEffects: None
Test: compile
Bug: 35373582
Change-Id: I470cb17f64fa48f14aafc02f574e296bffe3a3f3
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
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
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
LogBuffer::pidToUid(pid_t pid) { return stats.pidToUid(pid); }
needs to have LogBuffer::lock()/unlock() to prevent unordered_map
data corruption. This can lead to multiple symptoms, crashes and
continuous spins on corrupted iterators.
Bug: 30688716
Bug: 30050636
Bug: 30614675
Bug: 25620123
Bug: 30792935
Change-Id: I1d8fec8e5fda98c6a08645e7456b081507696b3c
dmesg parser could wrap taglen limit resulting in out of bound
accesses. Can lead to crash or data corruption.
Fixed an issue with two-word tag parsing. Switched to case
insensitive tag content matching. Added a few extra limit
checks that could also wrap, simplified the parsing, then added
means to stop using hard coded constants.
Bug: 30688716
Bug: 30050636
Bug: 30614675
Bug: 25620123
Change-Id: Iae4f664f63ef7b842d82eaa1638b6d7a0d28fd18
Skip leading 'c0 32767 ' and place pid (32767 in example) into pid
field of log record.
Bug: 29831823
Change-Id: I9fcd3cb0235dfcad78627736712a20d2dc1250cc
(cherry pick from commit 2ad0bd0a9b)
LogReader.h needs to be individually importable.
Fix a few others, drop includes of local includes, let them be
included in source instead and allow headers to be included
alphabetically. Was not a complete audit since goal was to
separate LogReader.h out from the pack.
Bug: 27242723
Change-Id: Ic7759ef90995e5bd285810706af33550c73cf5b5
LogReader.h needs to be individually importable.
Fix a few others, drop includes of local includes, let them be
included in source instead and allow headers to be included
alphabetically. Was not a complete audit since goal was to
separate LogReader.h out from the pack.
Bug: 27242723
Change-Id: Ic7759ef90995e5bd285810706af33550c73cf5b5
Use 1972 as a right delineation. Otherwise use half way point
between the monotonic and realtime. Treat correction factor as
unsigned, ensure that any wrapping to a negative value is
dropped or set to EPOCH. Acknowledge that we can get a more
accurate time track by acquiring the time rather than relying on
healthd timestamp.
Bug: 26331432
Change-Id: I09075fca58676a30cf7d87baf2d4b0f53795abaa
klogd is sensitive to changes in timezone resulting in glitches
surrounding conversion to local realtime logging. logger manages
a map from monotonic to realtime, but the process is racey since
the system can change the timezone at any time, this catches those
cases where it glitches.
Bug: 21868540
Change-Id: I03de6675fcd04f18ba7306a24dc3d9e750d86976
Resolve three areas missing taglen checking. Add some additional
limit-checking paranoia. Problem started when p was allowed to
go beyond the size of the incoming buffer in some blind
p = cp + 1 fragments, placed the check for that after them all
before harm could be done, rather than in each location.
Bug: 25620123
Change-Id: Ib5687fd30ef0cd3ba3bc0df310b436ad675ccabc
if ro.logd.timestamp or persist.logd.timestamp are set to the value
monotonic then liblog writer, liblog printing and logd all switch to
recording/printing monotonic time rather than realtime. If reinit
detects a change for presist.logd.timestamp, correct the older entry
timestamps in place.
ToDo: A corner case condition where new log entries in monotonic time
occur before logd reinit detects persist.logd.timestamp, there
will be a few out-of-order entries, but with accurate
timestamps. This problem does not happen for ro.logd.timestamp
as it is set before logd starts.
NB: This offers a nano second time accuracy on all log entries
that may be more suitable for merging with other system
activities, such as systrace, that also use monotonic time. This
feature is for debugging.
Bug: 23668800
Change-Id: Iee6dab7140061b1a6627254921411f61b01aa5c2
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
Switch to using string and length in all transactions, treating
trailing nuls the same as spaces.
ToDo: change dumpstate (bugreport) to use logcat -b printable _regardless_
Bug: 23517551
Change-Id: I42162365e6bf8ed79d356e7b689a673902116fdb
Rename to log_strntok_r and change from dealing with strings
to dealing with a string and an associated length.
Bug: 23517551
Change-Id: Ia72f1305a53f55eeef9861ac378fb8205fd2378e
Need some more flexibility when parsing kernel messages
cluttered with extra fluff. This is the minimal relaxation
we can do to the rules to ensure that we work on all
possible devices and kernels when sniffing for time
correction information.
We want to minimize any future maintenance, keep in mind
klogd is a "userdebug" or "eng" feature and is disabled
in "user" builds. Manage expectations.
Bug: 23517551
Change-Id: I026d074e14fb2550e728683e85a973bd87e78a9c
- sniff for PID in kernel log messages if available
- properly deal with klogd watermark in face of modified output
- deal more stringently with priority tag, must have [ following
- suppress process-name stutter in tag that can happen
- do not use : to demark tag if within [ ]
Mediatek-special change that adds <printk_state>(<cpu>)[<pid>:<comm>]
as a prefix to the printk messages. Along the lines of (simplified
for entertainment purposes, YMMV):
char tbuf[50]; /* printk prefix */
int this_cpu = smp_processor_id();
char state = __raw_get_cpu_var(printk_state);
unsigned tlen = snprintf(tbuf, sizeof(tbuf), "%c(%x)[%d:%s]",
state, this_cpu, current->pid, current->comm);
Bug: 23517551
Change-Id: I568e25c5aa6d8474835454a0e83b19c2921b7985
Aid monotonic to realtime logging synchronization correction in
the Android ecosystem by providing a periodic notification. We
now have the following messages in the kernel logs:
- PM: suspend entry %Y-%m-%d %H:%M:%S.%09q UTC
- PM: suspend exit %Y-%m-%d %H:%M:%S.%09q UTC
- Suspended for %s.%03q seconds
- healthd: battery l=100 ... %Y-%m-%d %H:%M:%S.%09q UTC
Alter klogd to resynchronize on healthd messages as well.
NB: Time using strftime format, %q is a reference to fractional
second as introduced into log_time strptime method.
Bug: 21868540
Change-Id: I854afc0a07dff9c7f26d2b2f68990e52bf90e300
- Heuristics associated with translation of kernel messages to
Android user space logs.
- Limit is_prio to 4 characters, we got false positives on hex
values like <register contents> with no alpha chars.
- x11 and other register definitions are not valid tags, en0 is
- fix some Android coding standard issues
Change-Id: Idc3dcc53a2cb75ac38628c8ef7a5d5b53f12587a
- regression in log_strtok_r (part deux) In commit
'logd: fix kernel logline stutter'
2c3b300fd8 we introduced log_strtok_r.
as a replacement for strtok_r that dealt with a problem with
some kernel log messages. Fix is to refine definition of
is_timestamp to not match on patterns like [0], requiring
a single period. Another fix is to refine definition of
is_prio to properly escape non-digit content.
- Missing content because SYSLOG_ACTION_SIZE_BUFFER with added logging
is too short for full read of SYSLOG_ACTION_READ_ALL dropping
initial content. Add a margin for additional 1024 bytes.
- Absolute _first_ log entry has sequence number of 1, which is
specifically dropped, start sequence count at 1 rather than 0.
- Remove trailing space for efficiency.
- If tag exists but no content, trick into kernel logging.
Bug: 21851884
Change-Id: I0867a555a3bca09bbf18d18e75e41dffffe57a23
In commit 'logd: fix kernel logline stutter'
2c3b300fd8 we introduced log_strtok_r.
as a replacement for strtok_r that dealt with a problem with
some kernel log messages. Fix is to refine definition of
is_timestamp to not match on patterns like [0].
Change-Id: I0867a555a3bca09bbf18d18e75e41dffffe57a22
- look for cases where one log line contains two without a newline.
- rare condition, occurs when a printk does not have
a terminating newline under certain race conditions.
- the newline may be performed broken up as a second call
- the timestamps can be reversed (showing the race effects).
- driver(s) should really have the newline in there log messages.
Change-Id: Ibfb56b32047da3d6513db059ca6edad0f0105168
- 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
