Bug 939372 - Rewrite oom-msg-logger in C or C++ r=dhylands
authorDave Hylands <dhylands@mozilla.com>
Fri, 10 Jan 2014 22:22:55 -0800
changeset 162979 45369d72225ba889ffb0e1a4348f4011ddd9f4d4
parent 162978 83eac2d4dcfad43835f119897348fd3cf3b9a68f
child 162980 4ebeda74d588687de47f8ca9f5b0aa2376355638
push id3733
push userdhylands@mozilla.com
push dateSat, 11 Jan 2014 06:23:06 +0000
treeherderb2g-inbound@45369d72225b [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersdhylands
bugs939372
milestone29.0a1
Bug 939372 - Rewrite oom-msg-logger in C or C++ r=dhylands
hal/gonk/GonkHal.cpp
--- a/hal/gonk/GonkHal.cpp
+++ b/hal/gonk/GonkHal.cpp
@@ -10,21 +10,24 @@
  *
  * 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.
  */
 
+#include <ctype.h>
 #include <errno.h>
 #include <fcntl.h>
 #include <linux/android_alarm.h>
 #include <math.h>
+#include <regex.h>
 #include <stdio.h>
+#include <sys/klog.h>
 #include <sys/syscall.h>
 #include <sys/resource.h>
 #include <time.h>
 #include <asm/page.h>
 
 #include "mozilla/DebugOnly.h"
 
 #include "android/log.h"
@@ -1033,16 +1036,141 @@ static void
 RoundOomScoreAdjUpWithBackroundLRU(int& aOomScoreAdj, uint32_t aBackgroundLRU)
 {
   // We want to add minimum value to round OomScoreAdj up according to
   // the steps by aBackgroundLRU.
   aOomScoreAdj +=
     ceil(((float)OOM_SCORE_ADJ_MAX / OOM_ADJUST_MAX) * aBackgroundLRU);
 }
 
+#define OOM_LOG(level, args...) __android_log_print(level, "OomLogger", ##args)
+class OomVictimLogger MOZ_FINAL
+  : public nsIObserver
+{
+public:
+  OomVictimLogger()
+    : mLastLineChecked(-1.0),
+      mRegexes(nullptr)
+  {
+    // Enable timestamps in kernel's printk
+    WriteToFile("/sys/module/printk/parameters/time", "Y");
+  }
+
+  NS_DECL_ISUPPORTS
+  NS_DECL_NSIOBSERVER
+private:
+  double mLastLineChecked;
+  ScopedFreePtr<regex_t> mRegexes;
+};
+NS_IMPL_ISUPPORTS1(OomVictimLogger, nsIObserver);
+
+NS_IMETHODIMP
+OomVictimLogger::Observe(
+  nsISupports* aSubject,
+  const char* aTopic,
+  const char16_t* aData)
+{
+  nsDependentCString event_type(aTopic);
+  if (!event_type.EqualsLiteral("ipc:content-shutdown")) {
+    return NS_OK;
+  }
+
+  // OOM message finding regexes
+  const char* const regexes_raw[] = {
+    ".*select.*to kill.*",
+    ".*send sigkill to.*",
+    ".*lowmem_shrink.*, return",
+    ".*lowmem_shrink.*, ofree.*"};
+  const size_t regex_count = NS_ARRAY_LENGTH(regexes_raw);
+
+  // Compile our regex just in time
+  if (!mRegexes) {
+    mRegexes = static_cast<regex_t*>(malloc(sizeof(regex_t) * regex_count));
+    for (size_t i = 0; i < regex_count; i++) {
+      int compilation_err = regcomp(&(mRegexes[i]), regexes_raw[i], REG_NOSUB);
+      if (compilation_err) {
+        OOM_LOG(ANDROID_LOG_ERROR, "Cannot compile regex \"%s\"\n", regexes_raw[i]);
+        return NS_OK;
+      }
+    }
+  }
+
+#ifndef KLOG_SIZE_BUFFER
+  // Upstream bionic in commit
+  // e249b059637b49a285ed9f58a2a18bfd054e5d95
+  // deprecated the old klog defs.
+  // Our current bionic does not hit this
+  // change yet so handle the future change.
+  #define KLOG_SIZE_BUFFER KLOG_WRITE
+#else
+  // Once the change hits our bionic this ifndef
+  // can be removed.
+  #warning "Please remove KLOG_UNREAD_SIZE compatability def"
+#endif
+  // Retreive kernel log
+  int msg_buf_size = klogctl(KLOG_SIZE_BUFFER, NULL, 0);
+  ScopedFreePtr<char> msg_buf(static_cast<char *>(malloc(msg_buf_size + 1)));
+  int read_size = klogctl(KLOG_READ_ALL, msg_buf.rwget(), msg_buf_size);
+
+  // Turn buffer into cstring
+  read_size = read_size > msg_buf_size ? msg_buf_size : read_size;
+  msg_buf.rwget()[read_size] = '\0';
+
+  // Foreach line
+  char* line_end;
+  char* line_begin = msg_buf.rwget();
+  for (; (line_end = strchr(line_begin, '\n')); line_begin = line_end + 1) {
+    // make line into cstring
+    *line_end = '\0';
+
+    // Note: Kernel messages look like:
+    // <5>[63648.286409] sd 35:0:0:0: Attached scsi generic sg1 type 0
+    // 5 is the loging level
+    // [*] is the time timestamp, seconds since boot
+    // last comes the logged message
+
+    // Since the logging level can be a string we must
+    // skip it since scanf lacks wildcard matching
+    char*  timestamp_begin = strchr(line_begin, '[');
+    char   after_float;
+    double lineTimestamp = -1;
+    bool   lineTimestampFound = false;
+    if (timestamp_begin &&
+         // Note: scanf treats a ' ' as [ ]*
+         // Note: scanf treats [ %lf] as [ %lf thus we must check
+         // for the closing bracket outselves.
+         2 == sscanf(timestamp_begin, "[ %lf%c", &lineTimestamp, &after_float) &&
+         after_float == ']') {
+      if (lineTimestamp <= mLastLineChecked) {
+        continue;
+      }
+
+      lineTimestampFound = true;
+      mLastLineChecked = lineTimestamp;
+    }
+      
+
+    // Log interesting lines
+    for (size_t i = 0; i < regex_count; i++) {
+      int matching = !regexec(&(mRegexes[i]), line_begin, 0, NULL, 0);
+      if (matching) {
+        // Log content of kernel message
+        line_begin = strchr(line_begin, ']') + 2;
+        if (!lineTimestampFound) {
+          OOM_LOG(ANDROID_LOG_WARN, "following kill message may be a duplicate");
+        }
+        OOM_LOG(ANDROID_LOG_ERROR, "[Kill]: %s\n", line_begin);
+        break;
+      }
+    }
+  }
+
+  return NS_OK;
+}
+
 static void
 EnsureKernelLowMemKillerParamsSet()
 {
   static bool kernelLowMemKillerParamsSet;
   if (kernelLowMemKillerParamsSet) {
     return;
   }
   kernelLowMemKillerParamsSet = true;
@@ -1126,16 +1254,23 @@ EnsureKernelLowMemKillerParamsSet()
   if (NS_SUCCEEDED(Preferences::GetInt(
         "hal.processPriorityManager.gonk.notifyLowMemUnderMB",
         &lowMemNotifyThresholdMB))) {
 
     // notify_trigger is in pages.
     WriteToFile("/sys/module/lowmemorykiller/parameters/notify_trigger",
       nsPrintfCString("%d", lowMemNotifyThresholdMB * 1024 * 1024 / PAGE_SIZE).get());
   }
+
+  // Ensure OOM events appear in logcat
+  nsRefPtr<OomVictimLogger> oomLogger = new OomVictimLogger();
+  nsCOMPtr<nsIObserverService> os = services::GetObserverService();
+  if (os) {
+    os->AddObserver(oomLogger, "ipc:content-shutdown", false);
+  }
 }
 
 static void
 SetNiceForPid(int aPid, int aNice)
 {
   errno = 0;
   int origProcPriority = getpriority(PRIO_PROCESS, aPid);
   if (errno) {