Commit graph

21 commits

Author SHA1 Message Date
Mark Salyzyn
dc3c14720f liblog: clock_gettime, clock_getres and time benchmarks
Add local BM_time_clock_gettime_*, BM_time_clock_getres_* and
BM_time_time benchmarks.  Relates to the bionic benchmarks of
the same names, except adds CLOCK_MONOTONIC_RAW.  Added here for
developer convenience whenever updates to the liblog or logd
code base need integration testing.

ToDo: add liblog gTests that analyse the benchmark data to confirm
that the specified integrated device has vdso access to all the
pertinent clock sources.  Add liblog local benchmarks and tests to
measure the device clock drift of each possible liblog clock
source to help evaluate device configuration.

Test: liblog_benchmarks --benchmark_filter=BM_time*
Bug: 63737556
Bug: 69423514
Change-Id: Ibafe0880d976ef2b3885765f71e0ba6c99d56f2a
2018-01-16 08:11:59 -08:00
Mark Salyzyn
1520bd43b0 liblog: benchmarks use google-benchmark library
Remove our circa 2014 snapshot of the google benchmarking library, and
use the now very stable google-benchmark suite. Some porting effort,
and deal with some benchmarking saddle points that take too long to
sort out. Focus on minimal API changes, _odd_ new behaviors, and style.

Test: liblog_benchmarks, ensure results in about the same range
Bug: 69423514
Change-Id: I2add1df9cb664333bcf983b57121ae151b26935b
2018-01-16 08:11:26 -08:00
Mark Salyzyn
fe8c96d152 liblog: benchmark add BM_log_event_overhead_42 for a well known tag
Measure the cost of using a known test event log tag from
system/core/logcat/event.logtags:

42    answer (to life the universe etc|3)

Test: liblog_benchmarks BM_log_event_overhead_42
Bug: 36683634
Change-Id: Ibd4be82bebfcedd381c84e8078cf6d05a636aa98
2017-03-31 13:25:36 -07:00
Mark Salyzyn
81321a7980 liblog: replace "frontend" with "transport"
We still do not have any users of the 'frontend' interface, let's
right a wrong and rename it to 'transport' as it makes more sense.
Renames android_log_set_frontend, android_log_get_frontend and
include/log/log_frontend.h.

SideEffects: None
Test: gTest liblog-unit-tests
Bug: 27405083
Change-Id: I7c1c0f3dfdc7cf047285403e306edbd16ad1324d
2017-03-09 09:36:34 -08:00
Mark Salyzyn
2ed51d708e liblog: specify clang format
Switch coding style to match

SideEffects: None
Test: compile
Bug: 27405083
Change-Id: Id426d5c5e3b18f2ceec22b31bbc9781aabf6bcca
2017-03-09 09:36:19 -08:00
Mark Salyzyn
8f2492f582 liblog: benchmark: Use local LOGGER_NULL frontend
Additional benchmarks to check the effects and performance of the
frontend changes.

Test: manual liblog-benchmarks
Bug: 27405083
Change-Id: I2a9dba81b70e9d71cdb8de1b35e8dff099ad6038
2017-02-08 13:37:44 -08:00
Mark Salyzyn
c9e5f37166 liblog: add android_lookupEventTagNum
android_lookupEventTagNum added.  Adds support for creating a new
log tag at runtime, registered to the logd service.

Tested on Hikey, all services stopped, shell only access, CPUs not
locked (there is enough repeatability on this platform).

$ /data/nativetest64/liblog-benchmarks/liblog-benchmarks BM_lookupEventTagNum

                          iterations      ns/op
Precharge: start
Precharge: stop 231
NB: only Tag matching, linear lookup (as reference, before unordered_map)
BM_lookupEventTagNum         1000000       1017
NB: unordered_map with full Tag & Format lookup, but with Tag hashing
BM_lookupEventTagNum         2000000        683
NB: with full Tag & Format hash and lookup for matching
BM_lookupEventTagNum         2000000        814
NB: only Tag matching (Hail Mary path)
BM_lookupEventTagNum         5000000        471

Because the database can now be dynamic, we added reader/writer locks
which adds a 65ns (uncontended) premium on lookups, and switch to
check for an allocation adds 25ns (either open code, or using
string_view, no difference) which means our overall speed takes 90%
as long as the requests did before we switched to unordered_map.
Faster than before where we originally utilized binary lookup on
static content, but not by much.  Dynamic updates that are not cached
locally take the following times to acquire long path to logd to
generate.

BM_lookupEventTag           20000000         139
BM_lookupEventTag_NOT       20000000         87
BM_lookupEventFormat        20000000         139
BM_lookupEventTagNum_logd_new   5000         335936
BM_lookupEventTagNum_logd_existing 10000     249226

The long path pickups are mitigated by the built-in caching, and
the public mapping in /dev/event-log-tags.

SideEffects: Event tags and signal handlers do not mix
Test: liblog benchmarks
Bug: 31456426
Change-Id: I69e6489d899cf35cdccffcee0d8d7cad469ada0a
2017-02-02 15:21:15 -08:00
Mark Salyzyn
0b37d01f72 liblog: event_tag_map benchmark
Tested on Hikey, all services stopped, shell only access, CPUs not
locked.

$ /data/nativetest64/liblog-benchmarks/liblog-benchmarks BM_lookupEvent*
                          iterations      ns/op
Precharge: start
Precharge: stop 231
BM_lookupEventTag           10000000        153
BM_lookupEventTag_NOT       20000000        139
BM_lookupEventFormat        10000000        153

Test: run benchmarks
Bug: 31456426
Change-Id: Ice3ffa0b061d9a6b917718b2d9aedcc2348b7005
2016-11-28 15:15:58 -08: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
6584d0a35a liblog: Replace log/log.h with android/log.h
Move all liblog related content into android/log.h, and make
log/log.h points to android/log.h.

Test: Compile
Bug: 26552300
Bug: 31289077
Change-Id: I858e0ebe047b86f2a8530a99bc9c380d3d58edbb
2016-09-30 12:47:05 -07:00
Mark Salyzyn
004cd3c55d liblog: logd: logcat: deprecate log/log_read.h
Always used in combination with log/logger.h except in log_time.cpp,
and not used externally.  As a result liblog has to support stl, a
small price to pay since goal is to convert liblog to C++ internally.

Test: compile
Bug: 31456426
Bug: 26552300
Bug: 31289077
Change-Id: I72828ec807d0a2c8e40bbdebd7a69f147a7ca5a9
2016-09-30 12:47:05 -07:00
Mark Salyzyn
305374cf0f logger: validate hdr_size field in logger entry
- check hdr_size to make sure it is in the expected range
  from sizeof entry_v1 to entry (entry_v4).
- alter msg() method to report NULL on invalid hdr_size
- alter all users of msg() method.

Bug: 30947841
Change-Id: I9bc1740d7aa9f37df5be966c18de1fb9de63d5dd
2016-08-23 14:51:50 -07:00
Elliott Hughes
5f4a946c09 Use alignas for alignment.
Change-Id: I427c407a188682a360c74b2bd5a44dd62551ea66
2016-06-06 19:59:45 -07:00
Mark Salyzyn
a67d8a53c7 liblog: is loggable is flaky
- Deal with __android_log_is_loggable inside signal handler by
  treating a lock contention system call as more costly than reading
  the associated property directly. Rather waiting around in a
  contended stat to hit cache.
- Check both the individual known __system_property_serial() and
  global __system_property_area_serial() to detect updates or
  additions to the properties to respond in the most aggressive and
  timely manner. __android_log_is_loggable() return at max CPU
  clockrate on a N9 in 61ns.
- Craft a common do_cache2 inline that adds the above to the other
  functions that utilize cache handling and preserves (within 3ns)
  performance in android_log_clockid() and __android_log_security().
  These functions return at max CPU clockrate on a N9 in 23ns.

Bug: 19544788
Bug: 25693940
Bug: 25792367
Bug: 26178938
Change-Id: I9cd94598f5c558e946b93977ad3714a4b03d0422
2015-12-22 10:06:22 -08:00
Mark Salyzyn
163ebdc7cd liblog: test: pmsg overhead measurement
This test tells us that scatter-gather (writev instead of write)
carries a small ~2% penalty. Unaligned buffer carry a similar
additional penalty. On N9 it takes 3us to 22us _just_ to write
the pmsg logs, depending on size. Some assumptions about the
socket read and write performance for the main logging can be made
from tracking these results and should improve design decisions.

Bug: 18771697
Bug: 23685592
Change-Id: Id4d64c449140e4f39078c62b0097e403df91fe0c
2015-12-16 13:12:56 -08:00
Mark Salyzyn
1ac79cbd89 liblog: Add BM_is_loggable benchmark
- On a N9 64-bit benchmark, the __android_log_is_loggable overhead
  is roughly 500ns (1/2 of a syscall?)

Bug: 19544788
Bug: 17760225
Bug: 20416721
Change-Id: Ib9e4d06d96e1b19ca5d459e569ead451ef47a9c0
2015-04-24 07:59:44 -07:00
Mark Salyzyn
2d3f38a6b8 liblog: introduce ANDROID_LOG_* flags
Move away from using POSIX open(2) flags and introduce ANDROID_LOG_* flags to
replace them. Add security by preventing random mode flags from getting into
underlying POSIX calls. ANDROID_LOG_* flags overlap POSIX O_* flag definitions.

Change-Id: Ib32bb64c287e8bf150be62242e1ba46bb37839fc
2015-02-25 17:44:18 +00:00
Mark Salyzyn
a04464adaf liblog: set -Werror
- Deal with some -Wunused issues
- Cleanup UNUSED to __unused transition

Change-Id: Icd33808d4c974625f4fd0a126a90a2b4c90c8314
2014-05-07 16:56:21 -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
819c58a8ca liblog: Add liblog test suite
(cherry picked from commit 8d1fdb5093)

Change-Id: Ia457d518b4e7ff37e840336ff0c48583709700d4
2014-01-27 15:17:39 -08:00