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
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
This code has evolved to the point that it LogReader::notifyNewLog()
executes FlushCommand on every socket. FlushCommand then iterates
over all log reader threads in LogTimes and flushes triggers them to
flush logs if they match the client. This can be simplified to simply
looping over all of the reads in LogTimes.
Code readability was the primary motivation here, but note that 64% of
LogReader::notifyNewLog() was spent looping over the sockets, and an
additional 78% of FlushCommand::runSocketCommand() was spent
repeatedly locking and unlocking the LogTimes lock.
Overall, this reduces the cost of LogReader::notifyNewLog() in
LogListener::onDataAvailable() from 5.91% to 2.93%. This is the
critical path for handling incoming log messages, so it's a
non-trivial savings.
Test: logging unit tests
Test: unprivileged clients still cannot view privileged logs
Change-Id: Ic7620978a6c23e5e2cb179ff0c42b7cea52fc011
Logs in logd's buffer are not in time order.
If a client connects and requests logs from a given timestamp, we
start at the beginning of the buffer and find the first entry that has
happened since that timestamp and use its sequence number to flush
logs from. This ensures that we get all logs accumulated in the
buffer since that time stamp and not just the most recent.
However there may be other logs in the buffer that happened before the
timestamp and have likely been already served to the client, therefore
we do not flush those.
We only do this for the first flush, since once we have flushed all of
the logs in the buffer, if another log comes in with a timestamp
earlier than the requested timestamp, it must be out of order and not
seen yet, since it is new even to logd.
Note! This is still broken. There is a race that logs before the
timestamp may come in out of order since the last time the client
disconnected and before it reconnects. The *only* solution to this
problem is that clients need to request logs after a given sequence
number. That will be done as a separate liblog API change, while
these changes put in the ground work to make that possible.
Note 2: the security log implementation, which is one of the most
important users of this, already captures logs from seconds before the
last previous log to work around issues with timestamps. That
workaround mitigates the above issue.
Test: logs work with logcat -t
Change-Id: If1a62a90c082d98c4cf2eb5c92ae3b7e89850cf2
This reverts commit 5a34d6ea43.
There is a long standing bug that logd will leak memory during its
prune process if the time on the device changes significantly forwards
then backwards. This is due to using the timestamp of each log
message to determine what log messages are yet to be processed by a
reader thread.
Various attempts have been made to rectify this, but the only solution
that safely fixes this issue is to go back to using sequence numbers
on the log messages.
Bug: 64675203
Bug: 77971811
Bug: 149340579
Bug: 150923384
Test: logcat output looks sane
Change-Id: Ibce79cf184eb29a4914f3e42a8cb2868d04dc165
There are well known issues with CLOCK_REALTIME jumping drastically.
Test: --wrap works successfully
Change-Id: I5676274783ac9aa9374d2b9254e0109d883cc5a8
This code was accidentally deleted in the refactoring of
4f22786cc9 cause the
logd.timeout_no_start test to start failing.
Bug: 117942520
Test: logd unit tests
Change-Id: Id7994230a89d7f8c2cb1f36a8ca1175a6b398de0
LogTimeEntry's lifecycle is spread out in various locations. It
further seems incomplete as there is logic that assumes that its
associated thread can exit while the underlying LogTimeEntry remains
valid, however it doesn't appear that that is actually a supported
situation.
This change simplifies this logic to have only one valid state for a
LogTimeEntry: it must have its thread running and be present in
LastLogTimes. A LogTimeEntry will never be placed into LastLogTimes
unless its thread is running and its thread will remove its associated
LogTimeEntry from LastLogTimes before it has exited.
This admittedly breaks situations where a blocking socket gets issued
multiple commands with different pid filters, tail lines, etc,
however, I'm reasonably sure that these situations were already
broken. A check is added to close the socket in this case.
Test: multiple logcat instances work, logd.reader.per's are cleaned up
Change-Id: Ibe8651e7d530c5e9a8d6ce3150cd247982887cbe
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
Helpful instrumentation to determine who is waiting for logger data.
Test: manual
Bug: 37274132
Bug: 37378309
Change-Id: I14fb1d9d15ae413930121048b770852359f06682
Move lastTid array from local in LogBuffer::flushTo to per-reader
context in LogTimes::mLastTid and pass into LogBuffer::flushTo.
Replace NULL with nullptr in touched files.
Simplify LogTimeEntry::cleanSkip_Locked initialization of skipAhead
to memset, to match mLastTid memset initialization.
Test: gTest liblog-unit-tests, logd-unit-tests & logcat-unit-tests
Test: adb logcat -b all | grep chatty | grep -v identical
Bug: 36488201
Change-Id: I0c3887f220a57f80c0490be4b182657b9563aa3f
Use getRealTime() instead and leverage private liblog log_time
comparison and math functions. This saves 8 bytes off each
element in the logging database.
Test: gTest liblog-unit-tests logd-unit-tests logcat-unit-tests
Bug: 35373582
Change-Id: Ia55ef8b95cbb2a841ccb1dae9a24f314735b076a
Switch _all_ file's coding style to match to ease all future changes.
SideEffects: None
Test: compile
Bug: 35373582
Change-Id: I470cb17f64fa48f14aafc02f574e296bffe3a3f3
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
Allow socket send syscall to terminate after 32 seconds if reader
stalled because of memory pressure allocating new network buffers
Add a gTest to catch regressions, add security buffer to log_dump
Bug: 27242723
Change-Id: Idaa6699d9d284e7f5f723ae0e76b3d6aa3371489
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
- limit AID_SYSTEM uid or gid to read security buffer messages
- adjust liblog tests to reflect the reality of this adjustment
To fully test all security buffer paths and modes
$ su 0,0,0 /data/nativetest/liblog-unit-tests/liblog-unit-tests --gtest_filter=liblog.__security*
$ su 1000,1000,1000 /data/nativetest/liblog-unit-tests/liblog-unit-tests --gtest_filter=liblog.__security*
$ su 2000,2000,2000 /data/nativetest/liblog-unit-tests/liblog-unit-tests --gtest_filter=liblog.__security*
ToDo: Integrate the above individually into the gTest Q/A testing
Bug: 26029733
Change-Id: Idcf5492db78fa6934ef6fb43f3ef861052675651
If a timeout is specified for the reader, then go to sleep
with the socket open. If the start time is about to get
pruned in the specified log buffers, then wakeup and dump
the logs; or wakeup on timeout, whichever comes first.
Bug: 25929746
Change-Id: I7d2421c2c5083b33747b84f74d9a560d3ba645df
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 simpler and faster internal sequence number, drops
a syscall overhead on 32-bit platforms.
- add ability to break-out of flushTo loop with filter return -1
allowing in reduction in reader overhead.
Change-Id: Ic5cb2b9afa4d9470153971fc9197b07279e2b79d
- sched_yield and lock synchronization in reader thread
startup to give writer thread a chance to catch up
Bug: 17512203
Change-Id: I43cf0b4e2829b22b3ab4e537fa95ce13c76a869c
- permits easier determination of logd thread at
fault in a stack trace from debuggerd.
Bug: 14275676
Change-Id: Iac2c523147e2bcce34ab7ddcecd02582c5fa7cc0
* Create a new userspace log daemon for handling logging messages.
Original-Change-Id: I75267df16359684490121e6c31cca48614d79856
Signed-off-by: Nick Kralevich <nnk@google.com>
* Merge conflicts
* rename new syslog daemon to logd to prevent confusion with bionic syslog
* replace racy getGroups call with KISS call to client->getGid()
* Timestamps are filed at logging source
* insert entries into list in timestamp order
* Added LogTimeEntry tail filtration handling
* Added region locking around LogWriter list
* separate threads for each writer
* /dev/socket/logd* permissions
Signed-off-by: Mark Salyzyn <salyzyn@google.com>
(cherry picked from commit 3e76e0a497)
Author: Nick Kralevich <nnk@google.com>
Change-Id: Ice88b1412d8f9daa7f9119b2b5aaf684a5e28098
