common_time: Turn the logging up to 11
Hand merge from ics-aah
> DO NOT MERGE: common_time: Turn the logging up to 11
>
> Actually, despite the CL title, no addition log messages are being
> sent to logcat. Generally speaking, the common_time service tends to
> be rather quiet from a log perspective. Events related to master
> election and arbitration as well as state changes tend to be
> infrequent in steady state operation. Unfortunately, if there is a
> problem with the system, it frequently gets pushed out of logcat by
> other messages and is missing from the logs when a bugreport is
> finally taken.
>
> This change adds a utility class which can be used to store the last N
> log message in a ring buffer to be dumped later during a dumpsys
> operation. Three internal log buffers were added to the system. One
> to record messages having to do with state transitions. Another was
> added to record traffic relating to master election, and one final
> buffer to record basic data on packets which were received but
> discarded for any reason. During a bugreport, these common_time.clock
> service will be able to dump these messages regardless of the amt of
> other logcat activity, which should assist in debugging long running
> issues.
>
> Change-Id: Ic3bbf7480c8978f9bf82bafaba04cf4586db60cf
> Signed-off-by: John Grossman <johngro@google.com>
Change-Id: If7156d41ce4553d5ba5c3a8e1dd616564a569711
Signed-off-by: John Grossman <johngro@google.com>
diff --git a/services/common_time/utils.cpp b/services/common_time/utils.cpp
index 3ed2599..ed2c77d 100644
--- a/services/common_time/utils.cpp
+++ b/services/common_time/utils.cpp
@@ -14,6 +14,9 @@
* limitations under the License.
*/
+#define LOG_TAG "common_time"
+#include <utils/Log.h>
+
#include "utils.h"
namespace android {
@@ -46,4 +49,116 @@
return static_cast<int>(delta);
}
+LogRing::LogRing(const char* header, size_t entries)
+ : mSize(entries)
+ , mWr(0)
+ , mIsFull(false)
+ , mHeader(header) {
+ mRingBuffer = new Entry[mSize];
+ if (NULL == mRingBuffer)
+ ALOGE("Failed to allocate log ring with %u entries.", mSize);
+}
+
+LogRing::~LogRing() {
+ if (NULL != mRingBuffer)
+ delete[] mRingBuffer;
+}
+
+void LogRing::log(int prio, const char* tag, const char* fmt, ...) {
+ va_list argp;
+ va_start(argp, fmt);
+ internalLog(prio, tag, fmt, argp);
+ va_end(argp);
+}
+
+void LogRing::log(const char* fmt, ...) {
+ va_list argp;
+ va_start(argp, fmt);
+ internalLog(0, NULL, fmt, argp);
+ va_end(argp);
+}
+
+void LogRing::internalLog(int prio,
+ const char* tag,
+ const char* fmt,
+ va_list argp) {
+ if (NULL != mRingBuffer) {
+ Mutex::Autolock lock(&mLock);
+ String8 s(String8::formatV(fmt, argp));
+ Entry* last = NULL;
+
+ if (mIsFull || mWr)
+ last = &(mRingBuffer[(mWr + mSize - 1) % mSize]);
+
+
+ if ((NULL != last) && !last->s.compare(s)) {
+ gettimeofday(&(last->last_ts), NULL);
+ ++last->count;
+ } else {
+ gettimeofday(&mRingBuffer[mWr].first_ts, NULL);
+ mRingBuffer[mWr].last_ts = mRingBuffer[mWr].first_ts;
+ mRingBuffer[mWr].count = 1;
+ mRingBuffer[mWr].s.setTo(s);
+
+ mWr = (mWr + 1) % mSize;
+ if (!mWr)
+ mIsFull = true;
+ }
+ }
+
+ if (NULL != tag)
+ LOG_PRI_VA(prio, tag, fmt, argp);
+}
+
+void LogRing::dumpLog(int fd) {
+ if (NULL == mRingBuffer)
+ return;
+
+ Mutex::Autolock lock(&mLock);
+
+ if (!mWr && !mIsFull)
+ return;
+
+ char buf[1024];
+ int res;
+ size_t start = mIsFull ? mWr : 0;
+ size_t count = mIsFull ? mSize : mWr;
+ static const char* kTimeFmt = "%a %b %d %Y %H:%M:%S";
+
+ res = snprintf(buf, sizeof(buf), "\n%s\n", mHeader);
+ if (res > 0)
+ write(fd, buf, res);
+
+ for (size_t i = 0; i < count; ++i) {
+ struct tm t;
+ char timebuf[64];
+ char repbuf[96];
+ size_t ndx = (start + i) % mSize;
+
+ if (1 != mRingBuffer[ndx].count) {
+ localtime_r(&mRingBuffer[ndx].last_ts.tv_sec, &t);
+ strftime(timebuf, sizeof(timebuf), kTimeFmt, &t);
+ snprintf(repbuf, sizeof(repbuf),
+ " (repeated %d times, last was %s.%03ld)",
+ mRingBuffer[ndx].count,
+ timebuf,
+ mRingBuffer[ndx].last_ts.tv_usec / 1000);
+ repbuf[sizeof(repbuf) - 1] = 0;
+ } else {
+ repbuf[0] = 0;
+ }
+
+ localtime_r(&mRingBuffer[ndx].first_ts.tv_sec, &t);
+ strftime(timebuf, sizeof(timebuf), kTimeFmt, &t);
+ res = snprintf(buf, sizeof(buf), "[%2d] %s.%03ld :: %s%s\n",
+ i, timebuf,
+ mRingBuffer[ndx].first_ts.tv_usec / 1000,
+ mRingBuffer[ndx].s.string(),
+ repbuf);
+
+ if (res > 0)
+ write(fd, buf, res);
+ }
+}
+
} // namespace android