Pass the last error code when statslog.write fails

The error code will give us some clue on what caused the loss (e.g., EBUSY, or ENOENT)

Test: manual
Bug: 80538532

Change-Id: I446c6e2255bdae063dfb8803ad0b702ead87c645
This commit is contained in:
Yao Chen
2018-11-08 15:32:17 -08:00
parent 3064067908
commit 39b679925a
5 changed files with 36 additions and 22 deletions

View File

@@ -47,11 +47,9 @@ const int FIELD_ID_CONFIG_STATS = 3;
const int FIELD_ID_ATOM_STATS = 7;
const int FIELD_ID_UIDMAP_STATS = 8;
const int FIELD_ID_ANOMALY_ALARM_STATS = 9;
// const int FIELD_ID_PULLED_ATOM_STATS = 10; // The proto is written in stats_log_util.cpp
const int FIELD_ID_LOGGER_ERROR_STATS = 11;
const int FIELD_ID_PERIODIC_ALARM_STATS = 12;
// const int FIELD_ID_LOG_LOSS_STATS = 14;
const int FIELD_ID_SYSTEM_SERVER_RESTART = 15;
const int FIELD_ID_LOGGER_ERROR_STATS = 16;
const int FIELD_ID_ATOM_STATS_TAG = 1;
const int FIELD_ID_ATOM_STATS_COUNT = 2;
@@ -59,8 +57,9 @@ const int FIELD_ID_ATOM_STATS_COUNT = 2;
const int FIELD_ID_ANOMALY_ALARMS_REGISTERED = 1;
const int FIELD_ID_PERIODIC_ALARMS_REGISTERED = 1;
const int FIELD_ID_LOGGER_STATS_TIME = 1;
const int FIELD_ID_LOGGER_STATS_ERROR_CODE = 2;
const int FIELD_ID_LOG_LOSS_STATS_TIME = 1;
const int FIELD_ID_LOG_LOSS_STATS_COUNT = 2;
const int FIELD_ID_LOG_LOSS_STATS_ERROR = 3;
const int FIELD_ID_CONFIG_STATS_UID = 1;
const int FIELD_ID_CONFIG_STATS_ID = 2;
@@ -181,12 +180,12 @@ void StatsdStats::noteConfigReset(const ConfigKey& key) {
noteConfigResetInternalLocked(key);
}
void StatsdStats::noteLogLost(int32_t wallClockTimeSec, int32_t count) {
void StatsdStats::noteLogLost(int32_t wallClockTimeSec, int32_t count, int32_t lastError) {
lock_guard<std::mutex> lock(mLock);
if (mLogLossStats.size() == kMaxLoggerErrors) {
mLogLossStats.pop_front();
}
mLogLossStats.push_back(std::make_pair(wallClockTimeSec, count));
mLogLossStats.emplace_back(wallClockTimeSec, count, lastError);
}
void StatsdStats::noteBroadcastSent(const ConfigKey& key) {
@@ -557,8 +556,8 @@ void StatsdStats::dumpStats(int out) const {
}
for (const auto& loss : mLogLossStats) {
dprintf(out, "Log loss: %lld (wall clock sec) - %d (count)\n", (long long)loss.first,
loss.second);
dprintf(out, "Log loss: %lld (wall clock sec) - %d (count) %d (last error)\n",
(long long)loss.mWallClockSec, loss.mCount, loss.mLastError);
}
}
@@ -713,13 +712,11 @@ void StatsdStats::dumpStats(std::vector<uint8_t>* output, bool reset) {
proto.end(uidMapToken);
for (const auto& error : mLogLossStats) {
// The logger error stats are not used anymore since we move away from logd.
// Temporarily use this field to log the log loss timestamp and count
// TODO(b/80538532) Add a dedicated field in stats_log for this.
uint64_t token = proto.start(FIELD_TYPE_MESSAGE | FIELD_ID_LOGGER_ERROR_STATS |
FIELD_COUNT_REPEATED);
proto.write(FIELD_TYPE_INT32 | FIELD_ID_LOGGER_STATS_TIME, error.first);
proto.write(FIELD_TYPE_INT32 | FIELD_ID_LOGGER_STATS_ERROR_CODE, error.second);
proto.write(FIELD_TYPE_INT32 | FIELD_ID_LOG_LOSS_STATS_TIME, error.mWallClockSec);
proto.write(FIELD_TYPE_INT32 | FIELD_ID_LOG_LOSS_STATS_COUNT, error.mCount);
proto.write(FIELD_TYPE_INT32 | FIELD_ID_LOG_LOSS_STATS_ERROR, error.mLastError);
proto.end(token);
}

View File

@@ -298,7 +298,7 @@ public:
/**
* Records statsd skipped an event.
*/
void noteLogLost(int32_t wallClockTimeSec, int32_t count);
void noteLogLost(int32_t wallClockTimeSec, int32_t count, int lastError);
/**
* Reset the historical stats. Including all stats in icebox, and the tracked stats about
@@ -358,8 +358,18 @@ private:
// Maps PullAtomId to its stats. The size is capped by the puller atom counts.
std::map<int, PulledAtomStats> mPulledAtomStats;
struct LogLossStats {
LogLossStats(int32_t sec, int32_t count, int32_t error)
: mWallClockSec(sec), mCount(count), mLastError(error) {
}
int32_t mWallClockSec;
int32_t mCount;
// error code defined in linux/errno.h
int32_t mLastError;
};
// Timestamps when we detect log loss, and the number of logs lost.
std::list<std::pair<int32_t, int32_t>> mLogLossStats;
std::list<LogLossStats> mLogLossStats;
std::list<int32_t> mSystemServerRestartSec;

View File

@@ -40,7 +40,6 @@ namespace os {
namespace statsd {
static const int kLogMsgHeaderSize = 28;
static const int kLibLogTag = 1006;
StatsSocketListener::StatsSocketListener(const sp<LogListener>& listener)
: SocketListener(getLogSocket(), false /*start listen*/), mListener(listener) {
@@ -109,10 +108,11 @@ bool StatsSocketListener::onDataAvailable(SocketClient* cli) {
// TODO(b/80538532): In addition to log it in StatsdStats, we should properly reset the config.
if (n == sizeof(android_log_event_int_t)) {
android_log_event_int_t* int_event = reinterpret_cast<android_log_event_int_t*>(ptr);
if (int_event->header.tag == kLibLogTag && int_event->payload.type == EVENT_TYPE_INT) {
ALOGE("Found dropped events: %d", int_event->payload.data);
if (int_event->payload.type == EVENT_TYPE_INT) {
ALOGE("Found dropped events: %d error %d", int_event->payload.data,
int_event->header.tag);
StatsdStats::getInstance().noteLogLost((int32_t)getWallClockSec(),
int_event->payload.data);
int_event->payload.data, int_event->header.tag);
return true;
}
}

View File

@@ -397,4 +397,11 @@ message StatsdStatsReport {
repeated int64 log_loss_stats = 14;
repeated int32 system_restart_sec = 15;
message LogLossStats {
optional int32 detected_time_sec = 1;
optional int32 count = 2;
optional int32 last_error = 3;
}
repeated LogLossStats detected_log_loss = 16;
}

View File

@@ -435,7 +435,7 @@ static int write_stats_log_cpp(FILE *out, const Atoms &atoms,
fprintf(out, " std::this_thread::sleep_for(std::chrono::milliseconds(10));\n");
fprintf(out, " }\n");
fprintf(out, " if (ret < 0) {\n");
fprintf(out, " note_log_drop();\n");
fprintf(out, " note_log_drop(ret);\n");
fprintf(out, " }\n");
fprintf(out, " return ret;\n");
fprintf(out, "}\n");
@@ -528,7 +528,7 @@ static int write_stats_log_cpp(FILE *out, const Atoms &atoms,
fprintf(out, " std::this_thread::sleep_for(std::chrono::milliseconds(10));\n");
fprintf(out, " }\n");
fprintf(out, " if (ret < 0) {\n");
fprintf(out, " note_log_drop();\n");
fprintf(out, " note_log_drop(ret);\n");
fprintf(out, " }\n");
fprintf(out, " return ret;\n\n");
fprintf(out, "}\n");