android: Log and plot native library code residency.

When enabled with the --log-native-library-residency command line switch,
periodically collects native library residency, and dumps it to a
file. process_residency.py then takes the output and creates a graph from
it. This is used to assess the efficiency of the code ordering logic.

Bug: 746665
Change-Id: I4a21ce4b9c01f8bb255f5997e665ff3dbdcf240a
Reviewed-on: https://chromium-review.googlesource.com/756847
Commit-Queue: Benoit L <lizeb@chromium.org>
Reviewed-by: agrieve <agrieve@chromium.org>
Reviewed-by: Matthew Cary <mattcary@chromium.org>
Reviewed-by: Egor Pasko <pasko@chromium.org>
Cr-Commit-Position: refs/heads/master@{#517385}

base/android/java/src/org/chromium/base/library_loader/LibraryLoader.java

@@ -243,33 +243,46 @@ public class LibraryLoader {
         if (isNotPrefetchingLibraries()) return;
 
         final boolean coldStart = mPrefetchLibraryHasBeenCalled.compareAndSet(false, true);
+
+        // Collection should start close to the native library load, but doesn't have
+        // to be simultaneous with it. Also, don't prefetch in this case, as this would
+        // skew the results.
+        if (coldStart && CommandLine.getInstance().hasSwitch("log-native-library-residency")) {
+            // nativePeriodicallyCollectResidency() sleeps, run it on another thread,
+            // and not on the AsyncTask thread pool.
+            new Thread(() -> nativePeriodicallyCollectResidency()).run();
+            return;
+        }
+
         new AsyncTask<Void, Void, Void>() {
             @Override
             protected Void doInBackground(Void... params) {
-                TraceEvent.begin("LibraryLoader.asyncPrefetchLibrariesToMemory");
-                int percentage = nativePercentageOfResidentNativeLibraryCode();
-                boolean success = false;
-                // Arbitrary percentage threshold. If most of the native library is already
-                // resident (likely with monochrome), don't bother creating a prefetch process.
-                boolean prefetch = coldStart && percentage < 90;
-                if (prefetch) {
-                    success = nativeForkAndPrefetchNativeLibrary();
-                    if (!success) {
-                        Log.w(TAG, "Forking a process to prefetch the native library failed.");
+                try (TraceEvent e =
+                                TraceEvent.scoped("LibraryLoader.asyncPrefetchLibrariesToMemory")) {
+                    int percentage = nativePercentageOfResidentNativeLibraryCode();
+                    boolean success = false;
+                    // Arbitrary percentage threshold. If most of the native library is already
+                    // resident (likely with monochrome), don't bother creating a prefetch process.
+                    boolean prefetch = coldStart && percentage < 90;
+                    if (prefetch) {
+                        success = nativeForkAndPrefetchNativeLibrary();
+                        if (!success) {
+                            Log.w(TAG, "Forking a process to prefetch the native library failed.");
+                        }
+                    }
+                    // As this runs in a background thread, it can be called before histograms are
+                    // initialized. In this instance, histograms are dropped.
+                    RecordHistogram.initialize();
+                    if (prefetch) {
+                        RecordHistogram.recordBooleanHistogram(
+                                "LibraryLoader.PrefetchStatus", success);
+                    }
+                    if (percentage != -1) {
+                        String histogram = "LibraryLoader.PercentageOfResidentCodeBeforePrefetch"
+                                + (coldStart ? ".ColdStartup" : ".WarmStartup");
+                        RecordHistogram.recordPercentageHistogram(histogram, percentage);
                     }
                 }
-                // As this runs in a background thread, it can be called before histograms are
-                // initialized. In this instance, histograms are dropped.
-                RecordHistogram.initialize();
-                if (prefetch) {
-                    RecordHistogram.recordBooleanHistogram("LibraryLoader.PrefetchStatus", success);
-                }
-                if (percentage != -1) {
-                    String histogram = "LibraryLoader.PercentageOfResidentCodeBeforePrefetch"
-                            + (coldStart ? ".ColdStartup" : ".WarmStartup");
-                    RecordHistogram.recordPercentageHistogram(histogram, percentage);
-                }
-                TraceEvent.end("LibraryLoader.asyncPrefetchLibrariesToMemory");
                 return null;
             }
         }.executeOnExecutor(AsyncTask.THREAD_POOL_EXECUTOR);
@@ -545,4 +558,7 @@ public class LibraryLoader {
     // Returns the percentage of the native library code page that are currently reseident in
     // memory.
     private static native int nativePercentageOfResidentNativeLibraryCode();
+
+    // Periodically logs native library residency from this thread.
+    private static native void nativePeriodicallyCollectResidency();
 }

base/android/library_loader/library_loader_hooks.cc

@@ -83,7 +83,7 @@ void RecordLibraryPreloaderRendereHistogram() {
   }
 }
 
-} // namespace
+}  // namespace
 
 static void RegisterChromiumAndroidLinkerRendererHistogram(
     JNIEnv* env,
@@ -194,6 +194,11 @@ static jint PercentageOfResidentNativeLibraryCode(
   return NativeLibraryPrefetcher::PercentageOfResidentNativeLibraryCode();
 }
 
+static void PeriodicallyCollectResidency(JNIEnv* env,
+                                         const JavaParamRef<jclass>& clazz) {
+  return NativeLibraryPrefetcher::PeriodicallyCollectResidency();
+}
+
 void SetVersionNumber(const char* version_number) {
   g_library_version_number = strdup(version_number);
 }

base/android/library_loader/library_prefetcher.cc

@@ -10,12 +10,16 @@
 #include <sys/wait.h>
 #include <unistd.h>
 #include <algorithm>
+#include <memory>
 #include <utility>
 #include <vector>
 
+#include "base/files/file.h"
+#include "base/format_macros.h"
 #include "base/macros.h"
 #include "base/posix/eintr_wrapper.h"
 #include "base/strings/string_util.h"
+#include "base/strings/stringprintf.h"
 #include "build/build_config.h"
 
 namespace base {
@@ -78,6 +82,81 @@ bool Prefetch(const std::vector<std::pair<uintptr_t, uintptr_t>>& ranges) {
   return true;
 }
 
+// Populate the per-page residency for |range| in |residency|. If successful,
+// |residency| has the size of |range| in pages.
+// Returns true for success.
+bool MincoreOnRange(const NativeLibraryPrefetcher::AddressRange& range,
+                    std::vector<unsigned char>* residency) {
+  if (range.first % kPageSize || range.second % kPageSize)
+    return false;
+  size_t size = range.second - range.first;
+  size_t size_in_pages = size / kPageSize;
+  if (residency->size() != size_in_pages)
+    residency->resize(size_in_pages);
+  int err = HANDLE_EINTR(
+      mincore(reinterpret_cast<void*>(range.first), size, &(*residency)[0]));
+  if (err) {
+    PLOG(ERROR) << "mincore() failed";
+    return false;
+  }
+  return true;
+}
+
+// Timestamp in ns since Unix Epoch, and residency, as returned by mincore().
+struct TimestampAndResidency {
+  uint64_t timestamp_nanos;
+  std::vector<unsigned char> residency;
+
+  TimestampAndResidency(uint64_t timestamp_nanos,
+                        std::vector<unsigned char>&& residency)
+      : timestamp_nanos(timestamp_nanos), residency(residency) {}
+};
+
+// Returns true for success.
+bool CollectResidency(const NativeLibraryPrefetcher::AddressRange& range,
+                      std::vector<TimestampAndResidency>* data) {
+  // Not using base::TimeTicks() to not call too many base:: symbol that would
+  // pollute the reached symbols dumps.
+  struct timespec ts;
+  if (HANDLE_EINTR(clock_gettime(CLOCK_MONOTONIC, &ts))) {
+    PLOG(ERROR) << "Cannot get the time.";
+    return false;
+  }
+  uint64_t now =
+      static_cast<uint64_t>(ts.tv_sec) * 1000 * 1000 * 1000 + ts.tv_nsec;
+  std::vector<unsigned char> residency;
+  if (!MincoreOnRange(range, &residency))
+    return false;
+
+  data->emplace_back(now, std::move(residency));
+  return true;
+}
+
+void DumpResidency(std::unique_ptr<std::vector<TimestampAndResidency>> data) {
+  auto path = base::FilePath(
+      base::StringPrintf("/data/local/tmp/chrome/residency-%d.txt", getpid()));
+  auto file =
+      base::File(path, base::File::FLAG_CREATE_ALWAYS | base::File::FLAG_WRITE);
+  if (!file.IsValid()) {
+    PLOG(ERROR) << "Cannot open file to dump the residency data "
+                << path.value();
+    return;
+  }
+
+  for (const auto& data_point : *data) {
+    auto timestamp =
+        base::StringPrintf("%" PRIu64 " ", data_point.timestamp_nanos);
+    file.WriteAtCurrentPos(timestamp.c_str(), timestamp.size());
+
+    std::vector<char> dump;
+    dump.reserve(data_point.residency.size() + 1);
+    for (auto c : data_point.residency)
+      dump.push_back(c ? '1' : '0');
+    dump[dump.size() - 1] = '\n';
+    file.WriteAtCurrentPos(&dump[0], dump.size());
+  }
+}
+
 }  // namespace
 
 // static
@@ -109,6 +188,10 @@ void NativeLibraryPrefetcher::FilterLibchromeRangesOnlyIfPossible(
 
 // static
 bool NativeLibraryPrefetcher::FindRanges(std::vector<AddressRange>* ranges) {
+  // All code (including in the forked process) relies on this assumption.
+  if (sysconf(_SC_PAGESIZE) != static_cast<long>(kPageSize))
+    return false;
+
   std::string proc_maps;
   if (!base::debug::ReadProcMaps(&proc_maps))
     return false;
@@ -169,23 +252,15 @@ int NativeLibraryPrefetcher::PercentageOfResidentCode(
     const std::vector<AddressRange>& ranges) {
   size_t total_pages = 0;
   size_t resident_pages = 0;
-  const uintptr_t page_mask = kPageSize - 1;
 
   for (const auto& range : ranges) {
-    if (range.first & page_mask || range.second & page_mask)
-      return -1;
-    size_t length = range.second - range.first;
-    size_t pages = length / kPageSize;
-    total_pages += pages;
-    std::vector<unsigned char> is_page_resident(pages);
-    int err = mincore(reinterpret_cast<void*>(range.first), length,
-                      &is_page_resident[0]);
-    DPCHECK(!err);
-    if (err)
+    std::vector<unsigned char> residency;
+    bool ok = MincoreOnRange(range, &residency);
+    if (!ok)
       return -1;
-    resident_pages +=
-        std::count_if(is_page_resident.begin(), is_page_resident.end(),
-                      [](unsigned char x) { return x & 1; });
+    total_pages += residency.size();
+    resident_pages += std::count_if(residency.begin(), residency.end(),
+                                    [](unsigned char x) { return x & 1; });
   }
   if (total_pages == 0)
     return -1;
@@ -200,5 +275,31 @@ int NativeLibraryPrefetcher::PercentageOfResidentNativeLibraryCode() {
   return PercentageOfResidentCode(ranges);
 }
 
+// static
+void NativeLibraryPrefetcher::PeriodicallyCollectResidency() {
+  CHECK_EQ(static_cast<long>(kPageSize), sysconf(_SC_PAGESIZE));
+  std::vector<AddressRange> ranges;
+  if (!FindRanges(&ranges))
+    return;
+
+  // To keep only the range containing .text, find out which one contains
+  // ourself.
+  const size_t here = reinterpret_cast<size_t>(
+      &NativeLibraryPrefetcher::PeriodicallyCollectResidency);
+  auto it =
+      std::find_if(ranges.begin(), ranges.end(), [here](const AddressRange& r) {
+        return r.first <= here && here <= r.second;
+      });
+  CHECK(ranges.end() != it);
+
+  auto data = std::make_unique<std::vector<TimestampAndResidency>>();
+  for (int i = 0; i < 60; ++i) {
+    if (!CollectResidency(*it, data.get()))
+      return;
+    usleep(2e5);
+  }
+  DumpResidency(std::move(data));
+}
+
 }  // namespace android
 }  // namespace base

base/android/library_loader/library_prefetcher.h

@@ -9,6 +9,8 @@
 
 #include <stdint.h>
 #include <string>
+#include <utility>
+#include <vector>
 
 #include "base/debug/proc_maps_linux.h"
 #include "base/gtest_prod_util.h"
@@ -27,6 +29,8 @@ namespace android {
 // the Android runtime, can be killed at any time, which is not an issue here.
 class BASE_EXPORT NativeLibraryPrefetcher {
  public:
+  using AddressRange = std::pair<uintptr_t, uintptr_t>;
+
   // Finds the ranges matching the native library, forks a low priority
   // process pre-fetching these ranges and wait()s for it.
   // Returns true for success.
@@ -35,8 +39,11 @@ class BASE_EXPORT NativeLibraryPrefetcher {
   // memory, or -1 in case of error.
   static int PercentageOfResidentNativeLibraryCode();
 
+  // Collects residency for the native library executable multiple times, then
+  // dumps it to disk.
+  static void PeriodicallyCollectResidency();
+
  private:
-  using AddressRange = std::pair<uintptr_t, uintptr_t>;
   // Returns true if the region matches native code or data.
   static bool IsGoodToPrefetch(const base::debug::MappedMemoryRegion& region);
   // Filters the regions to keep only libchrome ranges if possible.

tools/android/native_lib_memory/process_residency.py

+#!/usr/bin/python
+# Copyright 2017 The Chromium Authors. All rights reserved.
+# Use of this source code is governed by a BSD-style license that can be
+# found in the LICENSE file.
+
+"""From a native code residency dump created by log_residency.cc, generates a
+visual timeline.
+"""
+
+import argparse
+import logging
+from matplotlib import collections as mc
+from matplotlib import pylab as plt
+import numpy as np
+
+
+def CreateArgumentParser():
+  """Creates and returns an argument parser."""
+  parser = argparse.ArgumentParser(
+      description='Reads and shows native library residency data.')
+  parser.add_argument('--dump', type=str, required=True, help='Residency dump')
+  parser.add_argument('--output', type=str, required=True,
+                      help='Output filename')
+  return parser
+
+
+def ParseDump(filename):
+  """Parses a residency dump, as generated from lightweight_cygprofile.cc.
+
+  Args:
+    filename: (str) dump filename.
+
+  Returns:
+    {timestamp (int): data ([bool])}
+  """
+  result = {}
+  with open(filename, 'r') as f:
+    for line in f:
+      line = line.strip()
+      timestamp, data = line.split(' ')
+      data_array = [x == '1' for x in data]
+      result[int(timestamp)] = data_array
+  return result
+
+
+def PlotResidency(data, output_filename):
+  """Creates a graph of residency.
+
+  Args:
+    data: (dict) As returned by ParseDump().
+    output_filename: (str) Output filename.
+  """
+  fig, ax = plt.subplots(figsize=(20, 10))
+  timestamps = sorted(data.keys())
+  x_max = len(data.values()[0]) * 4096
+  for t in timestamps:
+    offset_ms = (t - timestamps[0]) / 1e6
+    incore = [i * 4096 for (i, x) in enumerate(data[t]) if x]
+    outcore = [i * 4096 for (i, x) in enumerate(data[t]) if not x]
+    percentage = 100. * len(incore) / (len(incore) + len(outcore))
+    plt.text(x_max, offset_ms, '%.1f%%' % percentage)
+    for (d, color) in ((incore, (.2, .6, .05, 1)), (outcore, (1, 0, 0, 1))):
+      segments = [[(x, offset_ms), (x + 4096, offset_ms)] for x in d]
+      colors = np.array([color] * len(segments))
+      lc = mc.LineCollection(segments, colors=colors, linewidths=8)
+      ax.add_collection(lc)
+
+  plt.title('Code residency vs time since startup.')
+  plt.xlabel('Code page offset (bytes)')
+  plt.ylabel('Time since startup (ms)')
+  plt.ylim(-.5e3, ymax=(timestamps[-1] - timestamps[0]) / 1e6 + .5e3)
+  plt.xlim(xmin=0, xmax=x_max)
+  plt.savefig(output_filename, bbox_inches='tight', dpi=300)
+
+
+def main():
+  parser = CreateArgumentParser()
+  args = parser.parse_args()
+  logging.basicConfig(level=logging.INFO)
+  logging.info('Parsing the data')
+  data = ParseDump(args.dump)
+  logging.info('Plotting the results')
+  PlotResidency(data, args.output)
+
+
+if __name__ == '__main__':
+  main()