Implemented typed, thread-specific logging system. Currently supported types are:
* Strings
* Integers
* Floats
* Timestamps
* Process IDs
Added printf-like formatted logging using mentioned types.
Test: included in this CL
Bug: 29421410
Change-Id: Ie07b78d8d39c32fcc8a122ffa9b1b7082800b990
diff --git a/include/media/nbaio/NBLog.h b/include/media/nbaio/NBLog.h
index acf2d31..ff10b8c 100644
--- a/include/media/nbaio/NBLog.h
+++ b/include/media/nbaio/NBLog.h
@@ -40,6 +40,12 @@
EVENT_RESERVED,
EVENT_STRING, // ASCII string, not NUL-terminated
EVENT_TIMESTAMP, // clock_gettime(CLOCK_MONOTONIC)
+ EVENT_INTEGER,
+ EVENT_FLOAT,
+ EVENT_PID,
+ EVENT_START_FMT, // logFormat start event: entry includes format string, following
+ // entries contain format arguments
+ EVENT_END_FMT, // end of logFormat argument list
};
// ---------------------------------------------------------------------------
@@ -73,6 +79,13 @@
// byte[2+mLength] duplicate copy of mLength to permit reverse scan
// byte[3+mLength] start of next log entry
+ static void appendInt(String8 *body, const void *data);
+ static void appendFloat(String8 *body, const void *data);
+ static void appendPID(String8 *body, const void *data);
+ static int handleFormat(const char *fmt, size_t length, const uint8_t *data,
+ String8 *timestamp, String8 *body);
+ static void appendTimestamp(String8 *body, const void *data);
+
public:
// Located in shared memory, must be POD.
@@ -133,7 +146,15 @@
virtual void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));
virtual void logvf(const char *fmt, va_list ap);
virtual void logTimestamp();
- virtual void logTimestamp(const struct timespec& ts);
+ virtual void logTimestamp(const struct timespec &ts);
+ virtual void logInteger(const int x);
+ virtual void logFloat(const float x);
+ virtual void logPID();
+ virtual void logFormat(const char *fmt, ...);
+ virtual void logVFormat(const char *fmt, va_list ap);
+ virtual void logStart(const char *fmt);
+ virtual void logEnd();
+
virtual bool isEnabled() const;
@@ -170,7 +191,12 @@
virtual void logf(const char *fmt, ...) __attribute__ ((format (printf, 2, 3)));
virtual void logvf(const char *fmt, va_list ap);
virtual void logTimestamp();
- virtual void logTimestamp(const struct timespec& ts);
+ virtual void logTimestamp(const struct timespec &ts);
+ virtual void logInteger(const int x);
+ virtual void logFloat(const float x);
+ virtual void logPID();
+ virtual void logStart(const char *fmt);
+ virtual void logEnd();
virtual bool isEnabled() const;
virtual bool setEnabled(bool enabled);
diff --git a/media/libnbaio/NBLog.cpp b/media/libnbaio/NBLog.cpp
index f019df5..7c2523d 100644
--- a/media/libnbaio/NBLog.cpp
+++ b/media/libnbaio/NBLog.cpp
@@ -105,6 +105,7 @@
if (!mEnabled) {
return;
}
+ LOG_ALWAYS_FATAL_IF(string == NULL, "Attempted to log NULL string");
size_t length = strlen(string);
if (length > Entry::kMaxLength) {
length = Entry::kMaxLength;
@@ -147,16 +148,136 @@
}
struct timespec ts;
if (!clock_gettime(CLOCK_MONOTONIC, &ts)) {
- log(EVENT_TIMESTAMP, &ts, sizeof(struct timespec));
+ log(EVENT_TIMESTAMP, &ts, sizeof(ts));
}
}
-void NBLog::Writer::logTimestamp(const struct timespec& ts)
+void NBLog::Writer::logTimestamp(const struct timespec &ts)
{
if (!mEnabled) {
return;
}
- log(EVENT_TIMESTAMP, &ts, sizeof(struct timespec));
+ log(EVENT_TIMESTAMP, &ts, sizeof(ts));
+}
+
+void NBLog::Writer::logInteger(const int x)
+{
+ if (!mEnabled) {
+ return;
+ }
+ log(EVENT_INTEGER, &x, sizeof(x));
+}
+
+void NBLog::Writer::logFloat(const float x)
+{
+ if (!mEnabled) {
+ return;
+ }
+ log(EVENT_FLOAT, &x, sizeof(x));
+}
+
+void NBLog::Writer::logPID()
+{
+ if (!mEnabled) {
+ return;
+ }
+ pid_t id = ::getpid();
+ // TODO: append process name to pid
+ // const char* path = sprintf("/proc/%d/status", id);
+ // FILE* f = fopen(path);
+ // size_t length = 30
+ // char buffer[length];
+ // getline(&buffer, &length, f);
+ // char* pidTag = sprintf("")
+ log(EVENT_PID, &id, sizeof(pid_t));
+}
+
+void NBLog::Writer::logStart(const char *fmt)
+{
+ if (!mEnabled) {
+ return;
+ }
+ size_t length = strlen(fmt);
+ if (length > Entry::kMaxLength) {
+ length = Entry::kMaxLength;
+ }
+ log(EVENT_START_FMT, fmt, length);
+}
+
+void NBLog::Writer::logEnd()
+{
+ if (!mEnabled) {
+ return;
+ }
+ Entry entry = Entry(EVENT_END_FMT, NULL, 0);
+ log(&entry, true);
+}
+
+void NBLog::Writer::logFormat(const char *fmt, ...)
+{
+ if (!mEnabled) {
+ return;
+ }
+
+ va_list ap;
+ va_start(ap, fmt);
+ Writer::logVFormat(fmt, ap);
+ va_end(ap);
+}
+
+void NBLog::Writer::logVFormat(const char *fmt, va_list argp)
+{
+ if (!mEnabled) {
+ return;
+ }
+ Writer::logStart(fmt);
+ int i;
+ double f;
+ char* s;
+ struct timespec t;
+ Writer::logTimestamp();
+ for (const char *p = fmt; *p != '\0'; p++) {
+ // TODO: implement more complex formatting such as %.3f
+ if (*p != '%') {
+ continue;
+ }
+ switch(*++p) {
+ case 's': // string
+ s = va_arg(argp, char *);
+ Writer::log(s);
+ break;
+
+ case 't': // timestamp
+ t = va_arg(argp, struct timespec);
+ Writer::logTimestamp(t);
+ break;
+
+ case 'd': // integer
+ i = va_arg(argp, int);
+ Writer::logInteger(i);
+ break;
+
+ case 'f': // float
+ f = va_arg(argp, double); // float arguments are promoted to double in vararg lists
+ Writer::logFloat((float)f);
+ break;
+
+ case 'p': // pid
+ Writer::logPID();
+ break;
+
+ // the "%\0" case finishes parsing
+ case '\0':
+ --p;
+ break;
+
+ default:
+ ALOGW("NBLog Writer parsed invalid format specifier: %c", *p);
+ break;
+ // the '%' case is handled using the formatted string in the reader
+ }
+ }
+ Writer::logEnd();
}
void NBLog::Writer::log(Event event, const void *data, size_t length)
@@ -173,6 +294,10 @@
switch (event) {
case EVENT_STRING:
case EVENT_TIMESTAMP:
+ case EVENT_INTEGER:
+ case EVENT_FLOAT:
+ case EVENT_PID:
+ case EVENT_START_FMT:
break;
case EVENT_RESERVED:
default:
@@ -257,12 +382,43 @@
Writer::logTimestamp();
}
-void NBLog::LockedWriter::logTimestamp(const struct timespec& ts)
+void NBLog::LockedWriter::logTimestamp(const struct timespec &ts)
{
Mutex::Autolock _l(mLock);
Writer::logTimestamp(ts);
}
+void NBLog::LockedWriter::logInteger(const int x)
+{
+ Mutex::Autolock _l(mLock);
+ Writer::logInteger(x);
+}
+
+void NBLog::LockedWriter::logFloat(const float x)
+{
+ Mutex::Autolock _l(mLock);
+ Writer::logFloat(x);
+}
+
+void NBLog::LockedWriter::logPID()
+{
+ Mutex::Autolock _l(mLock);
+ Writer::logPID();
+}
+
+void NBLog::LockedWriter::logStart(const char *fmt)
+{
+ Mutex::Autolock _l(mLock);
+ Writer::logStart(fmt);
+}
+
+
+void NBLog::LockedWriter::logEnd()
+{
+ Mutex::Autolock _l(mLock);
+ Writer::logEnd();
+}
+
bool NBLog::LockedWriter::isEnabled() const
{
Mutex::Autolock _l(mLock);
@@ -420,6 +576,22 @@
(int) (ts.tv_nsec / 1000000));
deferredTimestamp = true;
} break;
+ case EVENT_INTEGER:
+ appendInt(&body, data);
+ break;
+ case EVENT_FLOAT:
+ appendFloat(&body, data);
+ break;
+ case EVENT_PID:
+ appendPID(&body, data);
+ break;
+ case EVENT_START_FMT:
+ advance += handleFormat((const char*) ©[i + 2], length,
+ ©[i + Entry::kOverhead + length], ×tamp, &body);
+ break;
+ case EVENT_END_FMT:
+ body.appendFormat("warning: got to end format event");
+ break;
case EVENT_RESERVED:
default:
body.appendFormat("warning: unknown event %d", event);
@@ -437,7 +609,7 @@
}
}
-void NBLog::Reader::dumpLine(const String8& timestamp, String8& body)
+void NBLog::Reader::dumpLine(const String8 ×tamp, String8 &body)
{
if (mFd >= 0) {
dprintf(mFd, "%.*s%s %s\n", mIndent, "", timestamp.string(), body.string());
@@ -452,4 +624,104 @@
return iMemory != 0 && mIMemory != 0 && iMemory->pointer() == mIMemory->pointer();
}
+void NBLog::appendTimestamp(String8 *body, const void *data) {
+ struct timespec ts;
+ memcpy(&ts, data, sizeof(struct timespec));
+ body->appendFormat("[%d.%03d]", (int) ts.tv_sec,
+ (int) (ts.tv_nsec / 1000000));
+}
+
+void NBLog::appendInt(String8 *body, const void *data) {
+ int x = *((int*) data);
+ body->appendFormat("<%d>", x);
+}
+
+void NBLog::appendFloat(String8 *body, const void *data) {
+ float f;
+ memcpy(&f, data, sizeof(float));
+ body->appendFormat("<%f>", f);
+}
+
+void NBLog::appendPID(String8 *body, const void* data) {
+ pid_t id = *((pid_t*) data);
+ body->appendFormat("<PID: %d>", id);
+}
+
+int NBLog::handleFormat(const char *fmt, size_t fmt_length, const uint8_t *data,
+ String8 *timestamp, String8 *body) {
+ if (data[0] != EVENT_TIMESTAMP) {
+ ALOGW("NBLog Reader Expected timestamp event %d, got %d", EVENT_TIMESTAMP, data[0]);
+ }
+ struct timespec ts;
+ memcpy(&ts, &data[2], sizeof(ts));
+ timestamp->clear();
+ timestamp->appendFormat("[%d.%03d]", (int) ts.tv_sec,
+ (int) (ts.tv_nsec / 1000000));
+ size_t data_offset = Entry::kOverhead + sizeof ts;
+
+ for (size_t fmt_offset = 0; fmt_offset < fmt_length; ++fmt_offset) {
+ if (fmt[fmt_offset] != '%') {
+ body->append(&fmt[fmt_offset], 1); // TODO optimize to write consecutive strings at once
+ continue;
+ }
+ if (fmt[++fmt_offset] == '%') {
+ body->append("%");
+ continue;
+ }
+ if (fmt_offset == fmt_length) {
+ continue;
+ }
+
+ NBLog::Event event = (NBLog::Event) data[data_offset];
+ size_t length = data[data_offset + 1];
+
+ // TODO check length for event type is correct
+ if(length != data[data_offset + length + 2]) {
+ ALOGW("NBLog Reader recieved different lengths %zu and %d for event %d", length,
+ data[data_offset + length + 2], event);
+ body->append("<invalid entry>");
+ ++fmt_offset;
+ continue;
+ }
+
+ // TODO: implement more complex formatting such as %.3f
+ void * datum = (void*) &data[data_offset + 2]; // pointer to the current event data
+ switch(fmt[fmt_offset])
+ {
+ case 's': // string
+ ALOGW_IF(event != EVENT_STRING, "NBLog Reader incompatible event for string specifier: %d", event);
+ body->append((const char*) datum, length);
+ break;
+
+ case 't': // timestamp
+ ALOGW_IF(event != EVENT_TIMESTAMP, "NBLog Reader incompatible event for timestamp specifier: %d", event);
+ appendTimestamp(body, datum);
+ break;
+
+ case 'd': // integer
+ ALOGW_IF(event != EVENT_INTEGER, "NBLog Reader incompatible event for integer specifier: %d", event);
+ appendInt(body, datum);
+
+ break;
+
+ case 'f': // float
+ ALOGW_IF(event != EVENT_FLOAT, "NBLog Reader incompatible event for float specifier: %d", event);
+ appendFloat(body, datum);
+ break;
+
+ case 'p': // pid
+ ALOGW_IF(event != EVENT_PID, "NBLog Reader incompatible event for pid specifier: %d", event);
+ appendPID(body, datum);
+ break;
+
+ default:
+ ALOGW("NBLog Reader encountered unknown character %c", fmt[fmt_offset]);
+ }
+
+ data_offset += length + Entry::kOverhead;
+
+ }
+ return data_offset + Entry::kOverhead; // data offset + size of END_FMT event
+}
+
} // namespace android
diff --git a/services/audioflinger/Android.mk b/services/audioflinger/Android.mk
index aa2cd95..0c620f4 100644
--- a/services/audioflinger/Android.mk
+++ b/services/audioflinger/Android.mk
@@ -30,7 +30,8 @@
Effects.cpp \
PatchPanel.cpp \
StateQueue.cpp \
- BufLog.cpp
+ BufLog.cpp \
+ TypedLogger.cpp
LOCAL_C_INCLUDES := \
$(TOPDIR)frameworks/av/services/audiopolicy \
diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp
index a248912..8aaa388 100644
--- a/services/audioflinger/AudioFlinger.cpp
+++ b/services/audioflinger/AudioFlinger.cpp
@@ -70,6 +70,8 @@
//#define BUFLOG_NDEBUG 0
#include <BufLog.h>
+#include "TypedLogger.h"
+
// ----------------------------------------------------------------------------
// Note: the following macro is used for extremely verbose logging message. In
diff --git a/services/audioflinger/Threads.cpp b/services/audioflinger/Threads.cpp
index e025316..b40d51c 100644
--- a/services/audioflinger/Threads.cpp
+++ b/services/audioflinger/Threads.cpp
@@ -73,6 +73,9 @@
#include "AutoPark.h"
+#include <pthread.h>
+#include "TypedLogger.h"
+
// ----------------------------------------------------------------------------
// Note: the following macro is used for extremely verbose logging message. In
@@ -2903,6 +2906,8 @@
bool AudioFlinger::PlaybackThread::threadLoop()
{
+ logWriterTLS = mNBLogWriter.get();
+
Vector< sp<Track> > tracksToRemove;
mStandbyTimeNs = systemTime();
@@ -2934,7 +2939,9 @@
const char *logString = NULL;
checkSilentMode_l();
-
+#if 0
+ int z = 0; // used in logFormat example
+#endif
while (!exitPending())
{
cpuStats.sample(myName);
@@ -3023,7 +3030,17 @@
}
}
}
-
+#if 0
+ // logFormat example
+ if (!(z % 100)) {
+ timespec ts;
+ clock_gettime(CLOCK_MONOTONIC, &ts);
+ LOGF("This is an integer %d, this is a float %f, this is my "
+ "pid %p %% %s %t", 42, 3.14, "and this is a timestamp", ts);
+ LOGF("A deceptive null-terminated string %\0");
+ }
+ ++z;
+#endif
saveOutputTracks();
if (mSignalPending) {
// A signal was raised while we were unlocked
diff --git a/services/audioflinger/TypedLogger.cpp b/services/audioflinger/TypedLogger.cpp
new file mode 100644
index 0000000..b5b1bc5
--- /dev/null
+++ b/services/audioflinger/TypedLogger.cpp
@@ -0,0 +1,25 @@
+/*
+*
+* Copyright 2017, 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.
+*/
+
+#define LOG_TAG "AudioFlinger"
+//#define LOG_NDEBUG 0
+#include <utils/Log.h>
+
+#include <pthread.h>
+#include "TypedLogger.h"
+
+thread_local android::NBLog::Writer *logWriterTLS;
diff --git a/services/audioflinger/TypedLogger.h b/services/audioflinger/TypedLogger.h
new file mode 100644
index 0000000..2d71ab4
--- /dev/null
+++ b/services/audioflinger/TypedLogger.h
@@ -0,0 +1,29 @@
+/*
+*
+* Copyright 2017, 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 TYPED_LOGGER_H
+#define TYPED_LOGGER_H
+
+#include <media/nbaio/NBLog.h>
+
+extern "C" {
+ extern thread_local android::NBLog::Writer *logWriterTLS;
+}
+
+#define LOGF(fmt, ...) logWriterTLS->logFormat(fmt, ##__VA_ARGS__)
+
+#endif
\ No newline at end of file