[Runtime] Add tracing for section scans.

mikeash · mikeash · commit 8d0fa6fe75a6 · 2023-06-07T09:58:40.000-04:00
Section scans (for metadata, protocols, etc.) can be costly. This change adds tracing calls to those scans so we can more easily see how much time is spent in these scans and where they're initiated.

This adds an os_signpost implementation controlled by SWIFT_STDLIB_TRACING, and a default empty implementation for when that's disabled.

rdar://110266743
diff --git a/stdlib/cmake/modules/AddSwiftStdlib.cmake b/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
diff --git a/stdlib/cmake/modules/StdlibOptions.cmake b/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."
diff --git a/stdlib/public/runtime/AccessibleFunction.cpp b/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;
diff --git a/stdlib/public/runtime/CMakeLists.txt b/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)
 
diff --git a/stdlib/public/runtime/MetadataLookup.cpp b/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);
       }
     }
   }
diff --git a/stdlib/public/runtime/ProtocolConformance.cpp b/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);
       }
     }
   }
diff --git a/stdlib/public/runtime/Tracing.cpp b/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
diff --git a/stdlib/public/runtime/Tracing.h b/stdlib/public/runtime/Tracing.h
@@ -0,0 +1,189 @@
+//===--- 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",
+                             nodeToString(node).c_str());
+  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",
+                             nodeToString(node).c_str());
+  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);
+    os_signpost_interval_begin(ScanLog, id, SWIFT_LOG_SECTION_SCAN,
+                               "protocol conformance scan for %.*s(%p): %s(%p)",
+                               (int)typeName.length, typeName.data, type,
+                               protocol->Name.get(), 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",
+                             nodeToString(node).c_str());
+  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
diff --git a/utils/build-script-impl b/utils/build-script-impl
@@ -2044,6 +2044,13 @@ for host in "${ALL_HOSTS[@]}"; do
                     )
                 fi
 
+                if [[ "${SWIFT_STDLIB_TRACING}" ]] ; then
+                    cmake_options=(
+                        "${cmake_options[@]}"
+                        -DSWIFT_STDLIB_TRACING:BOOL=$(true_false "${SWIFT_STDLIB_TRACING}")
+                    )
+                fi
+
                 if [[ "${SWIFT_STDLIB_CONCURRENCY_TRACING}" ]] ; then
                     cmake_options=(
                         "${cmake_options[@]}"
diff --git a/utils/swift_build_support/swift_build_support/products/minimalstdlib.py b/utils/swift_build_support/swift_build_support/products/minimalstdlib.py
