Merge "Adding system property tracing"

libc/Android.bp

@@ -1178,7 +1178,6 @@ cc_library_static {
         },
     },
     whole_static_libs: [
-        "libc_bionic_systrace",
         "libsystemproperties",
     ],
     cppflags: ["-Wold-style-cast"],

libc/bionic/bionic_systrace.cpp

@@ -14,36 +14,41 @@
  * limitations under the License.
  */
 
+#include "private/bionic_systrace.h"
+
 #include <errno.h>
 #include <fcntl.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
 
-#include "private/bionic_lock.h"
-#include "private/bionic_systrace.h"
-#include "private/CachedProperty.h"
-
 #include <async_safe/log.h>
 #include <cutils/trace.h> // For ATRACE_TAG_BIONIC.
 
+#include "private/CachedProperty.h"
+#include "private/bionic_lock.h"
+
 #define WRITE_OFFSET   32
 
 static Lock g_lock;
-static CachedProperty g_debug_atrace_tags_enableflags("debug.atrace.tags.enableflags");
 static uint64_t g_tags;
 static int g_trace_marker_fd = -1;
 
-static bool should_trace() {
-  g_lock.lock();
-  if (g_debug_atrace_tags_enableflags.DidChange()) {
-    g_tags = strtoull(g_debug_atrace_tags_enableflags.Get(), nullptr, 0);
-  }
-  g_lock.unlock();
-  return ((g_tags & ATRACE_TAG_BIONIC) != 0);
+static CachedProperty& GetTagsProp() {
+  static CachedProperty cached_property(kTraceTagsProp);
+  return cached_property;
 }
 
-static int get_trace_marker_fd() {
+bool should_trace(const uint64_t enable_tags) {
+  g_lock.lock();
+  if (GetTagsProp().DidChange()) {
+    g_tags = strtoull(GetTagsProp().Get(), nullptr, 0);
+  }
+  g_lock.unlock();
+  return g_tags & enable_tags;
+}
+
+int get_trace_marker_fd() {
   g_lock.lock();
   if (g_trace_marker_fd == -1) {
     g_trace_marker_fd = open("/sys/kernel/tracing/trace_marker", O_CLOEXEC | O_WRONLY);
@@ -55,11 +60,8 @@ static int get_trace_marker_fd() {
   return g_trace_marker_fd;
 }
 
-void bionic_trace_begin(const char* message) {
-  if (!should_trace()) {
-    return;
-  }
-
+// event could be 'B' for begin or 'E' for end.
+void output_trace(const char* message, const char event) {
   int trace_marker_fd = get_trace_marker_fd();
   if (trace_marker_fd == -1) {
     return;
@@ -69,13 +71,22 @@ void bionic_trace_begin(const char* message) {
   // kernel trace_marker.
   int length = strlen(message);
   char buf[length + WRITE_OFFSET];
-  size_t len = async_safe_format_buffer(buf, length + WRITE_OFFSET, "B|%d|%s", getpid(), message);
+  size_t len =
+      async_safe_format_buffer(buf, length + WRITE_OFFSET, "%c|%d|%s", event, getpid(), message);
 
   // Tracing may stop just after checking property and before writing the message.
   // So the write is acceptable to fail. See b/20666100.
   TEMP_FAILURE_RETRY(write(trace_marker_fd, buf, len));
 }
 
+void bionic_trace_begin(const char* message) {
+  if (!should_trace()) {
+    return;
+  }
+
+  output_trace(message);
+}
+
 void bionic_trace_end() {
   if (!should_trace()) {
     return;

libc/bionic/system_property_set.cpp

@@ -41,12 +41,13 @@
 #include <sys/_system_properties.h>
 #include <unistd.h>
 
-#include <async_safe/log.h>
 #include <async_safe/CHECK.h>
+#include <async_safe/log.h>
+#include <system_properties/prop_trace.h>
 
-#include "private/bionic_defs.h"
 #include "platform/bionic/macros.h"
 #include "private/ScopedFd.h"
+#include "private/bionic_defs.h"
 
 static const char property_service_socket[] = "/dev/socket/" PROP_SERVICE_NAME;
 static const char* kServiceVersionPropertyName = "ro.property_service.version";
@@ -249,6 +250,8 @@ int __system_property_set(const char* key, const char* value) {
   if (key == nullptr) return -1;
   if (value == nullptr) value = "";
 
+  SyspropTrace trace(key, value, nullptr /* prop_info */, PropertyAction::kPropertySet);
+
   if (g_propservice_protocol_version == 0) {
     detect_protocol_version();
   }

libc/private/bionic_systrace.h

@@ -16,8 +16,12 @@
 
 #pragma once
 
+#include <cutils/trace.h>  // For ATRACE_TAG_BIONIC.
+
 #include "platform/bionic/macros.h"
 
+static constexpr char kTraceTagsProp[] = "debug.atrace.tags.enableflags";
+
 // Tracing class for bionic. To begin a trace at a specified point:
 //   ScopedTrace("Trace message");
 // The trace will end when the contructor goes out of scope.
@@ -33,5 +37,9 @@ class __LIBC_HIDDEN__ ScopedTrace {
   BIONIC_DISALLOW_COPY_AND_ASSIGN(ScopedTrace);
 };
 
+int get_trace_marker_fd();
+bool should_trace(const uint64_t enable_tags = ATRACE_TAG_BIONIC);
+void output_trace(const char* message, const char event = 'B');
+
 void bionic_trace_begin(const char* message);
 void bionic_trace_end();

libc/system_properties/Android.bp

@@ -8,9 +8,11 @@ cc_library_static {
         "contexts_serialized.cpp",
         "prop_area.cpp",
         "prop_info.cpp",
+        "prop_trace.cpp",
         "system_properties.cpp",
     ],
     whole_static_libs: [
+        "libc_bionic_systrace",
         "libpropertyinfoparser",
     ],
     header_libs: [

libc/system_properties/include/system_properties/prop_trace.h

@@ -0,0 +1,49 @@
+/*
+ * Copyright (C) 2020 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * 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.
+ */
+
+#pragma once
+
+#include "platform/bionic/macros.h"
+
+#include "prop_info.h"
+
+// Tracing class for sysprop. To begin a trace at a specified point:
+//   SyspropTrace trace ("prop_name", "prop_value");
+// The trace will end when the constructor goes out of scope.
+// For read-only properties (ro.*), also need to pass prop_info struct.
+
+enum class PropertyAction {
+  kPropertyFind = 0,
+  kPropertySet,
+  kPropertyGetReadOnly,
+  kPropertyGetReadWrite,
+};
+
+class __LIBC_HIDDEN__ SyspropTrace {
+ public:
+  explicit SyspropTrace(const char* prop_name, const char* prop_value, const prop_info* pi,
+                        PropertyAction action);
+  ~SyspropTrace();
+
+ private:
+  const char* prop_name_;
+  const char* prop_value_;
+  const prop_info* prop_info_;
+  PropertyAction prop_action_;
+  bool output_trace_;
+
+  BIONIC_DISALLOW_COPY_AND_ASSIGN(SyspropTrace);
+};

libc/system_properties/prop_trace.cpp

@@ -0,0 +1,113 @@
+/*
+ * Copyright (C) 2020 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * 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 "system_properties/prop_trace.h"
+
+#include <errno.h>
+#include <fcntl.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+
+#include "private/CachedProperty.h"
+#include "private/bionic_lock.h"
+#include "private/bionic_systrace.h"
+
+#include <async_safe/log.h>
+#include <cutils/trace.h>  // For ATRACE_TAG_SYSPROP.
+
+#define PROP_TRACE_MSG_LENGTH 1024
+
+static bool should_trace_prop(const char* prop_name) {
+  // Should not trace kTraceTagsProp to avoid infinite recursion.
+  // Because the following g_trace_enable_flags.Get() will get the property value
+  // of kTraceTagsProp again, which in turn invokes should_trace_prop() here.
+  if (prop_name == nullptr || !strcmp(prop_name, kTraceTagsProp)) {
+    return false;
+  }
+
+  return should_trace(ATRACE_TAG_SYSPROP);
+}
+
+static void sysprop_trace_end() {
+  int trace_marker_fd = get_trace_marker_fd();
+  if (trace_marker_fd == -1) {
+    return;
+  }
+
+  TEMP_FAILURE_RETRY(write(trace_marker_fd, "E|", 2));
+}
+
+static void get_sysprop_trace_end(const prop_info* pi, const char* prop_value,
+                                  bool read_only = false) {
+  const char* output_value;
+  char message[PROP_TRACE_MSG_LENGTH];
+
+  if (read_only) {
+    if (pi->is_long()) {
+      output_value = pi->long_value();
+    } else {
+      output_value = pi->value;
+    }
+  } else {
+    output_value = prop_value;
+  }
+
+  snprintf(message, sizeof(message), "prop_get: %s, value: %s", pi->name,
+           output_value ? output_value : "null_value");
+  output_trace(message, 'E');  // 'E' for end.
+}
+
+SyspropTrace::SyspropTrace(const char* prop_name, const char* prop_value, const prop_info* pi,
+                           PropertyAction action)
+    : prop_name_(prop_name),
+      prop_value_(prop_value),
+      prop_info_(pi),
+      prop_action_(action),
+      output_trace_(false) {
+  if (!should_trace_prop(prop_name)) {
+    return;
+  }
+
+  char message[PROP_TRACE_MSG_LENGTH];
+  if (prop_action_ == PropertyAction::kPropertyFind) {
+    snprintf(message, sizeof(message), "prop_find: %s", prop_name_);
+  } else if (prop_action_ == PropertyAction::kPropertySet) {
+    snprintf(message, sizeof(message), "prop_set: %s, value: %s", prop_name_,
+             prop_value_ ? prop_value_ : "null_value");
+  } else {
+    // For property get, the prop_value_ will be resolved then printed in the destructor.
+    snprintf(message, sizeof(message), "prop_get: %s", prop_name_);
+  }
+
+  output_trace(message, 'B');  // 'B' for begin.
+  output_trace_ = true;
+}
+
+SyspropTrace::~SyspropTrace() {
+  if (!output_trace_) {
+    return;
+  }
+  if (prop_action_ == PropertyAction::kPropertyFind ||
+      prop_action_ == PropertyAction::kPropertySet) {
+    sysprop_trace_end();
+  } else if (prop_action_ == PropertyAction::kPropertyGetReadOnly) {
+    get_sysprop_trace_end(prop_info_, prop_value_, true /* read_only */);
+  } else if (prop_action_ == PropertyAction::kPropertyGetReadWrite) {
+    get_sysprop_trace_end(prop_info_, prop_value_, false /* read_only */);
+  }
+  output_trace_ = false;
+}

libc/system_properties/system_properties.cpp

@@ -46,6 +46,7 @@
 #include "system_properties/context_node.h"
 #include "system_properties/prop_area.h"
 #include "system_properties/prop_info.h"
+#include "system_properties/prop_trace.h"
 
 #define SERIAL_DIRTY(serial) ((serial)&1)
 #define SERIAL_VALUE_LEN(serial) ((serial) >> 24)
@@ -127,6 +128,9 @@ const prop_info* SystemProperties::Find(const char* name) {
     return nullptr;
   }
 
+  SyspropTrace trace(name, nullptr /* prop_value */, nullptr /* prop_info */,
+                     PropertyAction::kPropertyFind);
+
   prop_area* pa = contexts_->GetPropAreaForName(name);
   if (!pa) {
     async_safe_format_log(ANDROID_LOG_ERROR, "libc", "Access denied finding property \"%s\"", name);
@@ -201,6 +205,10 @@ void SystemProperties::ReadCallback(const prop_info* pi,
   // Read only properties don't need to copy the value to a temporary buffer, since it can never
   // change.  We use relaxed memory order on the serial load for the same reason.
   if (is_read_only(pi->name)) {
+    // The 2nd argument is not required for read-only property tracing, as the
+    // value can be obtained via pi->value or pi->long_value().
+    SyspropTrace trace(pi->name, nullptr /* prop_value */, pi /* prop_info */,
+                       PropertyAction::kPropertyGetReadOnly);
     uint32_t serial = load_const_atomic(&pi->serial, memory_order_relaxed);
     if (pi->is_long()) {
       callback(cookie, pi->name, pi->long_value(), serial);
@@ -211,6 +219,8 @@ void SystemProperties::ReadCallback(const prop_info* pi,
   }
 
   char value_buf[PROP_VALUE_MAX];
+  SyspropTrace trace(pi->name, value_buf, pi /* prop_info */,
+                     PropertyAction::kPropertyGetReadWrite);
   uint32_t serial = ReadMutablePropertyValue(pi, value_buf);
   callback(cookie, pi->name, value_buf, serial);
 }