Merge pull request #66377 from mikeash/section-scan-signposts

[Runtime] Add tracing for section scans.

Author: swift-ci

stdlib/cmake/modules/AddSwiftStdlib.cmake

@@ -417,6 +417,10 @@ function(_add_target_variant_c_compile_flags)
     list(APPEND result "-DSWIFT_STDLIB_ENABLE_UNICODE_DATA")
   endif()
 
+  if(SWIFT_STDLIB_TRACING)
+    list(APPEND result "-DSWIFT_STDLIB_TRACING")
+  endif()
+
   if(SWIFT_STDLIB_CONCURRENCY_TRACING)
     list(APPEND result "-DSWIFT_STDLIB_CONCURRENCY_TRACING")
   endif()
@@ -897,7 +901,7 @@ function(add_swift_target_library_single target name)
 
   # Define availability macros.
   foreach(def ${SWIFT_STDLIB_AVAILABILITY_DEFINITIONS})
-    list(APPEND SWIFTLIB_SINGLE_SWIFT_COMPILE_FLAGS "-Xfrontend" "-define-availability" "-Xfrontend" "${def}") 
+    list(APPEND SWIFTLIB_SINGLE_SWIFT_COMPILE_FLAGS "-Xfrontend" "-define-availability" "-Xfrontend" "${def}")
   endforeach()
 
   # Enable -target-min-inlining-version

stdlib/cmake/modules/StdlibOptions.cmake

@@ -221,11 +221,18 @@ set(SWIFT_STDLIB_ENABLE_LTO OFF CACHE STRING "Build Swift stdlib with LTO. One
     option only affects the standard library and runtime, not tools.")
 
 if("${SWIFT_HOST_VARIANT_SDK}" IN_LIST SWIFT_DARWIN_PLATFORMS)
+  set(SWIFT_STDLIB_TRACING_default TRUE)
   set(SWIFT_STDLIB_CONCURRENCY_TRACING_default TRUE)
 else()
+  set(SWIFT_STDLIB_TRACING_default FALSE)
   set(SWIFT_STDLIB_CONCURRENCY_TRACING_default FALSE)
 endif()
 
+option(SWIFT_STDLIB_TRACING
+  "Enable tracing in the runtime; assumes the presence of os_log(3)
+   and the os_signpost(3) API."
+  "${SWIFT_STDLIB_TRACING_default}")
+
 option(SWIFT_STDLIB_CONCURRENCY_TRACING
   "Enable concurrency tracing in the runtime; assumes the presence of os_log(3)
    and the os_signpost(3) API."

stdlib/public/runtime/AccessibleFunction.cpp

@@ -21,6 +21,7 @@
 #include "swift/Runtime/AccessibleFunction.h"
 #include "swift/Runtime/Concurrent.h"
 #include "swift/Runtime/Metadata.h"
+#include "Tracing.h"
 
 #include <cstdint>
 #include <new>
@@ -120,12 +121,14 @@ void swift::addImageAccessibleFunctionsBlockCallback(
 
 static const AccessibleFunctionRecord *
 _searchForFunctionRecord(AccessibleFunctionsState &S, llvm::StringRef name) {
+  auto traceState = runtime::trace::accessible_function_scan_begin(name);
+
   for (const auto &section : S.SectionsToScan.snapshot()) {
     for (auto &record : section) {
       auto recordName =
           swift::Demangle::makeSymbolicMangledNameStringRef(record.Name.get());
       if (recordName == name)
-        return &record;
+        return traceState.end(&record);
     }
   }
   return nullptr;

stdlib/public/runtime/CMakeLists.txt

@@ -76,6 +76,7 @@ set(swift_runtime_sources
     SwiftDtoa.cpp
     SwiftTLSContext.cpp
     ThreadingError.cpp
+    Tracing.cpp
     AccessibleFunction.cpp
     Win32.cpp)
 

stdlib/public/runtime/Demangle.cpp

@@ -822,6 +822,9 @@ swift::_swift_buildDemanglingForMetadata(const Metadata *type,
     auto metatype = static_cast<const MetatypeMetadata *>(type);
     auto instance = _swift_buildDemanglingForMetadata(metatype->InstanceType,
                                                       Dem);
+    if (!instance)
+      return nullptr;
+
     auto typeNode = Dem.createNode(Node::Kind::Type);
     typeNode->addChild(instance, Dem);
     auto node = Dem.createNode(Node::Kind::Metatype);

stdlib/public/runtime/MetadataLookup.cpp

@@ -17,6 +17,7 @@
 #include "../CompatibilityOverride/CompatibilityOverride.h"
 #include "ImageInspection.h"
 #include "Private.h"
+#include "Tracing.h"
 #include "swift/ABI/TypeIdentity.h"
 #include "swift/Basic/Lazy.h"
 #include "swift/Demangling/Demangler.h"
@@ -742,11 +743,13 @@ _searchTypeMetadataRecords(TypeMetadataPrivateState &T,
           return nullptr;
 #endif
 
+  auto traceState = runtime::trace::metadata_scan_begin(node);
+
   for (auto &section : T.SectionsToScan.snapshot()) {
     for (const auto &record : section) {
       if (auto context = record.getContextDescriptor()) {
         if (_contextDescriptorMatchesMangling(context, node)) {
-          return context;
+          return traceState.end(context);
         }
       }
     }
@@ -970,11 +973,13 @@ void swift::swift_registerProtocols(const ProtocolRecord *begin,
 static const ProtocolDescriptor *
 _searchProtocolRecords(ProtocolMetadataPrivateState &C,
                        NodePointer node) {
+  auto traceState = runtime::trace::protocol_scan_begin(node);
+
   for (auto &section : C.SectionsToScan.snapshot()) {
     for (const auto &record : section) {
       if (auto protocol = record.Protocol.getPointer()) {
         if (_contextDescriptorMatchesMangling(protocol, node))
-          return protocol;
+          return traceState.end(protocol);
       }
     }
   }

stdlib/public/runtime/ProtocolConformance.cpp

@@ -30,6 +30,7 @@
 #include "../CompatibilityOverride/CompatibilityOverride.h"
 #include "ImageInspection.h"
 #include "Private.h"
+#include "Tracing.h"
 
 #include <new>
 #include <vector>
@@ -1089,6 +1090,9 @@ swift_conformsToProtocolMaybeInstantiateSuperclasses(
     }
   };
 
+  auto traceState =
+      runtime::trace::protocol_conformance_scan_begin(type, protocol);
+
   auto snapshot = C.SectionsToScan.snapshot();
   if (C.scanSectionsBackwards) {
     for (auto &section : llvm::reverse(snapshot))
@@ -1125,6 +1129,8 @@ swift_conformsToProtocolMaybeInstantiateSuperclasses(
   }
   noteFinalMetadataState(superclassIterator.state);
 
+  traceState.end(foundWitness);
+
   // If it's for a superclass or if we didn't find anything, then add an
   // authoritative entry for this type.
   if (foundType != type)
@@ -1170,13 +1176,15 @@ swift_conformsToProtocolImpl(const Metadata *const type,
 
 const ContextDescriptor *
 swift::_searchConformancesByMangledTypeName(Demangle::NodePointer node) {
+  auto traceState = runtime::trace::protocol_conformance_scan_begin(node);
+
   auto &C = Conformances.get();
 
   for (auto &section : C.SectionsToScan.snapshot()) {
     for (const auto &record : section) {
       if (auto ntd = record->getTypeDescriptor()) {
         if (_contextDescriptorMatchesMangling(ntd, node))
-          return ntd;
+          return traceState.end(ntd);
       }
     }
   }

stdlib/public/runtime/Tracing.cpp

@@ -0,0 +1,39 @@
+//===--- Tracing.cpp - Support code for runtime tracing ------------*- C++ -*-//
+//
+// This source file is part of the Swift.org open source project
+//
+// Copyright (c) 2014 - 2021 Apple Inc. and the Swift project authors
+// Licensed under Apache License v2.0 with Runtime Library Exception
+//
+// See https://swift.org/LICENSE.txt for license information
+// See https://swift.org/CONTRIBUTORS.txt for the list of Swift project authors
+//
+//===----------------------------------------------------------------------===//
+//
+// Support code for tracing events in the Swift runtime
+//
+//===----------------------------------------------------------------------===//
+
+#include "Tracing.h"
+
+#if SWIFT_STDLIB_TRACING
+
+#define SWIFT_LOG_SUBSYSTEM "com.apple.swift"
+#define SWIFT_LOG_SECTION_SCAN_CATEGORY "SectionScan"
+
+namespace swift {
+namespace runtime {
+namespace trace {
+
+os_log_t ScanLog;
+swift::once_t LogsToken;
+
+void setupLogs(void *unused) {
+  ScanLog = os_log_create(SWIFT_LOG_SUBSYSTEM, SWIFT_LOG_SECTION_SCAN_CATEGORY);
+}
+
+} // namespace trace
+} // namespace runtime
+} // namespace swift
+
+#endif

stdlib/public/runtime/Tracing.h

@@ -0,0 +1,190 @@
+//===--- Tracing.h - Support code for runtime tracing --------------*- C++ -*-//
+//
+// This source file is part of the Swift.org open source project
+//
+// Copyright (c) 2014 - 2021 Apple Inc. and the Swift project authors
+// Licensed under Apache License v2.0 with Runtime Library Exception
+//
+// See https://swift.org/LICENSE.txt for license information
+// See https://swift.org/CONTRIBUTORS.txt for the list of Swift project authors
+//
+//===----------------------------------------------------------------------===//
+//
+// Support code for tracing events in the Swift runtime
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef SWIFT_TRACING_H
+#define SWIFT_TRACING_H
+
+#include "llvm/ADT/StringRef.h"
+#include "swift/ABI/Metadata.h"
+#include "swift/Demangling/Demangler.h"
+
+#if SWIFT_STDLIB_TRACING
+#include <os/signpost.h>
+
+#include "swift/Runtime/HeapObject.h"
+
+#define SWIFT_LOG_SECTION_SCAN "section_scan"
+
+namespace swift {
+namespace runtime {
+namespace trace {
+
+extern os_log_t ScanLog;
+extern swift::once_t LogsToken;
+
+void setupLogs(void *unused);
+
+// Every function does ENSURE_LOGS() before making any os_signpost calls, so
+// we can skip availability checking on all the individual calls.
+#pragma clang diagnostic push
+#pragma clang diagnostic ignored "-Wunguarded-availability"
+#pragma clang diagnostic ignored "-Wunguarded-availability-new"
+
+// Check a representative os_signpost function for NULL rather than doing a
+// standard availability check, for better performance if the check doesn't get
+// optimized out.
+#define ENSURE_LOG(log)                                                        \
+  do {                                                                         \
+    if (!SWIFT_RUNTIME_WEAK_CHECK(os_signpost_enabled))                        \
+      return {};                                                               \
+    swift::once(LogsToken, setupLogs, nullptr);                                \
+  } while (0)
+
+/// A struct that captures the state of a scan tracing signpost. When the scan
+/// is complete, call end() with the result of the scan. If the state struct
+/// goes out of scope without calling end(), then it will automatically do the
+/// equivalent of end(nullptr).
+struct ScanTraceState {
+  os_signpost_id_t signpostID;
+
+  bool ended = false;
+
+  template <typename T>
+  T *end(T *result) {
+    ended = true;
+    os_signpost_interval_end(ScanLog, signpostID, SWIFT_LOG_SECTION_SCAN,
+                             "result=%p", result);
+    return result;
+  }
+
+  ~ScanTraceState() {
+    if (!ended)
+      end((void *)nullptr);
+  }
+};
+
+static inline ScanTraceState
+accessible_function_scan_begin(llvm::StringRef name) {
+  ENSURE_LOG(ScanLog);
+
+  auto id = os_signpost_id_generate(ScanLog);
+  os_signpost_interval_begin(ScanLog, id, SWIFT_LOG_SECTION_SCAN,
+                             "accessible function scan for '%.*s'",
+                             (int)name.size(), name.data());
+  return {id};
+}
+
+static inline ScanTraceState metadata_scan_begin(Demangle::NodePointer node) {
+  ENSURE_LOG(ScanLog);
+
+  auto id = os_signpost_id_generate(ScanLog);
+  os_signpost_interval_begin(ScanLog, id, SWIFT_LOG_SECTION_SCAN,
+                             "metadata scan for %s",
+                             node ? nodeToString(node).c_str() : "<null>");
+  return {id};
+}
+
+static inline ScanTraceState
+protocol_conformance_scan_begin(Demangle::NodePointer node) {
+  ENSURE_LOG(ScanLog);
+
+  auto id = os_signpost_id_generate(ScanLog);
+  os_signpost_interval_begin(ScanLog, id, SWIFT_LOG_SECTION_SCAN,
+                             "protocol conformance scan for %s",
+                             node ? nodeToString(node).c_str() : "<null>");
+  return {id};
+}
+
+static inline ScanTraceState
+protocol_conformance_scan_begin(const Metadata *type,
+                                const ProtocolDescriptor *protocol) {
+  ENSURE_LOG(ScanLog);
+
+  auto id = os_signpost_id_generate(ScanLog);
+
+  // Check for enablement separately to avoid the potentially expensive
+  // swift_getTypeName call when tracing is not enabled.
+  if (os_signpost_enabled(ScanLog)) {
+    auto typeName = swift_getTypeName(type, /*qualified*/ true);
+    auto protoName = protocol ? protocol->Name.get() : "<null>";
+    os_signpost_interval_begin(ScanLog, id, SWIFT_LOG_SECTION_SCAN,
+                               "protocol conformance scan for %.*s(%p): %s(%p)",
+                               (int)typeName.length, typeName.data, type,
+                               protoName, protocol);
+  }
+  return {id};
+}
+
+static inline ScanTraceState protocol_scan_begin(Demangle::NodePointer node) {
+  ENSURE_LOG(ScanLog);
+
+  auto id = os_signpost_id_generate(ScanLog);
+  os_signpost_interval_begin(ScanLog, id, SWIFT_LOG_SECTION_SCAN,
+                             "protocol scan for '%s'",
+                             node ? nodeToString(node).c_str() : "<null>");
+  return {id};
+}
+
+#pragma clang diagnostic pop
+
+} // namespace trace
+} // namespace runtime
+} // namespace swift
+
+#else
+
+namespace swift {
+namespace runtime {
+namespace trace {
+
+struct ScanTraceState {
+  template <typename T>
+  T *end(T *result) {
+    return result;
+  }
+};
+
+static inline ScanTraceState
+accessible_function_scan_begin(llvm::StringRef name) {
+  return {};
+}
+
+static inline ScanTraceState metadata_scan_begin(Demangle::NodePointer node) {
+  return {};
+}
+
+static inline ScanTraceState
+protocol_conformance_scan_begin(Demangle::NodePointer node) {
+  return {};
+}
+
+static inline ScanTraceState
+protocol_conformance_scan_begin(const Metadata *type,
+                                const ProtocolDescriptor *protocol) {
+  return {};
+}
+
+static inline ScanTraceState protocol_scan_begin(Demangle::NodePointer node) {
+  return {};
+}
+
+} // namespace trace
+} // namespace runtime
+} // namespace swift
+
+#endif
+
+#endif // SWIFT_TRACING_H