Merge "Retry logs write when it fails. Report skipped event in statsd." into pi-dev

cmds/statsd/src/StatsLogProcessor.cpp

@@ -158,7 +158,10 @@ void StatsLogProcessor::onIsolatedUidChangedEventLocked(const LogEvent& event) {
 void StatsLogProcessor::OnLogEvent(LogEvent* event) {
     std::lock_guard<std::mutex> lock(mMetricsMutex);
     const int64_t currentTimestampNs = event->GetElapsedTimestampNs();
+
     if (currentTimestampNs < mLastLogTimestamp) {
+        StatsdStats::getInstance().noteLogEventSkipped(
+            event->GetTagId(), event->GetElapsedTimestampNs());
         return;
     }
 

cmds/statsd/src/guardrail/StatsdStats.cpp

@@ -49,17 +49,21 @@ 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_SUBSCRIBER_ALARM_STATS = 12;
+const int FIELD_ID_PERIODIC_ALARM_STATS = 12;
+const int FIELD_ID_SKIPPED_LOG_EVENT_STATS = 13;
 
 const int FIELD_ID_ATOM_STATS_TAG = 1;
 const int FIELD_ID_ATOM_STATS_COUNT = 2;
 
 const int FIELD_ID_ANOMALY_ALARMS_REGISTERED = 1;
-const int FIELD_ID_SUBSCRIBER_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_SKIPPED_LOG_EVENT_STATS_TAG = 1;
+const int FIELD_ID_SKIPPED_LOG_EVENT_STATS_TIMESTAMP = 2;
+
 const int FIELD_ID_CONFIG_STATS_UID = 1;
 const int FIELD_ID_CONFIG_STATS_ID = 2;
 const int FIELD_ID_CONFIG_STATS_CREATION = 3;
@@ -346,6 +350,15 @@ void StatsdStats::noteAtomLogged(int atomId, int32_t timeSec) {
     mPushedAtomStats[atomId]++;
 }
 
+void StatsdStats::noteLogEventSkipped(int tag, int64_t timestamp) {
+    lock_guard<std::mutex> lock(mLock);
+    // grows strictly one at a time. so it won't > kMaxSkippedLogEvents
+    if (mSkippedLogEvents.size() == kMaxSkippedLogEvents) {
+        mSkippedLogEvents.pop_front();
+    }
+    mSkippedLogEvents.push_back(std::make_pair(tag, timestamp));
+}
+
 void StatsdStats::noteLoggerError(int error) {
     lock_guard<std::mutex> lock(mLock);
     // grows strictly one at a time. so it won't > kMaxLoggerErrors
@@ -368,6 +381,7 @@ void StatsdStats::resetInternalLocked() {
     mAnomalyAlarmRegisteredStats = 0;
     mPeriodicAlarmRegisteredStats = 0;
     mLoggerErrors.clear();
+    mSkippedLogEvents.clear();
     for (auto& config : mConfigStats) {
         config.second->broadcast_sent_time_sec.clear();
         config.second->data_drop_time_sec.clear();
@@ -491,6 +505,9 @@ void StatsdStats::dumpStats(FILE* out) const {
         strftime(buffer, sizeof(buffer), "%Y-%m-%d %I:%M%p\n", error_tm);
         fprintf(out, "Logger error %d at %s\n", error.second, buffer);
     }
+    for (const auto& skipped : mSkippedLogEvents) {
+        fprintf(out, "Log event (%d) skipped at %lld\n", skipped.first, (long long)skipped.second);
+    }
 }
 
 void addConfigStatsToProto(const ConfigStats& configStats, ProtoOutputStream* proto) {
@@ -617,8 +634,8 @@ void StatsdStats::dumpStats(std::vector<uint8_t>* output, bool reset) {
     }
 
     if (mPeriodicAlarmRegisteredStats > 0) {
-        uint64_t token = proto.start(FIELD_TYPE_MESSAGE | FIELD_ID_SUBSCRIBER_ALARM_STATS);
+        uint64_t token = proto.start(FIELD_TYPE_MESSAGE | FIELD_ID_PERIODIC_ALARM_STATS);
-        proto.write(FIELD_TYPE_INT32 | FIELD_ID_SUBSCRIBER_ALARMS_REGISTERED,
+        proto.write(FIELD_TYPE_INT32 | FIELD_ID_PERIODIC_ALARMS_REGISTERED,
                     mPeriodicAlarmRegisteredStats);
         proto.end(token);
     }
@@ -640,6 +657,15 @@ void StatsdStats::dumpStats(std::vector<uint8_t>* output, bool reset) {
         proto.end(token);
     }
 
+    for (const auto& skipped : mSkippedLogEvents) {
+        uint64_t token = proto.start(FIELD_TYPE_MESSAGE | FIELD_ID_SKIPPED_LOG_EVENT_STATS |
+                                      FIELD_COUNT_REPEATED);
+        proto.write(FIELD_TYPE_INT32 | FIELD_ID_SKIPPED_LOG_EVENT_STATS_TAG, skipped.first);
+        proto.write(FIELD_TYPE_INT64 | FIELD_ID_SKIPPED_LOG_EVENT_STATS_TIMESTAMP,
+                    (long long)skipped.second);
+        proto.end(token);
+    }
+
     output->clear();
     size_t bufferSize = proto.size();
     output->resize(bufferSize);

cmds/statsd/src/guardrail/StatsdStats.h

@@ -105,6 +105,8 @@ public:
 
     const static int kMaxLoggerErrors = 10;
 
+    const static int kMaxSkippedLogEvents = 200;
+
     const static int kMaxTimestampCount = 20;
 
     const static int kMaxLogSourceCount = 50;
@@ -269,6 +271,11 @@ public:
      */
     void noteLoggerError(int error);
 
+    /**
+     * Records statsd skipped an event.
+     */
+    void noteLogEventSkipped(int tag, int64_t timestamp);
+
     /**
      * Reset the historical stats. Including all stats in icebox, and the tracked stats about
      * metrics, matchers, and atoms. The active configs will be kept and StatsdStats will continue
@@ -324,6 +331,9 @@ private:
     // Logd errors. Size capped by kMaxLoggerErrors.
     std::list<const std::pair<int, int>> mLoggerErrors;
 
+    // Skipped log events.
+    std::list<const std::pair<int, int64_t>> mSkippedLogEvents;
+
     // Stores the number of times statsd modified the anomaly alarm registered with
     // StatsCompanionService.
     int mAnomalyAlarmRegisteredStats = 0;

cmds/statsd/src/stats_log.proto

@@ -292,4 +292,15 @@ message StatsdStatsReport {
         optional int32 error_code = 2;
     }
     repeated LoggerErrorStats logger_error_stats = 11;
+
+    message PeriodicAlarmStats {
+        optional int32 alarms_registered = 1;
+    }
+    optional PeriodicAlarmStats periodic_alarm_stats = 12;
+
+    message  SkippedLogEventStats {
+        optional int32 tag = 1;
+        optional int64 elapsed_timestamp_nanos = 2;
+    }
+    repeated SkippedLogEventStats skipped_log_event_stats = 13;
 }

tools/stats_log_api_gen/Android.bp

@@ -101,7 +101,6 @@ cc_library_shared {
     cflags: [
         "-Wall",
         "-Werror",
-        "-fexceptions",
     ],
     export_generated_headers: ["statslog.h"],
     shared_libs: [

tools/stats_log_api_gen/main.cpp

@@ -101,7 +101,8 @@ static int write_stats_log_cpp(FILE *out, const Atoms &atoms,
     fprintf(out, "// This file is autogenerated\n");
     fprintf(out, "\n");
 
-    fprintf(out, "#include <exception>\n");
+    fprintf(out, "#include <chrono>\n");
+    fprintf(out, "#include <thread>\n");
     fprintf(out, "#include <log/log_event_list.h>\n");
     fprintf(out, "#include <log/log.h>\n");
     fprintf(out, "#include <statslog.h>\n");
@@ -212,7 +213,7 @@ static int write_stats_log_cpp(FILE *out, const Atoms &atoms,
         int argIndex;
 
         fprintf(out, "int\n");
-        fprintf(out, "stats_write(int32_t code");
+        fprintf(out, "try_stats_write(int32_t code");
         argIndex = 1;
         for (vector<java_type_t>::const_iterator arg = signature->begin();
             arg != signature->end(); arg++) {
@@ -247,10 +248,6 @@ static int write_stats_log_cpp(FILE *out, const Atoms &atoms,
                     if (chainField.javaType == JAVA_TYPE_STRING) {
                         fprintf(out, "    if (%s_length != %s.size()) {\n",
                             attributionDecl.fields.front().name.c_str(), chainField.name.c_str());
-                        fprintf(out, "        throw std::invalid_argument(\"attribution fields with"
-                            " diff length: %s vs %s\");\n",
-                            attributionDecl.fields.front().name.c_str(),
-                            chainField.name.c_str());
                         fprintf(out, "        return -EINVAL;\n");
                         fprintf(out, "    }\n");
                     }
@@ -289,12 +286,74 @@ static int write_stats_log_cpp(FILE *out, const Atoms &atoms,
         fprintf(out, "\n");
     }
 
+   for (set<vector<java_type_t>>::const_iterator signature = atoms.signatures.begin();
+       signature != atoms.signatures.end(); signature++) {
+       int argIndex;
+
+       fprintf(out, "int \n");
+       fprintf(out, "stats_write(int32_t code");
+       argIndex = 1;
+       for (vector<java_type_t>::const_iterator arg = signature->begin();
+           arg != signature->end(); arg++) {
+           if (*arg == JAVA_TYPE_ATTRIBUTION_CHAIN) {
+               for (auto chainField : attributionDecl.fields) {
+                   if (chainField.javaType == JAVA_TYPE_STRING) {
+                           fprintf(out, ", const std::vector<%s>& %s",
+                                cpp_type_name(chainField.javaType),
+                                chainField.name.c_str());
+                   } else {
+                           fprintf(out, ", const %s* %s, size_t %s_length",
+                                cpp_type_name(chainField.javaType),
+                                chainField.name.c_str(), chainField.name.c_str());
+                   }
+               }
+           } else {
+               fprintf(out, ", %s arg%d", cpp_type_name(*arg), argIndex);
+           }
+           argIndex++;
+       }
+       fprintf(out, ")\n");
+
+       fprintf(out, "{\n");
+       fprintf(out, "  int ret = 0;\n");
+
+       fprintf(out, "  for(int retry = 0; retry < 3; ++retry) {\n");
+       fprintf(out, "      ret =  try_stats_write(code");
+
+       argIndex = 1;
+       for (vector<java_type_t>::const_iterator arg = signature->begin();
+           arg != signature->end(); arg++) {
+           if (*arg == JAVA_TYPE_ATTRIBUTION_CHAIN) {
+               for (auto chainField : attributionDecl.fields) {
+                   if (chainField.javaType == JAVA_TYPE_STRING) {
+                           fprintf(out, ", %s",
+                                chainField.name.c_str());
+                   } else {
+                           fprintf(out, ",  %s,  %s_length",
+                                chainField.name.c_str(), chainField.name.c_str());
+                   }
+               }
+           } else {
+               fprintf(out, ", arg%d", argIndex);
+           }
+           argIndex++;
+       }
+       fprintf(out, ");\n");
+       fprintf(out, "      if (ret >= 0) { return retry; }\n");
+       fprintf(out,
+               "      std::this_thread::sleep_for(std::chrono::milliseconds(10 + 10 * retry));\n");
+       fprintf(out, "  }\n");
+       fprintf(out, "  return ret;\n");
+       fprintf(out, "}\n");
+       fprintf(out, "\n");
+   }
+
     for (set<vector<java_type_t>>::const_iterator signature = atoms.non_chained_signatures.begin();
         signature != atoms.non_chained_signatures.end(); signature++) {
         int argIndex;
 
         fprintf(out, "int\n");
-        fprintf(out, "stats_write_non_chained(int32_t code");
+        fprintf(out, "try_stats_write_non_chained(int32_t code");
         argIndex = 1;
         for (vector<java_type_t>::const_iterator arg = signature->begin();
             arg != signature->end(); arg++) {
@@ -331,6 +390,45 @@ static int write_stats_log_cpp(FILE *out, const Atoms &atoms,
         fprintf(out, "}\n");
         fprintf(out, "\n");
     }
+
+   for (set<vector<java_type_t>>::const_iterator signature = atoms.non_chained_signatures.begin();
+       signature != atoms.non_chained_signatures.end(); signature++) {
+       int argIndex;
+
+       fprintf(out, "int\n");
+       fprintf(out, "stats_write_non_chained(int32_t code");
+       argIndex = 1;
+       for (vector<java_type_t>::const_iterator arg = signature->begin();
+           arg != signature->end(); arg++) {
+           fprintf(out, ", %s arg%d", cpp_type_name(*arg), argIndex);
+           argIndex++;
+       }
+       fprintf(out, ")\n");
+
+       fprintf(out, "{\n");
+
+       fprintf(out, "  int ret = 0;\n");
+       fprintf(out, "  for(int retry = 0; retry < 3; ++retry) {\n");
+       fprintf(out, "      ret =  try_stats_write_non_chained(code");
+
+       argIndex = 1;
+       for (vector<java_type_t>::const_iterator arg = signature->begin();
+           arg != signature->end(); arg++) {
+           fprintf(out, ", arg%d",   argIndex);
+           argIndex++;
+       }
+       fprintf(out, ");\n");
+       fprintf(out, "      if (ret >= 0) { return retry; }\n");
+       fprintf(out,
+               "      std::this_thread::sleep_for(std::chrono::milliseconds(10 + 10 * retry));\n");
+       fprintf(out, "  }\n");
+       fprintf(out, "  return ret;\n");
+       fprintf(out, "}\n");
+
+       fprintf(out, "\n");
+   }
+
+
     // Print footer
     fprintf(out, "\n");
     fprintf(out, "} // namespace util\n");
@@ -775,10 +873,6 @@ write_stats_log_jni(FILE* out, const string& java_method_name, const string& cpp
                         fprintf(out, "    if (%s_length != %s_length) {\n",
                             chainField.name.c_str(),
                             attributionDecl.fields.front().name.c_str());
-                        fprintf(out, "        jniThrowException(env, "
-                            "\"java/lang/IllegalArgumentException\", "
-                            "\"invalid attribution field(%s) length.\");\n",
-                            chainField.name.c_str());
                         fprintf(out, "        return -EINVAL;\n");
                         fprintf(out, "    }\n");
                     }