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
diff --git a/liblog/event_tag_map.cpp b/liblog/event_tag_map.cpp
index fec5dee..1f08eb4 100644
--- a/liblog/event_tag_map.cpp
+++ b/liblog/event_tag_map.cpp
@@ -19,6 +19,7 @@
#include <errno.h>
#include <fcntl.h>
#include <inttypes.h>
+#include <limits.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
@@ -26,15 +27,63 @@
#include <experimental/string_view>
#include <functional>
+#include <string>
#include <unordered_map>
#include <log/event_tag_map.h>
+#include <utils/FastStrcmp.h>
+#include <utils/RWLock.h>
+#include <private/android_logger.h>
#include "log_portability.h"
+#include "logd_reader.h"
#define OUT_TAG "EventTagMap"
-typedef std::experimental::string_view MapString;
+class MapString {
+private:
+ const std::string* alloc; // HAS-AN
+ const std::experimental::string_view str; // HAS-A
+
+public:
+ operator const std::experimental::string_view() const { return str; }
+
+ const char* data() const { return str.data(); }
+ size_t length() const { return str.length(); }
+
+ bool operator== (const MapString& rval) const {
+ if (length() != rval.length()) return false;
+ if (length() == 0) return true;
+ return fastcmp<strncmp>(data(), rval.data(), length()) == 0;
+ }
+ bool operator!= (const MapString& rval) const {
+ return !(*this == rval);
+ }
+
+ MapString(const char* str, size_t len) : alloc(NULL), str(str, len) { }
+ explicit MapString(const std::string& str) :
+ alloc(new std::string(str)),
+ str(alloc->data(), alloc->length()) { }
+ MapString(MapString &&rval) :
+ alloc(rval.alloc),
+ str(rval.data(), rval.length()) {
+ rval.alloc = NULL;
+ }
+ explicit MapString(const MapString &rval) :
+ alloc(rval.alloc ? new std::string(*rval.alloc) : NULL),
+ str(alloc ? alloc->data() : rval.data(), rval.length()) { }
+
+ ~MapString() { if (alloc) delete alloc; }
+};
+
+// Hash for MapString
+template <> struct std::hash<MapString>
+ : public std::unary_function<const MapString&, size_t> {
+ size_t operator()(const MapString& __t) const noexcept {
+ if (!__t.length()) return 0;
+ return std::hash<std::experimental::string_view>()(std::experimental::string_view(__t));
+ }
+};
typedef std::pair<MapString, MapString> TagFmt;
@@ -60,6 +109,10 @@
private:
std::unordered_map<uint32_t, TagFmt> Idx2TagFmt;
+ std::unordered_map<TagFmt, uint32_t> TagFmt2Idx;
+ std::unordered_map<MapString, uint32_t> Tag2Idx;
+ // protect unordered sets
+ android::RWLock rwlock;
public:
EventTagMap() {
@@ -69,6 +122,8 @@
~EventTagMap() {
Idx2TagFmt.clear();
+ TagFmt2Idx.clear();
+ Tag2Idx.clear();
for (size_t which = 0; which < NUM_MAPS; ++which) {
if (mapAddr[which]) {
munmap(mapAddr[which], mapLen[which]);
@@ -79,37 +134,93 @@
bool emplaceUnique(uint32_t tag, const TagFmt& tagfmt, bool verbose = false);
const TagFmt* find(uint32_t tag) const;
+ int find(TagFmt&& tagfmt) const;
+ int find(MapString&& tag) const;
};
bool EventTagMap::emplaceUnique(uint32_t tag, const TagFmt& tagfmt, bool verbose) {
- std::unordered_map<uint32_t, TagFmt>::const_iterator it;
- it = Idx2TagFmt.find(tag);
- if (it != Idx2TagFmt.end()) {
- if (verbose) {
- fprintf(stderr,
- OUT_TAG ": duplicate tag entries %" PRIu32
- ":%.*s:%.*s and %" PRIu32 ":%.*s:%.*s)\n",
- it->first,
- (int)it->second.first.length(), it->second.first.data(),
- (int)it->second.second.length(), it->second.second.data(),
- tag,
- (int)tagfmt.first.length(), tagfmt.first.data(),
- (int)tagfmt.second.length(), tagfmt.second.data());
+ bool ret = true;
+ static const char errorFormat[] = OUT_TAG ": duplicate tag entries %" PRIu32
+ ":%.*s:%.*s and %" PRIu32
+ ":%.*s:%.*s)\n";
+ android::RWLock::AutoWLock writeLock(rwlock);
+ {
+ std::unordered_map<uint32_t, TagFmt>::const_iterator it;
+ it = Idx2TagFmt.find(tag);
+ if (it != Idx2TagFmt.end()) {
+ if (verbose) {
+ fprintf(stderr, errorFormat,
+ it->first,
+ (int)it->second.first.length(), it->second.first.data(),
+ (int)it->second.second.length(), it->second.second.data(),
+ tag,
+ (int)tagfmt.first.length(), tagfmt.first.data(),
+ (int)tagfmt.second.length(), tagfmt.second.data());
+ }
+ ret = false;
+ } else {
+ Idx2TagFmt.emplace(std::make_pair(tag, tagfmt));
}
- return false;
}
- Idx2TagFmt.emplace(std::make_pair(tag, tagfmt));
- return true;
+ {
+ std::unordered_map<TagFmt, uint32_t>::const_iterator it;
+ it = TagFmt2Idx.find(tagfmt);
+ if (it != TagFmt2Idx.end()) {
+ if (verbose) {
+ fprintf(stderr, errorFormat,
+ it->second,
+ (int)it->first.first.length(), it->first.first.data(),
+ (int)it->first.second.length(), it->first.second.data(),
+ tag,
+ (int)tagfmt.first.length(), tagfmt.first.data(),
+ (int)tagfmt.second.length(), tagfmt.second.data());
+ }
+ ret = false;
+ } else {
+ TagFmt2Idx.emplace(std::make_pair(tagfmt, tag));
+ }
+ }
+
+ {
+ std::unordered_map<MapString, uint32_t>::const_iterator it;
+ it = Tag2Idx.find(tagfmt.first);
+ if (!tagfmt.second.length() && (it != Tag2Idx.end())) {
+ Tag2Idx.erase(it);
+ it = Tag2Idx.end();
+ }
+ if (it == Tag2Idx.end()) {
+ Tag2Idx.emplace(std::make_pair(tagfmt.first, tag));
+ }
+ }
+
+ return ret;
}
const TagFmt* EventTagMap::find(uint32_t tag) const {
std::unordered_map<uint32_t, TagFmt>::const_iterator it;
+ android::RWLock::AutoRLock readLock(const_cast<android::RWLock&>(rwlock));
it = Idx2TagFmt.find(tag);
if (it == Idx2TagFmt.end()) return NULL;
return &(it->second);
}
+int EventTagMap::find(TagFmt&& tagfmt) const {
+ std::unordered_map<TagFmt, uint32_t>::const_iterator it;
+ android::RWLock::AutoRLock readLock(const_cast<android::RWLock&>(rwlock));
+ it = TagFmt2Idx.find(std::move(tagfmt));
+ if (it == TagFmt2Idx.end()) return -1;
+ return it->second;
+}
+
+int EventTagMap::find(MapString&& tag) const {
+ std::unordered_map<MapString, uint32_t>::const_iterator it;
+ android::RWLock::AutoRLock readLock(const_cast<android::RWLock&>(rwlock));
+ it = Tag2Idx.find(std::move(tag));
+ if (it == Tag2Idx.end()) return -1;
+ return it->second;
+}
+
// Scan one tag line.
//
// "*pData" should be pointing to the first digit in the tag number. On
@@ -380,3 +491,75 @@
if (*cp) *cp = '\0'; // Trigger copy on write :-( and why deprecated.
return tagStr;
}
+
+// Look up tagname, generate one if necessary, and return a tag
+LIBLOG_ABI_PUBLIC int android_lookupEventTagNum(EventTagMap* map,
+ const char* tagname,
+ const char* format,
+ int prio) {
+ size_t len = strlen(tagname);
+ if (!len) {
+ errno = EINVAL;
+ return -1;
+ }
+
+ if ((prio != ANDROID_LOG_UNKNOWN) && (prio < ANDROID_LOG_SILENT) &&
+ !__android_log_is_loggable_len(prio, tagname, len,
+ __android_log_is_debuggable() ?
+ ANDROID_LOG_VERBOSE :
+ ANDROID_LOG_DEBUG)) {
+ errno = EPERM;
+ return -1;
+ }
+
+ if (!format) format="";
+ ssize_t fmtLen = strlen(format);
+ int ret = map->find(TagFmt(std::make_pair(MapString(tagname, len),
+ MapString(format, fmtLen))));
+ if (ret != -1) return ret;
+
+ // call event tag service to arrange for a new tag
+ char *buf = NULL;
+ // Can not use android::base::StringPrintf, asprintf + free instead.
+ static const char command_template[] = "getEventTag name=%s format=\"%s\"";
+ ret = asprintf(&buf, command_template, tagname, format);
+ if (ret > 0) {
+ // Add some buffer margin for an estimate of the full return content.
+ char *cp;
+ size_t size = ret - strlen(command_template) +
+ strlen("65535\n4294967295\t?\t\t\t?\t# uid=32767\n\n\f?success?");
+ if (size > (size_t)ret) {
+ cp = static_cast<char*>(realloc(buf, size));
+ if (cp) {
+ buf = cp;
+ } else {
+ size = ret;
+ }
+ } else {
+ size = ret;
+ }
+ // Ask event log tag service for an allocation
+ if (__send_log_msg(buf, size) >= 0) {
+ buf[size - 1] = '\0';
+ unsigned long val = strtoul(buf, &cp, 10); // return size
+ if ((buf != cp) && (val > 0) && (*cp == '\n')) { // truncation OK
+ val = strtoul(cp + 1, &cp, 10); // allocated tag number
+ if ((val > 0) && (val < UINT32_MAX) && (*cp == '\t')) {
+ free(buf);
+ ret = val;
+ // cache
+ map->emplaceUnique(ret, TagFmt(std::make_pair(
+ MapString(std::string(tagname, len)),
+ MapString(std::string(format, fmtLen)))));
+ return ret;
+ }
+ }
+ }
+ free(buf);
+ }
+
+ // Hail Mary
+ ret = map->find(MapString(tagname, len));
+ if (ret == -1) errno = ESRCH;
+ return ret;
+}
diff --git a/liblog/fake_log_device.c b/liblog/fake_log_device.c
index 4939221..957129e 100644
--- a/liblog/fake_log_device.c
+++ b/liblog/fake_log_device.c
@@ -715,6 +715,12 @@
return redirectWritev(fd, vector, count);
}
+LIBLOG_HIDDEN ssize_t __send_log_msg(char *buf __unused,
+ size_t buf_size __unused)
+{
+ return -ENODEV;
+}
+
LIBLOG_ABI_PUBLIC int __android_log_is_loggable(int prio,
const char *tag __unused,
int def)
diff --git a/liblog/include/log/event_tag_map.h b/liblog/include/log/event_tag_map.h
index 22e62ec..e57e47b 100644
--- a/liblog/include/log/event_tag_map.h
+++ b/liblog/include/log/event_tag_map.h
@@ -58,6 +58,12 @@
const char* android_lookupEventFormat_len(const EventTagMap* map,
size_t* len, unsigned int tag);
+/*
+ * Look up tagname, generate one if necessary, and return a tag
+ */
+int android_lookupEventTagNum(EventTagMap* map, const char* tagname,
+ const char* format, int prio);
+
#ifdef __cplusplus
}
#endif
diff --git a/liblog/logd_reader.c b/liblog/logd_reader.c
index 99d7fea..ccc7da8 100644
--- a/liblog/logd_reader.c
+++ b/liblog/logd_reader.c
@@ -37,6 +37,7 @@
#include "config_read.h"
#include "log_portability.h"
+#include "logd_reader.h"
#include "logger.h"
/* branchless on many architectures. */
@@ -324,6 +325,11 @@
return ret;
}
+LIBLOG_HIDDEN ssize_t __send_log_msg(char *buf, size_t buf_size)
+{
+ return send_log_msg(NULL, NULL, buf, buf_size);
+}
+
static int check_log_success(char *buf, ssize_t ret)
{
if (ret < 0) {
diff --git a/liblog/logd_reader.h b/liblog/logd_reader.h
new file mode 100644
index 0000000..04c2cf2
--- /dev/null
+++ b/liblog/logd_reader.h
@@ -0,0 +1,30 @@
+/*
+ * Copyright (C) 2016 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+#ifndef _LIBLOG_LOGD_READER_H__
+#define _LIBLOG_LOGD_READER_H__
+
+#include <unistd.h>
+
+#include "log_portability.h"
+
+__BEGIN_DECLS
+
+LIBLOG_HIDDEN ssize_t __send_log_msg(char *buf, size_t buf_size);
+
+__END_DECLS
+
+#endif /* _LIBLOG_LOGD_READER_H__ */
diff --git a/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp
index 5420f68..dc411c3 100644
--- a/liblog/tests/liblog_benchmark.cpp
+++ b/liblog/tests/liblog_benchmark.cpp
@@ -15,6 +15,8 @@
*/
#include <fcntl.h>
+#include <inttypes.h>
+#include <poll.h>
#include <sys/endian.h>
#include <sys/socket.h>
#include <sys/types.h>
@@ -22,6 +24,7 @@
#include <unordered_set>
+#include <android-base/file.h>
#include <cutils/sockets.h>
#include <log/event_tag_map.h>
#include <private/android_logger.h>
@@ -695,7 +698,7 @@
// Keep maps around for multiple iterations
static std::unordered_set<uint32_t> set;
-static const EventTagMap* map;
+static EventTagMap* map;
static bool prechargeEventMap() {
if (map) return true;
@@ -785,3 +788,142 @@
StopBenchmarkTiming();
}
BENCHMARK(BM_lookupEventFormat);
+
+/*
+ * Measure the time it takes for android_lookupEventTagNum plus above
+ */
+static void BM_lookupEventTagNum(int iters) {
+
+ prechargeEventMap();
+
+ std::unordered_set<uint32_t>::const_iterator it = set.begin();
+
+ for (int i = 0; i < iters; ++i) {
+ size_t len;
+ const char* name = android_lookupEventTag_len(map, &len, (*it));
+ std::string Name(name, len);
+ const char* format = android_lookupEventFormat_len(map, &len, (*it));
+ std::string Format(format, len);
+ StartBenchmarkTiming();
+ android_lookupEventTagNum(map, Name.c_str(), Format.c_str(),
+ ANDROID_LOG_UNKNOWN);
+ StopBenchmarkTiming();
+ ++it;
+ if (it == set.end()) it = set.begin();
+ }
+
+}
+BENCHMARK(BM_lookupEventTagNum);
+
+// Must be functionally identical to liblog internal __send_log_msg.
+static void send_to_control(char *buf, size_t len)
+{
+ int sock = socket_local_client("logd",
+ ANDROID_SOCKET_NAMESPACE_RESERVED,
+ SOCK_STREAM);
+ if (sock < 0) return;
+ size_t writeLen = strlen(buf) + 1;
+
+ ssize_t ret = TEMP_FAILURE_RETRY(write(sock, buf, writeLen));
+ if (ret <= 0) {
+ close(sock);
+ return;
+ }
+ while ((ret = read(sock, buf, len)) > 0) {
+ if (((size_t)ret == len) || (len < PAGE_SIZE)) {
+ break;
+ }
+ len -= ret;
+ buf += ret;
+
+ struct pollfd p = {
+ .fd = sock,
+ .events = POLLIN,
+ .revents = 0
+ };
+
+ ret = poll(&p, 1, 20);
+ if ((ret <= 0) || !(p.revents & POLLIN)) {
+ break;
+ }
+ }
+ close(sock);
+}
+
+static void BM_lookupEventTagNum_logd_new(int iters) {
+ fprintf(stderr, "WARNING: "
+ "This test can cause logd to grow in size and hit DOS limiter\n");
+ // Make copies
+ static const char empty_event_log_tags[] = "# content owned by logd\n";
+ static const char dev_event_log_tags_path[] = "/dev/event-log-tags";
+ std::string dev_event_log_tags;
+ if (android::base::ReadFileToString(dev_event_log_tags_path,
+ &dev_event_log_tags) &&
+ (dev_event_log_tags.length() == 0)) {
+ dev_event_log_tags = empty_event_log_tags;
+ }
+ static const char data_event_log_tags_path[] = "/data/misc/logd/event-log-tags";
+ std::string data_event_log_tags;
+ if (android::base::ReadFileToString(data_event_log_tags_path,
+ &data_event_log_tags) &&
+ (data_event_log_tags.length() == 0)) {
+ data_event_log_tags = empty_event_log_tags;
+ }
+
+ for (int i = 0; i < iters; ++i) {
+ char buffer[256];
+ memset(buffer, 0, sizeof(buffer));
+ log_time now(CLOCK_MONOTONIC);
+ char name[64];
+ snprintf(name, sizeof(name), "a%" PRIu64, now.nsec());
+ snprintf(buffer, sizeof(buffer),
+ "getEventTag name=%s format=\"(new|1)\"", name);
+ StartBenchmarkTiming();
+ send_to_control(buffer, sizeof(buffer));
+ StopBenchmarkTiming();
+ }
+
+ // Restore copies (logd still know about them, until crash or reboot)
+ if (dev_event_log_tags.length() &&
+ !android::base::WriteStringToFile(dev_event_log_tags,
+ dev_event_log_tags_path)) {
+ fprintf(stderr, "WARNING: "
+ "failed to restore %s\n", dev_event_log_tags_path);
+ }
+ if (data_event_log_tags.length() &&
+ !android::base::WriteStringToFile(data_event_log_tags,
+ data_event_log_tags_path)) {
+ fprintf(stderr, "WARNING: "
+ "failed to restore %s\n", data_event_log_tags_path);
+ }
+ fprintf(stderr, "WARNING: "
+ "Restarting logd to make it forget what we just did\n");
+ system("stop logd ; start logd");
+}
+BENCHMARK(BM_lookupEventTagNum_logd_new);
+
+static void BM_lookupEventTagNum_logd_existing(int iters) {
+ prechargeEventMap();
+
+ std::unordered_set<uint32_t>::const_iterator it = set.begin();
+
+ for (int i = 0; i < iters; ++i) {
+ size_t len;
+ const char* name = android_lookupEventTag_len(map, &len, (*it));
+ std::string Name(name, len);
+ const char* format = android_lookupEventFormat_len(map, &len, (*it));
+ std::string Format(format, len);
+
+ char buffer[256];
+ snprintf(buffer, sizeof(buffer),
+ "getEventTag name=%s format=\"%s\"",
+ Name.c_str(), Format.c_str());
+
+ StartBenchmarkTiming();
+ send_to_control(buffer, sizeof(buffer));
+ StopBenchmarkTiming();
+ ++it;
+ if (it == set.end()) it = set.begin();
+ }
+}
+BENCHMARK(BM_lookupEventTagNum_logd_existing);
diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp
index 8b9f0f0..5faf8e1 100644
--- a/liblog/tests/liblog_test.cpp
+++ b/liblog/tests/liblog_test.cpp
@@ -2929,3 +2929,19 @@
}
// Do not test default seconds, to allow liblog to tune freely
}
+
+TEST(liblog, android_lookupEventTagNum) {
+#ifdef __ANDROID__
+ EventTagMap* map = android_openEventTagMap(NULL);
+ EXPECT_TRUE(NULL != map);
+ std::string Name = android::base::StringPrintf("a%d", getpid());
+ int tag = android_lookupEventTagNum(map, Name.c_str(), "(new|1)", ANDROID_LOG_UNKNOWN);
+ android_closeEventTagMap(map);
+ if (tag == -1) system("tail -3 /dev/event-log-tags >&2");
+ EXPECT_NE(-1, tag);
+ EXPECT_NE(0, tag);
+ EXPECT_GT(UINT32_MAX, (unsigned)tag);
+#else
+ GTEST_LOG_(INFO) << "This test does nothing.\n";
+#endif
+}
diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp
index 0db33b7..adf583b 100644
--- a/logd/tests/logd_test.cpp
+++ b/logd/tests/logd_test.cpp
@@ -48,7 +48,7 @@
if (write(sock, buf, strlen(buf) + 1) > 0) {
ssize_t ret;
while ((ret = read(sock, buf, len)) > 0) {
- if ((size_t)ret == len) {
+ if (((size_t)ret == len) || (len < PAGE_SIZE)) {
break;
}
len -= ret;