Commit graph

32 commits

Author SHA1 Message Date
Mark Salyzyn
5a34d6ea43 logd: drop mSequence from LogBufferElement
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
2017-03-16 08:22:00 -07:00
Mark Salyzyn
501c373916 logd: specify clang format
Switch _all_ file's coding style to match to ease all future changes.

SideEffects: None
Test: compile
Bug: 35373582
Change-Id: I470cb17f64fa48f14aafc02f574e296bffe3a3f3
2017-03-13 10:31:09 -07:00
Mark Salyzyn
b5b8796785 logd: multiple identical do not report expired
Report multiple identical chatty messages differently than for
regular expire chatty messages.  Multiple identical will
report identical count, while spam filter will report
expire count.

This should reduce the expected flood of people confused
but chatty messages in continuous logcat output.

Test: gTest logd_unit_tests --gtest_filter=logd.multiple*
Change-Id: Iad93d3efc6a3938a4b87ccadddbd86626a015d44
2017-01-24 11:02:18 -08:00
Mark Salyzyn
a2c022257c logd: record multiple duplicate messages as chatty
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
2016-12-15 16:31:51 -08:00
Mark Salyzyn
0eeb06b932 utils: Add FastStrcmp.h
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
2016-12-09 12:40:17 -08:00
Mark Salyzyn
60636fa872 logd: getTag() functional for chatty entries
getTag() becomes invalid when entry is dropped because mMsg
disappears to save space; but the per-tag spam filter depends on it
still being valid.  Conserve space in LogBufferElement by optimizing
the size of the fields, then add a new mTag field that is set in the
object constructor.  Add an isBinary() method.

SideEffects: save 12 bytes/log message overhead on 64-bit.
Test: define DEBUG_CHECK_FOR_STALE_ENTRIES and look for stale entries
Bug: 32247044
Change-Id: Iaa5f416718a92c9e0e6ffd56bd5260d8b908d5c0
2016-10-25 21:48:33 +00:00
Mark Salyzyn
cfd5b080af system/core: preparation to pull back interfaces from android/log.h
Point to log/log.h where necessary, define LOG_TAG where necessary.
Accept that private/android_logger.h is suitable replacement for
log/logger.h and android/log.h.

Correct liblog/README

Effectively a cleanup and controlled select revert of
'system/core: drop or replace log/logger.h' and
'system/core: Replace log/log.h with android/log.h'.

Test: compile
Bug: 30465923
Change-Id: Ic2ad157bad6f5efe2c6af293a73bb753300b17a2
2016-10-20 08:11:39 -07:00
Mark Salyzyn
807e40ecc9 liblog: logd: Add android_lookupEventTag_len()
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
2016-10-03 11:08:34 -07:00
Mark Salyzyn
47684ca591 logd: Replace logd with chatty log tag
Bug: 30118730
Change-Id: I7c7802fef157d5ded02573621d21e0ded3df9745
2016-07-15 14:57:58 -07:00
Mark Salyzyn
2ad0bd0a9b logd: Allow (some) headers to be individually importable
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
2016-02-24 10:15:22 -08:00
Mark Salyzyn
86052a5d4f Merge "logd: liblog: logcat: Add LOG_ID_SECURITY" 2015-12-11 17:33:33 +00:00
Mark Salyzyn
7b87365ecf logd: readlog apps get logger_entry_v4
Adds the uid field to outgoing content for readlog applications.
AID_LOG, AID_ROOT and AID_SYSTEM gain access to the information.

Bug: 25996918
Change-Id: I0254303c19d174cbf5e722c38844be5c54410c85
2015-12-09 08:12:07 -08:00
Mark Salyzyn
083b037c07 logd: liblog: logcat: Add LOG_ID_SECURITY
- Largish commit, buffer and access controls done together
- Add LOG_ID_SECURITY binary content log
- Add "default" meta buffer
- allow LOG_ID_SECURITY only from AID_SYSTEM and AID_ROOT UID & GID
- Use __android_log_security() to gate logging
- Add __android_log_security_bwrite() native access to security
  logging.
- Add liblog.__security_buffer end-to-end gTest

Bug: 26029733
Change-Id: Ibcf5b4660c17c1aa6902c0d93f8ffd29c93d9a93
2015-12-08 16:46:29 -08:00
Mark Salyzyn
c2e7d4965f Revert "liblog: resolve deadlocks"
This reverts commit 7a2a307192.

Bug: 25693940
Change-Id: I9a7c926289e972f80c03c92e33535e1dedaa7381
2015-11-16 19:00:41 +00:00
Mark Salyzyn
7a2a307192 liblog: resolve deadlocks
Although ever present, an increased regression introduced with
commit b6bee33182 (liblog: logd:
support logd.timestamp = monotonic).

A signal handler can interrupt in locked context, if log is written
in the signal handler, we are in deadlock. Block signals while we
are locked. Separate out timestamp lock from is loggable lock to
reduce contention situations. Provide a best-guess response if
lock would fail in timestamp path.

Bug: 25563384
Change-Id: I6dccd6b99ebace1c473c03a785a35c63ed5c6a8a
2015-11-12 15:39:04 -08:00
Mark Salyzyn
758058ffd8 logd: object layer format statistics
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
2015-10-05 09:27:57 -07:00
Mark Salyzyn
ddda212faa logd: optimize code hotspots
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
2015-10-02 16:45:22 -07:00
Mark Salyzyn
ed777e9eec logd: serialize accesses to stats helpers
Quick low-risk to resolve possible hash table corruption.
Resolved an unlikely path memory leak.

ToDo: replace lock with nested lock so no lock
      helpers are required.

Bug: 22068332
Change-Id: I303ab06608502c7d61d42f111a9c43366f184d0c
2015-06-25 07:39:24 -07:00
Mark Salyzyn
ee49c6a670 logd: missing klogd content
- 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
2015-06-15 21:19:10 +00:00
Mark Salyzyn
e59c469fa8 logd: filter on __android_log_is_loggable
- Default level when not specified is ANDROID_LOG_VERBOSE
  which is inert.

Bug: 20416721
Bug: 19544788
Bug: 17760225
Change-Id: Icc098e53dc47ceaaeb24ec42eb6f61d6430ec2f6
2015-06-12 10:35:09 -07:00
Mark Salyzyn
047cc0729f logd: filters remove leading expire messages and rate
- Cleanup resulting from experience and feedback
- When filtering inside logd, drop any leading expire messages, they
  are cluttering up leading edge of tombstones (which filter by pid)
- Increase and introduce EXPIRE_RATELIMIT from 1 to 10 seconds
- Increase EXPIRE_THRESHOLD from 4 to 10 count
- Improve the expire messages from:
   logd : uid=1000(system) too chatty comm=com.google.android.phone,
                                                   expire 2800 lines
  change tag to be more descriptive, and reduce accusatory tone to:
   chatty : uid=1000(system) com.google.android.phone expire 2800
                                                               lines
- if the UID name forms a prefix for comm name, then drop UID name

Change-Id: Ied7cc04c0ab3ae02167649a0b97378e44ef7b588
2015-06-05 08:05:05 -07:00
Mark Salyzyn
d1371a8b8b Merge "logd: Add TID statistics" 2015-05-13 16:17:37 +00:00
Mark Salyzyn
7718778793 logd: Cleanup
- Android Coding Standard for Constructors
- Side effects NONE

Change-Id: I2cda9dd73f3ac3ab58f394015cb810820093d47b
2015-05-12 15:51:46 -07:00
Mark Salyzyn
17ed6797df logd: Add TID statistics
Bug: 19608965
Change-Id: Ifbf0b00c48ef12b5970b9f9f217bd1dd8f587f2c
2015-05-12 12:57:25 -07:00
Mark Salyzyn
344bff4391 logd: Add Tag statistics
- Optional class of statistics for events Tags
- export tagToName from LogBuffer (located in main.cp to address
  https://android-review.googlesource.com/#/c/110204)
- Can not handle dropped because getTag() can not work,
  will need to be fixed if we start filtering.

Bug: 19608965
Change-Id: I7b90607ca588bf37bab71f19b1570a290e772776
2015-05-12 12:53:27 -07:00
Mark Salyzyn
21fb7e0b75 logd: improve details on chatty records
- Report applications UID, TID/PID by name.
- change wording to have an accurate connotation
- drop privilege check since filtered upstream

Bug: 19608965
Bug: 20334069
Bug: 20370119
Change-Id: I2b1c26580b4c2de293874214ff5ae745546f3cca
2015-04-30 13:14:51 -07:00
Mark Salyzyn
ab0dcf6828 logd: annotate worst-UID pruned entries
- internal dropped entries are associated by prune by worst UID
  and are applied by UID and by PID
- track dropped entries by rewriting them in place
- merge similar dropped entries together for same UID(implied),
  PID and TID so that blame can more clearly be placed
- allow aging of dropped entries by the general backgound pruning
- report individual dropped entries formatted to reader
- add statistics to track dropped entries by UID, the combination
  of statistics and dropped logging can track over-the-top Chattiest
  clients.

Bug: 19608965
Change-Id: Ibc68480df0c69c55703270cd70c6b26aea165853
2015-04-10 15:45:08 -07:00
Mark Salyzyn
f7c0f75275 logd: replace internal CLOCK_MONOTONIC use with sequence numbers
- 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
2015-03-18 12:43:23 -07:00
Mark Salyzyn
b992d0d7d3 logd: liblog: Thread IDs missing from logcat -v thread
- stuff caller's thread id into the packet.

Bug: 13568206
Change-Id: I02d0cdf9b1d9e839ff8969f591db42dfe6e4cc95
2014-03-21 10:37:44 -07:00
Mark Salyzyn
fa3716b250 logd: liblog: logcat: Arbitrary time to tail
Change-Id: I10e8d92c933e31ee11e78d2d1114261a30c4be0e
2014-03-14 10:23:51 -07:00
Mark Salyzyn
7e2f83c0bc logd: liblog: 64-bit issues
- structure packing
- move towards log_time from struct timespec
- extend log_time to cover differences between
  log_time and struct timespec

Change-Id: I106ed0b609917306d170044054b5b32645f2a295
2014-03-05 16:12:28 -08:00
Mark Salyzyn
0175b0747a logd: initial checkin.
* 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
2014-02-26 09:52:35 -08:00