From 110f428780689bfcf5cf5bc3db7f804205256929 Mon Sep 17 00:00:00 2001 From: Mike Ash Date: Tue, 6 Jun 2023 14:12:31 -0400 Subject: [PATCH] [Runtime] Add tracing for section scans. 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 --- stdlib/cmake/modules/AddSwiftStdlib.cmake | 6 +- stdlib/cmake/modules/StdlibOptions.cmake | 7 + stdlib/public/runtime/AccessibleFunction.cpp | 5 +- stdlib/public/runtime/CMakeLists.txt | 1 + stdlib/public/runtime/Demangle.cpp | 3 + stdlib/public/runtime/MetadataLookup.cpp | 9 +- stdlib/public/runtime/ProtocolConformance.cpp | 10 +- stdlib/public/runtime/Tracing.cpp | 39 ++++ stdlib/public/runtime/Tracing.h | 190 ++++++++++++++++++ utils/build-script-impl | 7 + .../products/minimalstdlib.py | 1 + 11 files changed, 273 insertions(+), 5 deletions(-) create mode 100644 stdlib/public/runtime/Tracing.cpp create mode 100644 stdlib/public/runtime/Tracing.h diff --git a/stdlib/cmake/modules/AddSwiftStdlib.cmake b/stdlib/cmake/modules/AddSwiftStdlib.cmake index d1e5053b8f267..5f2415f87b025 100644 --- 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 index 3733ee1e841e7..2e946e7cdb927 100644 --- 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 index e71cf09206af8..41b4d24589b11 100644 --- 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 #include @@ -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 §ion : 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 index 379f72b010a72..3771d972d5400 100644 --- 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/Demangle.cpp b/stdlib/public/runtime/Demangle.cpp index 8a8827ec9767f..7a585ccc43f4a 100644 --- a/stdlib/public/runtime/Demangle.cpp +++ b/stdlib/public/runtime/Demangle.cpp @@ -822,6 +822,9 @@ swift::_swift_buildDemanglingForMetadata(const Metadata *type, auto metatype = static_cast(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); diff --git a/stdlib/public/runtime/MetadataLookup.cpp b/stdlib/public/runtime/MetadataLookup.cpp index 557112086bd55..82f382d55976c 100644 --- 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 §ion : 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 §ion : 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 index 72e185d380745..47d4524091041 100644 --- 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 #include @@ -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 §ion : 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 §ion : 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 new file mode 100644 index 0000000000000..8be15546fafdc --- /dev/null +++ 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 new file mode 100644 index 0000000000000..5714962d02ea1 --- /dev/null +++ b/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 + +#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 + 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() : ""); + 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() : ""); + 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() : ""; + 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() : ""); + return {id}; +} + +#pragma clang diagnostic pop + +} // namespace trace +} // namespace runtime +} // namespace swift + +#else + +namespace swift { +namespace runtime { +namespace trace { + +struct ScanTraceState { + template + 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 index f3941c1427948..dafe4aeaff44c 100755 --- 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 index 1264f1a434d0e..8d70554d6fe10 100644 --- a/utils/swift_build_support/swift_build_support/products/minimalstdlib.py +++ b/utils/swift_build_support/swift_build_support/products/minimalstdlib.py @@ -116,6 +116,7 @@ def build(self, host_target): self.cmake_options.define( 'SWIFT_RUNTIME_STATIC_IMAGE_INSPECTION:BOOL', 'FALSE') self.cmake_options.define('SWIFT_STDLIB_BUILD_PRIVATE:BOOL', 'TRUE') + self.cmake_options.define('SWIFT_STDLIB_TRACING:BOOL', 'FALSE') self.cmake_options.define( 'SWIFT_STDLIB_CONCURRENCY_TRACING:BOOL', 'FALSE') self.cmake_options.define(