From a279b2230f36c98574c3bdec1807718cf30fd1b6 Mon Sep 17 00:00:00 2001 From: Alexander Shabalin Date: Wed, 25 Aug 2021 08:04:01 +0000 Subject: [PATCH] [K/N] Logging for runtime --- .../org/jetbrains/kotlin/cli/bc/K2Native.kt | 1 + .../cli/bc/K2NativeCompilerArguments.kt | 3 + .../kotlin/backend/konan/KonanConfig.kt | 1 + .../backend/konan/KonanConfigurationKeys.kt | 1 + .../kotlin/backend/konan/llvm/IrToBitcode.kt | 4 + .../gc/stms/cpp/SameThreadMarkAndSweep.cpp | 82 ++++++- .../gc/stms/cpp/SameThreadMarkAndSweep.hpp | 3 + kotlin-native/runtime/src/main/cpp/Alloc.h | 6 + .../src/main/cpp/CompilerConstants.hpp | 17 ++ .../runtime/src/main/cpp/Logging.cpp | 194 +++++++++++++++ .../runtime/src/main/cpp/Logging.hpp | 116 +++++++++ .../runtime/src/main/cpp/LoggingTest.cpp | 220 ++++++++++++++++++ .../runtime/src/main/cpp/Porting.cpp | 2 +- .../runtime/src/mm/cpp/ObjectFactory.hpp | 23 ++ .../runtime/src/mm/cpp/ObjectFactoryTest.cpp | 42 ++++ kotlin-native/runtime/src/mm/cpp/RootSet.cpp | 12 +- kotlin-native/runtime/src/mm/cpp/RootSet.hpp | 28 ++- .../runtime/src/mm/cpp/RootSetTest.cpp | 31 ++- .../runtime/src/mm/cpp/ThreadData.hpp | 7 +- .../runtime/src/mm/cpp/ThreadRegistry.cpp | 3 +- .../runtime/src/mm/cpp/ThreadRegistryTest.cpp | 2 +- .../runtime/src/mm/cpp/ThreadStateTest.cpp | 4 +- .../runtime/src/mm/cpp/ThreadSuspension.cpp | 5 + .../test_support/cpp/CompilerGenerated.cpp | 1 + 24 files changed, 772 insertions(+), 36 deletions(-) create mode 100644 kotlin-native/runtime/src/main/cpp/Logging.cpp create mode 100644 kotlin-native/runtime/src/main/cpp/Logging.hpp create mode 100644 kotlin-native/runtime/src/main/cpp/LoggingTest.cpp diff --git a/kotlin-native/backend.native/cli.bc/src/org/jetbrains/kotlin/cli/bc/K2Native.kt b/kotlin-native/backend.native/cli.bc/src/org/jetbrains/kotlin/cli/bc/K2Native.kt index b7a26f35e9b..23eca4feda6 100644 --- a/kotlin-native/backend.native/cli.bc/src/org/jetbrains/kotlin/cli/bc/K2Native.kt +++ b/kotlin-native/backend.native/cli.bc/src/org/jetbrains/kotlin/cli/bc/K2Native.kt @@ -359,6 +359,7 @@ class K2Native : CLICompiler() { } } }) + putIfNotNull(RUNTIME_LOGS, arguments.runtimeLogs) parseBinaryOptions(arguments, configuration).forEach { optionWithValue -> configuration.put(optionWithValue) diff --git a/kotlin-native/backend.native/cli.bc/src/org/jetbrains/kotlin/cli/bc/K2NativeCompilerArguments.kt b/kotlin-native/backend.native/cli.bc/src/org/jetbrains/kotlin/cli/bc/K2NativeCompilerArguments.kt index aa43263d282..a17693a6b9d 100644 --- a/kotlin-native/backend.native/cli.bc/src/org/jetbrains/kotlin/cli/bc/K2NativeCompilerArguments.kt +++ b/kotlin-native/backend.native/cli.bc/src/org/jetbrains/kotlin/cli/bc/K2NativeCompilerArguments.kt @@ -348,6 +348,9 @@ class K2NativeCompilerArguments : CommonCompilerArguments() { ) var binaryOptions: Array? = null + @Argument(value = "-Xruntime-logs", valueDescription = "", description = "Enable logging for runtime with tags.") + var runtimeLogs: String? = null + override fun configureAnalysisFlags(collector: MessageCollector, languageVersion: LanguageVersion): MutableMap, Any> = super.configureAnalysisFlags(collector, languageVersion).also { val useExperimental = it[AnalysisFlags.useExperimental] as List<*> diff --git a/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/KonanConfig.kt b/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/KonanConfig.kt index 2e1dfb493f9..bfa7d1fba39 100644 --- a/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/KonanConfig.kt +++ b/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/KonanConfig.kt @@ -62,6 +62,7 @@ class KonanConfig(val project: Project, val configuration: CompilerConfiguration val gcAggressive: Boolean get() = configuration.get(KonanConfigKeys.GARBAGE_COLLECTOR_AGRESSIVE)!! val runtimeAssertsMode: RuntimeAssertsMode get() = configuration.get(BinaryOptions.runtimeAssertionsMode) ?: RuntimeAssertsMode.IGNORE val workerExceptionHandling: WorkerExceptionHandling get() = configuration.get(KonanConfigKeys.WORKER_EXCEPTION_HANDLING)!! + val runtimeLogs: String? get() = configuration.get(KonanConfigKeys.RUNTIME_LOGS) val needVerifyIr: Boolean get() = configuration.get(KonanConfigKeys.VERIFY_IR) == true diff --git a/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/KonanConfigurationKeys.kt b/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/KonanConfigurationKeys.kt index 10f4433bde7..6bdce5a7301 100644 --- a/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/KonanConfigurationKeys.kt +++ b/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/KonanConfigurationKeys.kt @@ -165,6 +165,7 @@ class KonanConfigKeys { val EXTERNAL_DEPENDENCIES: CompilerConfigurationKey = CompilerConfigurationKey.create("use external dependencies to enhance IR linker error messages") val LLVM_VARIANT: CompilerConfigurationKey = CompilerConfigurationKey.create("llvm variant") + val RUNTIME_LOGS: CompilerConfigurationKey = CompilerConfigurationKey.create("enable runtime logging") } } diff --git a/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/llvm/IrToBitcode.kt b/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/llvm/IrToBitcode.kt index 592326f1ccf..d19173b2002 100644 --- a/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/llvm/IrToBitcode.kt +++ b/kotlin-native/backend.native/compiler/ir/backend.native/src/org/jetbrains/kotlin/backend/konan/llvm/IrToBitcode.kt @@ -2590,6 +2590,10 @@ internal class CodeGeneratorVisitor(val context: Context, val lifetimes: Map + #include "CompilerConstants.hpp" #include "GlobalData.hpp" +#include "Logging.hpp" #include "MarkAndSweepUtils.hpp" #include "Memory.h" #include "RootSet.hpp" @@ -68,6 +71,7 @@ void gc::SameThreadMarkAndSweep::ThreadData::SafePointAllocation(size_t size) no if (threadData_.suspensionData().suspendIfRequested()) { allocatedBytes_ = 0; } else if (allocationOverhead + size >= gc_.GetAllocationThresholdBytes()) { + RuntimeLogDebug({kTagGC}, "Attempt to GC at SafePointAllocation size=%zu", size); allocatedBytes_ = 0; PerformFullGC(); } @@ -92,16 +96,22 @@ void gc::SameThreadMarkAndSweep::ThreadData::PerformFullGC() noexcept { // TODO: These will actually need to be run on a separate thread. // TODO: Cannot use `threadData_` here, because there's no way to transform `mm::ThreadData` into `MemoryState*`. AssertThreadState(ThreadState::kRunnable); + RuntimeLogDebug({kTagGC}, "Starting to run finalizers"); + auto timeBeforeUs = konan::getTimeMicros(); finalizerQueue.Finalize(); + auto timeAfterUs = konan::getTimeMicros(); + RuntimeLogInfo({kTagGC}, "Finished running finalizers in %" PRIu64 " microseconds", timeAfterUs - timeBeforeUs); } void gc::SameThreadMarkAndSweep::ThreadData::OnOOM(size_t size) noexcept { + RuntimeLogDebug({kTagGC}, "Attempt to GC on OOM"); PerformFullGC(); } void gc::SameThreadMarkAndSweep::ThreadData::SafePointRegularSlowPath() noexcept { safePointsCounter_ = 0; if (konan::getTimeMicros() - timeOfLastGcUs_ >= gc_.GetCooldownThresholdUs()) { + RuntimeLogDebug({kTagGC}, "Attempt to GC at SafePointRegular"); timeOfLastGcUs_ = konan::getTimeMicros(); PerformFullGC(); } @@ -128,34 +138,88 @@ gc::SameThreadMarkAndSweep::SameThreadMarkAndSweep() noexcept { } mm::ObjectFactory::FinalizerQueue gc::SameThreadMarkAndSweep::PerformFullGC() noexcept { + RuntimeLogDebug({kTagGC}, "Attempt to suspend threads by thread %d", konan::currentThreadId()); + auto timeStartUs = konan::getTimeMicros(); bool didSuspend = mm::SuspendThreads(); + auto timeSuspendUs = konan::getTimeMicros(); if (!didSuspend) { + RuntimeLogDebug({kTagGC}, "Failed to suspend threads"); // Somebody else suspended the threads, and so ran a GC. // TODO: This breaks if suspension is used by something apart from GC. return {}; } + RuntimeLogDebug({kTagGC}, "Suspended all threads in %" PRIu64 " microseconds", timeSuspendUs - timeStartUs); + RuntimeLogInfo({kTagGC}, "Started GC epoch %zu. Time since last GC %" PRIu64 " microseconds", epoch_, timeStartUs - lastGCTimestampUs_); KStdVector graySet; for (auto& thread : mm::GlobalData::Instance().threadRegistry().LockForIter()) { // TODO: Maybe it's more efficient to do by the suspending thread? thread.Publish(); - for (auto* object : mm::ThreadRootSet(thread)) { - if (!isNullOrMarker(object)) { - graySet.push_back(object); + size_t stack = 0; + size_t tls = 0; + for (auto value : mm::ThreadRootSet(thread)) { + if (!isNullOrMarker(value.object)) { + graySet.push_back(value.object); + switch (value.source) { + case mm::ThreadRootSet::Source::kStack: + ++stack; + break; + case mm::ThreadRootSet::Source::kTLS: + ++tls; + break; + } + } + } + RuntimeLogDebug({kTagGC}, "Collected root set for thread stack=%zu tls=%zu", stack, tls); + } + mm::StableRefRegistry::Instance().ProcessDeletions(); + size_t global = 0; + size_t stableRef = 0; + for (auto value : mm::GlobalRootSet()) { + if (!isNullOrMarker(value.object)) { + graySet.push_back(value.object); + switch (value.source) { + case mm::GlobalRootSet::Source::kGlobal: + ++global; + break; + case mm::GlobalRootSet::Source::kStableRef: + ++stableRef; + break; } } } - mm::StableRefRegistry::Instance().ProcessDeletions(); - for (auto* object : mm::GlobalRootSet()) { - if (!isNullOrMarker(object)) { - graySet.push_back(object); - } - } + auto timeRootSetUs = konan::getTimeMicros(); + RuntimeLogDebug({kTagGC}, "Collected global root set global=%zu stableRef=%zu", global, stableRef); + // Can be unsafe, because we've stopped the world. + auto objectsCountBefore = mm::GlobalData::Instance().objectFactory().GetSizeUnsafe(); + + RuntimeLogInfo({kTagGC}, "Collected root set of size %zu of which %zu are stable refs in %" PRIu64 " microseconds", graySet.size(), stableRef, timeRootSetUs - timeSuspendUs); gc::Mark(std::move(graySet)); + auto timeMarkUs = konan::getTimeMicros(); + RuntimeLogDebug({kTagGC}, "Marked in %" PRIu64 " microseconds", timeMarkUs - timeRootSetUs); auto finalizerQueue = gc::Sweep(mm::GlobalData::Instance().objectFactory()); + auto timeSweepUs = konan::getTimeMicros(); + RuntimeLogDebug({kTagGC}, "Sweeped in %" PRIu64 " microseconds", timeSweepUs - timeMarkUs); + + // Can be unsafe, because we've stopped the world. + auto objectsCountAfter = mm::GlobalData::Instance().objectFactory().GetSizeUnsafe(); mm::ResumeThreads(); + auto timeResumeUs = konan::getTimeMicros(); + + RuntimeLogDebug({kTagGC}, "Resumed threads in %" PRIu64 " microseconds.", timeResumeUs - timeSweepUs); + + auto finalizersCount = finalizerQueue.size(); + auto collectedCount = objectsCountBefore - objectsCountAfter - finalizersCount; + + RuntimeLogInfo( + {kTagGC}, + "Finished GC epoch %zu. Collected %zu objects, to be finalized %zu objects, %zu objects remain. Total pause time %" PRIu64 + " microseconds", + epoch_, collectedCount, finalizersCount, objectsCountAfter, timeResumeUs - timeStartUs); + ++epoch_; + lastGCTimestampUs_ = timeResumeUs; return finalizerQueue; } diff --git a/kotlin-native/runtime/src/gc/stms/cpp/SameThreadMarkAndSweep.hpp b/kotlin-native/runtime/src/gc/stms/cpp/SameThreadMarkAndSweep.hpp index f8f83b40770..f02f8c5d891 100644 --- a/kotlin-native/runtime/src/gc/stms/cpp/SameThreadMarkAndSweep.hpp +++ b/kotlin-native/runtime/src/gc/stms/cpp/SameThreadMarkAndSweep.hpp @@ -83,6 +83,9 @@ public: private: mm::ObjectFactory::FinalizerQueue PerformFullGC() noexcept; + size_t epoch_ = 0; + uint64_t lastGCTimestampUs_ = 0; + size_t threshold_ = 100000; // Roughly 1 safepoint per 10ms (on a subset of examples on one particular machine). size_t allocationThresholdBytes_ = 10 * 1024 * 1024; // 10MiB by default. uint64_t cooldownThresholdUs_ = 200 * 1000; // 200 milliseconds by default. diff --git a/kotlin-native/runtime/src/main/cpp/Alloc.h b/kotlin-native/runtime/src/main/cpp/Alloc.h index 7f9c6042ddc..ccfa9fb2ba0 100644 --- a/kotlin-native/runtime/src/main/cpp/Alloc.h +++ b/kotlin-native/runtime/src/main/cpp/Alloc.h @@ -122,6 +122,12 @@ bool operator!=( template class KonanDeleter { public: + KonanDeleter() = default; + + // This is needed for `KStdUniquePtr` covariance: if `U*` converts to `T*` then `KStdUniquePtr` converts to `KStdUniquePtr`. + template , std::nullptr_t> = nullptr> + KonanDeleter(KonanDeleter) {} + void operator()(T* instance) noexcept { konanDestructInstance(instance); } }; diff --git a/kotlin-native/runtime/src/main/cpp/CompilerConstants.hpp b/kotlin-native/runtime/src/main/cpp/CompilerConstants.hpp index 143a79404d2..38034eced3e 100644 --- a/kotlin-native/runtime/src/main/cpp/CompilerConstants.hpp +++ b/kotlin-native/runtime/src/main/cpp/CompilerConstants.hpp @@ -7,6 +7,18 @@ #define RUNTIME_COMPILER_CONSTANTS_H #include +#if __has_include() +#include +#elif __has_include() +// TODO: Remove when wasm32 is gone. +#include +#include +namespace std { +using string_view = std::experimental::string_view; +} +#else +#error "No " +#endif #include "Common.h" @@ -15,6 +27,7 @@ // These are defined by setRuntimeConstGlobals in IrToBitcode.kt extern "C" const int32_t KonanNeedDebugInfo; extern "C" const int32_t Kotlin_runtimeAssertsMode; +extern "C" const char* const Kotlin_runtimeLogs; namespace kotlin { namespace compiler { @@ -52,6 +65,10 @@ ALWAYS_INLINE inline RuntimeAssertsMode runtimeAssertsMode() noexcept { WorkerExceptionHandling workerExceptionHandling() noexcept; +ALWAYS_INLINE inline std::string_view runtimeLogs() noexcept { + return Kotlin_runtimeLogs == nullptr ? std::string_view() : std::string_view(Kotlin_runtimeLogs); +} + } // namespace compiler } // namespace kotlin diff --git a/kotlin-native/runtime/src/main/cpp/Logging.cpp b/kotlin-native/runtime/src/main/cpp/Logging.cpp new file mode 100644 index 00000000000..fe35c954dad --- /dev/null +++ b/kotlin-native/runtime/src/main/cpp/Logging.cpp @@ -0,0 +1,194 @@ +/* + * Copyright 2010-2021 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license + * that can be found in the LICENSE file. + */ + +#include "Logging.hpp" + +#include +#if __has_include() +#include +#elif __has_include() +// TODO: Remove when wasm32 is gone. +#include +namespace std { +template +using optional = std::experimental::optional; +inline constexpr auto nullopt = std::experimental::nullopt; +} // namespace std +#else +#error "No " +#endif + +#include "Format.h" +#include "KAssert.h" + +using namespace kotlin; + +namespace { + +template +struct ParseResult { + std::optional value; + std::string_view rest; +}; + +ParseResult ParseTag(std::string_view input) noexcept { + auto position = input.find('='); + if (position == std::string_view::npos || position == 0) { + return {std::nullopt, input}; + } + return {input.substr(0, position), input.substr(position + 1)}; +} + +ParseResult ParseLevelString(std::string_view input) noexcept { + auto position = input.find(','); + if (position == 0) { + return {std::nullopt, input}; + } + if (position == std::string_view::npos) { + return {input, std::string_view()}; + } + return {input.substr(0, position), input.substr(position + 1)}; +} + +std::optional ParseLevel(std::string_view levelString) noexcept { + if (levelString == "debug") return logging::Level::kDebug; + if (levelString == "info") return logging::Level::kInfo; + if (levelString == "warning") return logging::Level::kWarning; + if (levelString == "error") return logging::Level::kError; + return std::nullopt; +} + +KStdOrderedMap ParseTagsFilter(std::string_view tagsFilter) noexcept { + if (tagsFilter.empty()) return {}; + KStdOrderedMap result; + std::string_view rest = tagsFilter; + while (!rest.empty()) { + auto tag = ParseTag(rest); + rest = tag.rest; + if (tag.value == std::nullopt) { + konan::consoleErrorf("Failed to parse tag at: '"); + konan::consoleErrorUtf8(rest.data(), rest.size()); + konan::consoleErrorf("'. No logging will be performed\n"); + return {}; + } + auto levelString = ParseLevelString(rest); + rest = levelString.rest; + auto level = levelString.value ? ParseLevel(*levelString.value) : std::nullopt; + if (level == std::nullopt) { + konan::consoleErrorf("Failed to parse level at: '"); + konan::consoleErrorUtf8(rest.data(), rest.size()); + konan::consoleErrorf("'. No logging will be performed\n"); + return {}; + } + result.emplace(KStdString(tag.value->data(), tag.value->size()), *level); + } + return result; +} + +class LogFilter : public logging::internal::LogFilter { +public: + explicit LogFilter(std::string_view tagsFilter) noexcept : tagLevelMap_(ParseTagsFilter(tagsFilter)) {} + + bool Empty() const noexcept override { return tagLevelMap_.empty(); } + + bool Enabled(logging::Level level, std_support::span tags) const noexcept override { + for (auto tag : tags) { + auto it = tagLevelMap_.find(tag); + if (it != tagLevelMap_.end()) { + if (it->second <= level) { + return true; + } + } + } + return false; + } + +private: + // TODO: Make it more efficient. + KStdOrderedMap tagLevelMap_; +}; + +class StderrLogger : public logging::internal::Logger { +public: + void Log(logging::Level level, std_support::span tags, std::string_view message) const noexcept override { + konan::consoleErrorUtf8(message.data(), message.size()); + konan::consoleErrorf("\n"); + } +}; + +std_support::span FormatLevel(std_support::span buffer, logging::Level level) noexcept { + switch (level) { + case logging::Level::kDebug: + return FormatToSpan(buffer, "[DEBUG]"); + case logging::Level::kInfo: + return FormatToSpan(buffer, "[INFO]"); + case logging::Level::kWarning: + return FormatToSpan(buffer, "[WARN]"); + case logging::Level::kError: + return FormatToSpan(buffer, "[ERROR]"); + } +} + +std_support::span FormatTags(std_support::span buffer, std_support::span tags) noexcept { + // `tags` cannot be empty. + auto firstTag = tags.front(); + buffer = FormatToSpan(buffer, "[%s", firstTag); + for (auto tag : tags.subspan(1)) { + buffer = FormatToSpan(buffer, ",%s", tag); + } + return FormatToSpan(buffer, "]"); +} + +} // namespace + +KStdUniquePtr logging::internal::CreateLogFilter(std::string_view tagsFilter) noexcept { + return ::make_unique<::LogFilter>(tagsFilter); +} + +KStdUniquePtr logging::internal::CreateStderrLogger() noexcept { + return ::make_unique(); +} + +std_support::span logging::internal::FormatLogEntry( + std_support::span buffer, + logging::Level level, + std_support::span tags, + const char* format, + std::va_list args) noexcept { + buffer = FormatLevel(buffer, level); + buffer = FormatTags(buffer, tags); + buffer = FormatToSpan(buffer, " "); + buffer = VFormatToSpan(buffer, format, args); + return buffer; +} + +void logging::internal::Log( + const LogFilter& logFilter, + const Logger& logger, + Level level, + std_support::span tags, + const char* format, + std::va_list args) noexcept { + if (!logFilter.Enabled(level, tags)) return; + // TODO: This might be suboptimal. + std::array logEntry; + auto rest = FormatLogEntry(logEntry, level, tags, format, args); + logger.Log(level, tags, std::string_view(logEntry.data(), rest.data() - logEntry.data())); +} + +void logging::Log(Level level, std::initializer_list tags, const char* format, ...) noexcept { + std::va_list args; + va_start(args, format); + VLog(level, tags, format, args); + va_end(args); +} + +void logging::VLog(Level level, std::initializer_list tags, const char* format, std::va_list args) noexcept { + static auto logFilter = internal::CreateLogFilter(compiler::runtimeLogs()); + static auto logger = internal::CreateStderrLogger(); + RuntimeAssert(tags.size() > 0, "Cannot Log without tags"); + std_support::span tagsSpan(std::data(tags), std::size(tags)); + internal::Log(*logFilter, *logger, level, tagsSpan, format, args); +} diff --git a/kotlin-native/runtime/src/main/cpp/Logging.hpp b/kotlin-native/runtime/src/main/cpp/Logging.hpp new file mode 100644 index 00000000000..95c2c8de680 --- /dev/null +++ b/kotlin-native/runtime/src/main/cpp/Logging.hpp @@ -0,0 +1,116 @@ +/* + * Copyright 2010-2021 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license + * that can be found in the LICENSE file. + */ + +#ifndef RUNTIME_LOGGING_H +#define RUNTIME_LOGGING_H + +#include +#include +#if __has_include() +#include +#elif __has_include() +// TODO: Remove when wasm32 is gone. +#include +#include +namespace std { +using string_view = std::experimental::string_view; +} +#else +#error "No " +#endif + +#include "CompilerConstants.hpp" +#include "cpp_support/Span.hpp" +#include "Types.h" + +namespace kotlin { +namespace logging { + +enum class Level { + kDebug, + kInfo, + kWarning, + kError, +}; + +namespace internal { + +class LogFilter { +public: + virtual ~LogFilter() = default; + + virtual bool Empty() const noexcept = 0; + virtual bool Enabled(Level level, std_support::span tags) const noexcept = 0; +}; + +KStdUniquePtr CreateLogFilter(std::string_view tagsFilter) noexcept; + +class Logger { +public: + virtual ~Logger() = default; + + virtual void Log(Level level, std_support::span tags, std::string_view message) const noexcept = 0; +}; + +KStdUniquePtr CreateStderrLogger() noexcept; + +std_support::span FormatLogEntry( + std_support::span buffer, + Level level, + std_support::span tags, + const char* format, + std::va_list args) noexcept; + +void Log( + const LogFilter& logFilter, + const Logger& logger, + Level level, + std_support::span tags, + const char* format, + std::va_list args) noexcept; + +} // namespace internal + +__attribute__((format(printf, 3, 4))) void Log(Level level, std::initializer_list tags, const char* format, ...) noexcept; +void VLog(Level level, std::initializer_list tags, const char* format, std::va_list args) noexcept; + +} // namespace logging + +// Well known tags. +// These are defined outside of logging namespace for simpler usage. + +inline constexpr const char* kTagGC = "gc"; +inline constexpr const char* kTagMM = "mm"; + +} // namespace kotlin + +#endif // RUNTIME_LOGGING_H + +// Using macros to simplify forwarding of varargs without breaking __attribute__((format)) and to avoid +// evaluating args in `...` if logging is disabled. + +#define RuntimeLog(level, tags, format, ...) \ + do { \ + if (!::kotlin::compiler::runtimeLogs().empty()) { \ + ::kotlin::logging::Log(level, tags, format, ##__VA_ARGS__); \ + } \ + } while (false) + +#define RuntimeVLog(level, tags, format, args) \ + do { \ + if (!::kotlin::compiler::runtimeLogs().empty()) { \ + ::kotlin::logging::VLog(level, tags, format, args); \ + } \ + } while (false) + +#define RuntimeLogDebug(tags, format, ...) RuntimeLog(::kotlin::logging::Level::kDebug, tags, format, ##__VA_ARGS__) +#define RuntimeLogInfo(tags, format, ...) RuntimeLog(::kotlin::logging::Level::kInfo, tags, format, ##__VA_ARGS__) +#define RuntimeLogWarning(tags, format, ...) RuntimeLog(::kotlin::logging::Level::kWarning, tags, format, ##__VA_ARGS__) +#define RuntimeLogError(tags, format, ...) RuntimeLog(::kotlin::logging::Level::kError, tags, format, ##__VA_ARGS__) + +#define RuntimeVLogDebug(tags, format, args) RuntimeVLog(::kotlin::logging::Level::kDebug, tags, format, args) +#define RuntimeVLogInfo(tags, format, args) RuntimeVLog(::kotlin::logging::Level::kInfo, tags, format, args) +#define RuntimeVLogWarning(tags, format, args) RuntimeVLog(::kotlin::logging::Level::kWarning, tags, format, args) +#define RuntimeVLogError(tags, format, args) RuntimeVLog(::kotlin::logging::Level::kError, tags, format, args) diff --git a/kotlin-native/runtime/src/main/cpp/LoggingTest.cpp b/kotlin-native/runtime/src/main/cpp/LoggingTest.cpp new file mode 100644 index 00000000000..14e124a56c4 --- /dev/null +++ b/kotlin-native/runtime/src/main/cpp/LoggingTest.cpp @@ -0,0 +1,220 @@ +/* + * Copyright 2010-2021 JetBrains s.r.o. Use of this source code is governed by the Apache 2.0 license + * that can be found in the LICENSE file. + */ + +#include "Logging.hpp" + +#include "gmock/gmock.h" +#include "gtest/gtest.h" + +using namespace kotlin; + +using ::testing::_; + +namespace { + +std_support::span FormatLogEntry( + std_support::span buffer, logging::Level level, std::initializer_list tags, const char* format, ...) { + std_support::span tagsSpan(std::data(tags), std::size(tags)); + std::va_list args; + va_start(args, format); + auto result = logging::internal::FormatLogEntry(buffer, level, tagsSpan, format, args); + va_end(args); + return result; +} + +class LogFilter { +public: + explicit LogFilter(std::string_view filter) : logFilter_(logging::internal::CreateLogFilter(filter)) {} + + bool Empty() const { return logFilter_->Empty(); } + + bool Enabled(logging::Level level, std::initializer_list tags) const { + std_support::span tagsSpan(std::data(tags), std::size(tags)); + return logFilter_->Enabled(level, tagsSpan); + } + +private: + KStdUniquePtr logFilter_; +}; + +class MockLogFilter : public logging::internal::LogFilter { +public: + MOCK_METHOD(bool, Empty, (), (const, noexcept, override)); + MOCK_METHOD(bool, Enabled, (logging::Level, std_support::span), (const, noexcept, override)); +}; + +class MockLogger : public logging::internal::Logger { +public: + MOCK_METHOD(void, Log, (logging::Level, std_support::span, std::string_view), (const, noexcept, override)); +}; + +} // namespace + +TEST(LoggingTest, FormatLogEntry_Debug_OneTag) { + std::array buffer; + FormatLogEntry(buffer, logging::Level::kDebug, {"t1"}, "Log #%d", 42); + EXPECT_THAT(buffer.data(), testing::StrEq("[DEBUG][t1] Log #42")); +} + +TEST(LoggingTest, FormatLogEntry_Debug_TwoTags) { + std::array buffer; + FormatLogEntry(buffer, logging::Level::kDebug, {"t1", "t2"}, "Log #%d", 42); + EXPECT_THAT(buffer.data(), testing::StrEq("[DEBUG][t1,t2] Log #42")); +} + +TEST(LoggingTest, FormatLogEntry_Info_OneTag) { + std::array buffer; + FormatLogEntry(buffer, logging::Level::kInfo, {"t1"}, "Log #%d", 42); + EXPECT_THAT(buffer.data(), testing::StrEq("[INFO][t1] Log #42")); +} + +TEST(LoggingTest, FormatLogEntry_Info_TwoTags) { + std::array buffer; + FormatLogEntry(buffer, logging::Level::kInfo, {"t1", "t2"}, "Log #%d", 42); + EXPECT_THAT(buffer.data(), testing::StrEq("[INFO][t1,t2] Log #42")); +} + +TEST(LoggingTest, FormatLogEntry_Warning_OneTag) { + std::array buffer; + FormatLogEntry(buffer, logging::Level::kWarning, {"t1"}, "Log #%d", 42); + EXPECT_THAT(buffer.data(), testing::StrEq("[WARN][t1] Log #42")); +} + +TEST(LoggingTest, FormatLogEntry_Warning_TwoTags) { + std::array buffer; + FormatLogEntry(buffer, logging::Level::kWarning, {"t1", "t2"}, "Log #%d", 42); + EXPECT_THAT(buffer.data(), testing::StrEq("[WARN][t1,t2] Log #42")); +} + +TEST(LoggingTest, FormatLogEntry_Error_OneTag) { + std::array buffer; + FormatLogEntry(buffer, logging::Level::kError, {"t1"}, "Log #%d", 42); + EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1] Log #42")); +} + +TEST(LoggingTest, FormatLogEntry_Error_TwoTags) { + std::array buffer; + FormatLogEntry(buffer, logging::Level::kError, {"t1", "t2"}, "Log #%d", 42); + EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1,t2] Log #42")); +} + +TEST(LoggingDeathTest, StderrLogger) { + auto logger = logging::internal::CreateStderrLogger(); + EXPECT_DEATH( + { + logger->Log(logging::Level::kInfo, {}, "Message for the log"); + std::abort(); + }, + "Message for the log"); +} + +TEST(LoggingTest, LogFilter_Empty) { + LogFilter filter(""); + EXPECT_TRUE(filter.Empty()); +} + +TEST(LoggingTest, LogFilter_EnableOne) { + LogFilter filter("t1=info"); + EXPECT_FALSE(filter.Empty()); + + EXPECT_FALSE(filter.Enabled(logging::Level::kDebug, {"t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {"t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {"t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kError, {"t1"})); + + EXPECT_FALSE(filter.Enabled(logging::Level::kDebug, {"t2"})); + EXPECT_FALSE(filter.Enabled(logging::Level::kInfo, {"t2"})); + EXPECT_FALSE(filter.Enabled(logging::Level::kWarning, {"t2"})); + EXPECT_FALSE(filter.Enabled(logging::Level::kError, {"t2"})); + + EXPECT_FALSE(filter.Enabled(logging::Level::kDebug, {"t1", "t2"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {"t1", "t2"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {"t1", "t2"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kError, {"t1", "t2"})); + + EXPECT_FALSE(filter.Enabled(logging::Level::kDebug, {"t2", "t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {"t2", "t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {"t2", "t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kError, {"t2", "t1"})); +} + +TEST(LoggingTest, LogFilter_EnableTwo) { + LogFilter filter("t1=info,t2=warning"); + EXPECT_FALSE(filter.Empty()); + + EXPECT_FALSE(filter.Enabled(logging::Level::kDebug, {"t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {"t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {"t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kError, {"t1"})); + + EXPECT_FALSE(filter.Enabled(logging::Level::kDebug, {"t2"})); + EXPECT_FALSE(filter.Enabled(logging::Level::kInfo, {"t2"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {"t2"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kError, {"t2"})); + + EXPECT_FALSE(filter.Enabled(logging::Level::kDebug, {"t1", "t2"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {"t1", "t2"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {"t1", "t2"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kError, {"t1", "t2"})); + + EXPECT_FALSE(filter.Enabled(logging::Level::kDebug, {"t2", "t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {"t2", "t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {"t2", "t1"})); + EXPECT_TRUE(filter.Enabled(logging::Level::kError, {"t2", "t1"})); +} + +TEST(LoggingTest, LogFilter_Broken) { + EXPECT_TRUE(LogFilter("t1").Empty()); + EXPECT_TRUE(LogFilter("t1=").Empty()); + EXPECT_TRUE(LogFilter("t1=oops").Empty()); + EXPECT_TRUE(LogFilter("t1=info,t2").Empty()); + EXPECT_TRUE(LogFilter("t1=info,t2=").Empty()); + EXPECT_TRUE(LogFilter("t1=info,t2=oops").Empty()); +} + +namespace { + +class LoggingLogTest : public testing::Test { +public: + void Log(logging::Level level, std::initializer_list tags, const char* format, ...) { + std::va_list args; + va_start(args, format); + logging::internal::Log( + logFilter_, logger_, level, std_support::span(std::data(tags), std::size(tags)), format, args); + va_end(args); + } + + MockLogFilter& logFilter() { return logFilter_; } + MockLogger& logger() { return logger_; } + +private: + testing::StrictMock logFilter_; + testing::StrictMock logger_; +}; + +MATCHER_P(TagsAre, tags, "") { + KStdVector actualTags; + for (auto tag : arg) { + actualTags.push_back(tag); + } + return testing::ExplainMatchResult(testing::ElementsAreArray(tags), actualTags, result_listener); +} + +} // namespace + +TEST_F(LoggingLogTest, Log_Fail) { + constexpr auto level = logging::Level::kInfo; + const std::initializer_list tags = {"t1", "t2"}; + EXPECT_CALL(logFilter(), Enabled(level, TagsAre(tags))).WillOnce(testing::Return(false)); + Log(level, tags, "Message %d", 42); +} + +TEST_F(LoggingLogTest, Log_Success) { + constexpr auto level = logging::Level::kInfo; + const std::initializer_list tags = {"t1", "t2"}; + EXPECT_CALL(logFilter(), Enabled(level, TagsAre(tags))).WillOnce(testing::Return(true)); + EXPECT_CALL(logger(), Log(level, TagsAre(tags), "[INFO][t1,t2] Message 42")); + Log(level, tags, "Message %d", 42); +} diff --git a/kotlin-native/runtime/src/main/cpp/Porting.cpp b/kotlin-native/runtime/src/main/cpp/Porting.cpp index b4d784c8300..73d3ab1821e 100644 --- a/kotlin-native/runtime/src/main/cpp/Porting.cpp +++ b/kotlin-native/runtime/src/main/cpp/Porting.cpp @@ -512,7 +512,7 @@ extern "C" { int _ZNSt3__112__next_primeEj(unsigned long n) { return _ZNSt3__212__next_primeEj(n); } - void __assert_fail(const char * assertion, const char * file, unsigned int line, const char * function) { + void __assert_fail(const char* assertion, const char* file, int line, const char* function) { char buf[1024]; konan::snprintf(buf, sizeof(buf), "%s:%d in %s: runtime assert: %s\n", file, line, function, assertion); Konan_abort(buf); diff --git a/kotlin-native/runtime/src/mm/cpp/ObjectFactory.hpp b/kotlin-native/runtime/src/mm/cpp/ObjectFactory.hpp index 4352e159253..cf2d46d878d 100644 --- a/kotlin-native/runtime/src/mm/cpp/ObjectFactory.hpp +++ b/kotlin-native/runtime/src/mm/cpp/ObjectFactory.hpp @@ -126,6 +126,8 @@ public: ~Producer() { Publish(); } + size_t size() const noexcept { return size_; } + Node& Insert(size_t dataSize) noexcept { AssertCorrect(); auto node = Node::Create(allocator_, dataSize); @@ -137,6 +139,7 @@ public: } last_ = nodePtr; + ++size_; RuntimeAssert(root_ != nullptr, "Must not be empty"); AssertCorrect(); return *nodePtr; @@ -172,6 +175,8 @@ public: owner_.last_ = last_; last_ = nullptr; + owner_.size_ += size_; + size_ = 0; RuntimeAssert(root_ == nullptr, "Must be empty"); AssertCorrect(); @@ -186,6 +191,7 @@ public: // Since it's only for tests, no need to worry about stack overflows. root_.reset(); last_ = nullptr; + size_ = 0; } private: @@ -204,6 +210,7 @@ public: Allocator allocator_; unique_ptr root_; Node* last_ = nullptr; + size_t size_ = 0; }; class Iterator { @@ -263,6 +270,8 @@ public: } } + size_t size() const noexcept { return size_; } + Iterator begin() noexcept { return Iterator(root_.get()); } Iterator end() noexcept { return Iterator(nullptr); } @@ -279,6 +288,7 @@ public: } last_ = nodePtr; + ++size_; AssertCorrect(); } @@ -293,12 +303,15 @@ public: unique_ptr root_; Node* last_ = nullptr; + size_t size_ = 0; }; class Iterable : private MoveOnly { public: explicit Iterable(ObjectFactoryStorage& owner) noexcept : owner_(owner), guard_(owner_.mutex_) {} + size_t size() const noexcept { return owner_.size_; } + Iterator begin() noexcept { return Iterator(nullptr, owner_.root_.get()); } Iterator end() noexcept { return Iterator(owner_.last_, nullptr); } @@ -326,9 +339,12 @@ public: // Lock `ObjectFactoryStorage` for safe iteration. Iterable LockForIter() noexcept { return Iterable(*this); } + size_t GetSizeUnsafe() const noexcept { return size_; } + void ClearForTests() { root_.reset(); last_ = nullptr; + size_ = 0; } private: @@ -344,6 +360,7 @@ private: if (!root_) { last_ = nullptr; } + --size_; AssertCorrectUnsafe(); return {std::move(node), root_.get()}; } @@ -353,6 +370,7 @@ private: if (!previousNode->next_) { last_ = previousNode; } + --size_; AssertCorrectUnsafe(); return {std::move(node), previousNode->next_.get()}; @@ -370,6 +388,7 @@ private: unique_ptr root_; Node* last_ = nullptr; + size_t size_ = 0; SpinLock mutex_; }; @@ -602,6 +621,8 @@ public: FinalizerQueue& owner_; }; + size_t size() const noexcept { return consumer_.size(); } + // TODO: Consider running it in the destructor instead. void Finalize() noexcept { for (auto node : Iterable(*this)) { @@ -640,6 +661,8 @@ public: // Lock ObjectFactory for safe iteration. Iterable LockForIter() noexcept { return Iterable(*this); } + size_t GetSizeUnsafe() const noexcept { return storage_.GetSizeUnsafe(); } + void ClearForTests() { storage_.ClearForTests(); } private: diff --git a/kotlin-native/runtime/src/mm/cpp/ObjectFactoryTest.cpp b/kotlin-native/runtime/src/mm/cpp/ObjectFactoryTest.cpp index 73da69a7ce1..74e08a6e69f 100644 --- a/kotlin-native/runtime/src/mm/cpp/ObjectFactoryTest.cpp +++ b/kotlin-native/runtime/src/mm/cpp/ObjectFactoryTest.cpp @@ -93,6 +93,7 @@ TEST(ObjectFactoryStorageTest, Empty) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::IsEmpty()); + EXPECT_THAT(storage.GetSizeUnsafe(), 0); } TEST(ObjectFactoryStorageTest, DoNotPublish) { @@ -105,6 +106,8 @@ TEST(ObjectFactoryStorageTest, DoNotPublish) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::IsEmpty()); + EXPECT_THAT(storage.GetSizeUnsafe(), 0); + EXPECT_THAT(producer.size(), 2); } TEST(ObjectFactoryStorageTest, Publish) { @@ -123,6 +126,9 @@ TEST(ObjectFactoryStorageTest, Publish) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::ElementsAre(1, 2, 10, 20)); + EXPECT_THAT(storage.GetSizeUnsafe(), 4); + EXPECT_THAT(producer1.size(), 0); + EXPECT_THAT(producer2.size(), 0); } TEST(ObjectFactoryStorageTest, PublishDifferentTypes) { @@ -156,6 +162,8 @@ TEST(ObjectFactoryStorageTest, PublishDifferentTypes) { EXPECT_THAT(maxAlign.value, 8); ++it; EXPECT_THAT(it, actual.end()); + EXPECT_THAT(storage.GetSizeUnsafe(), 5); + EXPECT_THAT(producer.size(), 0); } TEST(ObjectFactoryStorageTest, PublishSeveralTimes) { @@ -182,6 +190,8 @@ TEST(ObjectFactoryStorageTest, PublishSeveralTimes) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::ElementsAre(1, 2, 3, 4, 5)); + EXPECT_THAT(storage.GetSizeUnsafe(), 5); + EXPECT_THAT(producer.size(), 0); } TEST(ObjectFactoryStorageTest, PublishInDestructor) { @@ -196,6 +206,7 @@ TEST(ObjectFactoryStorageTest, PublishInDestructor) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::ElementsAre(1, 2)); + EXPECT_THAT(storage.GetSizeUnsafe(), 2); } TEST(ObjectFactoryStorageTest, FindNode) { @@ -235,6 +246,8 @@ TEST(ObjectFactoryStorageTest, EraseFirst) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::ElementsAre(2, 3)); + EXPECT_THAT(storage.GetSizeUnsafe(), 2); + EXPECT_THAT(producer.size(), 0); } TEST(ObjectFactoryStorageTest, EraseMiddle) { @@ -261,6 +274,8 @@ TEST(ObjectFactoryStorageTest, EraseMiddle) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::ElementsAre(1, 3)); + EXPECT_THAT(storage.GetSizeUnsafe(), 2); + EXPECT_THAT(producer.size(), 0); } TEST(ObjectFactoryStorageTest, EraseLast) { @@ -287,6 +302,8 @@ TEST(ObjectFactoryStorageTest, EraseLast) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::ElementsAre(1, 2)); + EXPECT_THAT(storage.GetSizeUnsafe(), 2); + EXPECT_THAT(producer.size(), 0); } TEST(ObjectFactoryStorageTest, EraseAll) { @@ -309,6 +326,8 @@ TEST(ObjectFactoryStorageTest, EraseAll) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::IsEmpty()); + EXPECT_THAT(storage.GetSizeUnsafe(), 0); + EXPECT_THAT(producer.size(), 0); } TEST(ObjectFactoryStorageTest, EraseTheOnlyElement) { @@ -329,6 +348,8 @@ TEST(ObjectFactoryStorageTest, EraseTheOnlyElement) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::IsEmpty()); + EXPECT_THAT(storage.GetSizeUnsafe(), 0); + EXPECT_THAT(producer.size(), 0); } TEST(ObjectFactoryStorageTest, MoveFirst) { @@ -358,6 +379,9 @@ TEST(ObjectFactoryStorageTest, MoveFirst) { EXPECT_THAT(actual, testing::ElementsAre(2, 3)); EXPECT_THAT(actualConsumer, testing::ElementsAre(1)); + EXPECT_THAT(storage.GetSizeUnsafe(), 2); + EXPECT_THAT(producer.size(), 0); + EXPECT_THAT(consumer.size(), 1); } TEST(ObjectFactoryStorageTest, MoveMiddle) { @@ -387,6 +411,9 @@ TEST(ObjectFactoryStorageTest, MoveMiddle) { EXPECT_THAT(actual, testing::ElementsAre(1, 3)); EXPECT_THAT(actualConsumer, testing::ElementsAre(2)); + EXPECT_THAT(storage.GetSizeUnsafe(), 2); + EXPECT_THAT(producer.size(), 0); + EXPECT_THAT(consumer.size(), 1); } TEST(ObjectFactoryStorageTest, MoveLast) { @@ -416,6 +443,9 @@ TEST(ObjectFactoryStorageTest, MoveLast) { EXPECT_THAT(actual, testing::ElementsAre(1, 2)); EXPECT_THAT(actualConsumer, testing::ElementsAre(3)); + EXPECT_THAT(storage.GetSizeUnsafe(), 2); + EXPECT_THAT(producer.size(), 0); + EXPECT_THAT(consumer.size(), 1); } TEST(ObjectFactoryStorageTest, MoveAll) { @@ -441,6 +471,9 @@ TEST(ObjectFactoryStorageTest, MoveAll) { EXPECT_THAT(actual, testing::IsEmpty()); EXPECT_THAT(actualConsumer, testing::ElementsAre(1, 2, 3)); + EXPECT_THAT(storage.GetSizeUnsafe(), 0); + EXPECT_THAT(producer.size(), 0); + EXPECT_THAT(consumer.size(), 3); } TEST(ObjectFactoryStorageTest, MoveTheOnlyElement) { @@ -464,6 +497,9 @@ TEST(ObjectFactoryStorageTest, MoveTheOnlyElement) { EXPECT_THAT(actual, testing::IsEmpty()); EXPECT_THAT(actualConsumer, testing::ElementsAre(1)); + EXPECT_THAT(storage.GetSizeUnsafe(), 0); + EXPECT_THAT(producer.size(), 0); + EXPECT_THAT(consumer.size(), 1); } TEST(ObjectFactoryStorageTest, MoveAndErase) { @@ -497,6 +533,9 @@ TEST(ObjectFactoryStorageTest, MoveAndErase) { EXPECT_THAT(actual, testing::ElementsAre(1, 4, 7)); EXPECT_THAT(actualConsumer, testing::ElementsAre(3, 6, 9)); + EXPECT_THAT(storage.GetSizeUnsafe(), 3); + EXPECT_THAT(producer.size(), 0); + EXPECT_THAT(consumer.size(), 3); } TEST(ObjectFactoryStorageTest, ConcurrentPublish) { @@ -529,6 +568,7 @@ TEST(ObjectFactoryStorageTest, ConcurrentPublish) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::UnorderedElementsAreArray(expected)); + EXPECT_THAT(storage.GetSizeUnsafe(), expected.size()); } TEST(ObjectFactoryStorageTest, IterWhileConcurrentPublish) { @@ -588,6 +628,7 @@ TEST(ObjectFactoryStorageTest, IterWhileConcurrentPublish) { auto actualAfter = Collect(storage); EXPECT_THAT(actualAfter, testing::UnorderedElementsAreArray(expectedAfter)); + EXPECT_THAT(storage.GetSizeUnsafe(), expectedAfter.size()); } TEST(ObjectFactoryStorageTest, EraseWhileConcurrentPublish) { @@ -647,6 +688,7 @@ TEST(ObjectFactoryStorageTest, EraseWhileConcurrentPublish) { auto actual = Collect(storage); EXPECT_THAT(actual, testing::UnorderedElementsAreArray(expectedAfter)); + EXPECT_THAT(storage.GetSizeUnsafe(), expectedAfter.size()); } using mm::internal::AllocatorWithGC; diff --git a/kotlin-native/runtime/src/mm/cpp/RootSet.cpp b/kotlin-native/runtime/src/mm/cpp/RootSet.cpp index ff9e65a9100..53e98e0d4cc 100644 --- a/kotlin-native/runtime/src/mm/cpp/RootSet.cpp +++ b/kotlin-native/runtime/src/mm/cpp/RootSet.cpp @@ -18,12 +18,12 @@ mm::ThreadRootSet::Iterator::Iterator(begin_t, ThreadRootSet& owner) noexcept : mm::ThreadRootSet::Iterator::Iterator(end_t, ThreadRootSet& owner) noexcept : owner_(owner), phase_(Phase::kDone) {} -ObjHeader*& mm::ThreadRootSet::Iterator::operator*() noexcept { +mm::ThreadRootSet::Value mm::ThreadRootSet::Iterator::operator*() noexcept { switch (phase_) { case Phase::kStack: - return *stackIterator_; + return {*stackIterator_, Source::kStack}; case Phase::kTLS: - return **tlsIterator_; + return {**tlsIterator_, Source::kTLS}; case Phase::kDone: RuntimeFail("Cannot dereference"); } @@ -84,12 +84,12 @@ mm::GlobalRootSet::Iterator::Iterator(begin_t, GlobalRootSet& owner) noexcept : mm::GlobalRootSet::Iterator::Iterator(end_t, GlobalRootSet& owner) noexcept : owner_(owner), phase_(Phase::kDone) {} -ObjHeader*& mm::GlobalRootSet::Iterator::operator*() noexcept { +mm::GlobalRootSet::Value mm::GlobalRootSet::Iterator::operator*() noexcept { switch (phase_) { case Phase::kGlobals: - return **globalsIterator_; + return {**globalsIterator_, Source::kGlobal}; case Phase::kStableRefs: - return *stableRefsIterator_; + return {*stableRefsIterator_, Source::kStableRef}; case Phase::kDone: RuntimeFail("Cannot dereference"); } diff --git a/kotlin-native/runtime/src/mm/cpp/RootSet.hpp b/kotlin-native/runtime/src/mm/cpp/RootSet.hpp index dcd5c2178da..ca7ff452bb7 100644 --- a/kotlin-native/runtime/src/mm/cpp/RootSet.hpp +++ b/kotlin-native/runtime/src/mm/cpp/RootSet.hpp @@ -20,6 +20,18 @@ class ThreadData; class ThreadRootSet { public: + enum class Source { + kStack, + kTLS, + }; + + struct Value { + ObjHeader*& object; + Source source; + + bool operator==(const Value& rhs) const noexcept { return object == rhs.object && source == rhs.source; } + }; + class Iterator { public: struct begin_t {}; @@ -31,7 +43,7 @@ public: Iterator(begin_t, ThreadRootSet& owner) noexcept; Iterator(end_t, ThreadRootSet& owner) noexcept; - ObjHeader*& operator*() noexcept; + Value operator*() noexcept; Iterator& operator++() noexcept; @@ -68,6 +80,18 @@ private: class GlobalRootSet { public: + enum class Source { + kGlobal, + kStableRef, + }; + + struct Value { + ObjHeader*& object; + Source source; + + bool operator==(const Value& rhs) const noexcept { return object == rhs.object && source == rhs.source; } + }; + class Iterator { public: struct begin_t {}; @@ -79,7 +103,7 @@ public: Iterator(begin_t, GlobalRootSet& owner) noexcept; Iterator(end_t, GlobalRootSet& owner) noexcept; - ObjHeader*& operator*() noexcept; + Value operator*() noexcept; Iterator& operator++() noexcept; diff --git a/kotlin-native/runtime/src/mm/cpp/RootSetTest.cpp b/kotlin-native/runtime/src/mm/cpp/RootSetTest.cpp index 9bb3d682e41..24eea3f63ad 100644 --- a/kotlin-native/runtime/src/mm/cpp/RootSetTest.cpp +++ b/kotlin-native/runtime/src/mm/cpp/RootSetTest.cpp @@ -59,12 +59,18 @@ TEST(ThreadRootSetTest, Basic) { mm::ThreadRootSet iter(stack, tls); - KStdVector actual; - for (auto& object : iter) { + KStdVector actual; + for (auto object : iter) { actual.push_back(object); } - EXPECT_THAT(actual, testing::ElementsAre(entry[0], entry[1], *tls.Lookup(&key, 0), *tls.Lookup(&key, 1), *tls.Lookup(&key, 2))); + auto asStack = [](ObjHeader*& object) -> mm::ThreadRootSet::Value { return {object, mm::ThreadRootSet::Source::kStack}; }; + auto asTLS = [](ObjHeader*& object) -> mm::ThreadRootSet::Value { return {object, mm::ThreadRootSet::Source::kTLS}; }; + EXPECT_THAT( + actual, + testing::ElementsAre( + asStack(entry[0]), asStack(entry[1]), asTLS(*tls.Lookup(&key, 0)), asTLS(*tls.Lookup(&key, 1)), + asTLS(*tls.Lookup(&key, 2)))); } TEST(ThreadRootSetTest, Empty) { @@ -73,8 +79,8 @@ TEST(ThreadRootSetTest, Empty) { mm::ThreadRootSet iter(stack, tls); - KStdVector actual; - for (auto& object : iter) { + KStdVector actual; + for (auto object : iter) { actual.push_back(object); } @@ -103,12 +109,17 @@ TEST(GlobalRootSetTest, Basic) { mm::GlobalRootSet iter(globals, stableRefs); - KStdVector actual; - for (auto& object : iter) { + KStdVector actual; + for (auto object : iter) { actual.push_back(object); } - EXPECT_THAT(actual, testing::ElementsAre(global1, global2, stableRef1, stableRef2, stableRef3)); + auto asGlobal = [](ObjHeader*& object) -> mm::GlobalRootSet::Value { return {object, mm::GlobalRootSet::Source::kGlobal}; }; + auto asStableRef = [](ObjHeader*& object) -> mm::GlobalRootSet::Value { return {object, mm::GlobalRootSet::Source::kStableRef}; }; + EXPECT_THAT( + actual, + testing::ElementsAre( + asGlobal(global1), asGlobal(global2), asStableRef(stableRef1), asStableRef(stableRef2), asStableRef(stableRef3))); } TEST(GlobalRootSetTest, Empty) { @@ -117,8 +128,8 @@ TEST(GlobalRootSetTest, Empty) { mm::GlobalRootSet iter(globals, stableRefs); - KStdVector actual; - for (auto& object : iter) { + KStdVector actual; + for (auto object : iter) { actual.push_back(object); } diff --git a/kotlin-native/runtime/src/mm/cpp/ThreadData.hpp b/kotlin-native/runtime/src/mm/cpp/ThreadData.hpp index 2904a7eb8af..dc8e57e35f0 100644 --- a/kotlin-native/runtime/src/mm/cpp/ThreadData.hpp +++ b/kotlin-native/runtime/src/mm/cpp/ThreadData.hpp @@ -7,7 +7,6 @@ #define RUNTIME_MM_THREAD_DATA_H #include -#include #include "GlobalData.hpp" #include "GlobalsRegistry.hpp" @@ -29,7 +28,7 @@ namespace mm { // Pin it in memory to prevent accidental copying. class ThreadData final : private Pinned { public: - ThreadData(pthread_t threadId) noexcept : + explicit ThreadData(int threadId) noexcept : threadId_(threadId), globalsThreadQueue_(GlobalsRegistry::Instance()), stableRefThreadQueue_(StableRefRegistry::Instance()), @@ -39,7 +38,7 @@ public: ~ThreadData() = default; - pthread_t threadId() const noexcept { return threadId_; } + int threadId() const noexcept { return threadId_; } GlobalsRegistry::ThreadQueue& globalsThreadQueue() noexcept { return globalsThreadQueue_; } @@ -75,7 +74,7 @@ public: } private: - const pthread_t threadId_; + const int threadId_; GlobalsRegistry::ThreadQueue globalsThreadQueue_; ThreadLocalStorage tls_; StableRefRegistry::ThreadQueue stableRefThreadQueue_; diff --git a/kotlin-native/runtime/src/mm/cpp/ThreadRegistry.cpp b/kotlin-native/runtime/src/mm/cpp/ThreadRegistry.cpp index 55ed241d16f..7d7c9f2ce71 100644 --- a/kotlin-native/runtime/src/mm/cpp/ThreadRegistry.cpp +++ b/kotlin-native/runtime/src/mm/cpp/ThreadRegistry.cpp @@ -6,6 +6,7 @@ #include "ThreadRegistry.hpp" #include "GlobalData.hpp" +#include "Porting.h" #include "ThreadData.hpp" #include "ThreadState.hpp" @@ -17,7 +18,7 @@ mm::ThreadRegistry& mm::ThreadRegistry::Instance() noexcept { } mm::ThreadRegistry::Node* mm::ThreadRegistry::RegisterCurrentThread() noexcept { - auto* threadDataNode = list_.Emplace(pthread_self()); + auto* threadDataNode = list_.Emplace(konan::currentThreadId()); AssertThreadState(threadDataNode->Get(), ThreadState::kNative); Node*& currentDataNode = currentThreadDataNode_; RuntimeAssert(!IsCurrentThreadRegistered(), "This thread already had some data assigned to it."); diff --git a/kotlin-native/runtime/src/mm/cpp/ThreadRegistryTest.cpp b/kotlin-native/runtime/src/mm/cpp/ThreadRegistryTest.cpp index 711267e5e87..9d9a7da4867 100644 --- a/kotlin-native/runtime/src/mm/cpp/ThreadRegistryTest.cpp +++ b/kotlin-native/runtime/src/mm/cpp/ThreadRegistryTest.cpp @@ -24,7 +24,7 @@ TEST(ThreadRegistryTest, RegisterCurrentThread) { } registration; auto* threadData = registration.node->Get(); - EXPECT_EQ(pthread_self(), threadData->threadId()); + EXPECT_EQ(konan::currentThreadId(), threadData->threadId()); EXPECT_EQ(threadData, mm::ThreadRegistry::Instance().CurrentThreadData()); }); t.join(); diff --git a/kotlin-native/runtime/src/mm/cpp/ThreadStateTest.cpp b/kotlin-native/runtime/src/mm/cpp/ThreadStateTest.cpp index 91f35765835..bac4079833b 100644 --- a/kotlin-native/runtime/src/mm/cpp/ThreadStateTest.cpp +++ b/kotlin-native/runtime/src/mm/cpp/ThreadStateTest.cpp @@ -185,7 +185,7 @@ TEST(ThreadStateDeathTest, IncorrectStateSwitchWithDifferentFunctions) { } TEST(ThreadStateDeathTest, StateSwitchCorrectness) { - mm::ThreadData threadData(pthread_self()); + mm::ThreadData threadData(0); // Allowed state switches: runnable <-> native threadData.setState(ThreadState::kRunnable); @@ -233,4 +233,4 @@ TEST(ThreadStateDeathTest, MovingReentrantGuard) { testing::ExitedWithCode(0), testing::Not(testing::ContainsRegex("runtime assert: Illegal thread state switch."))); }); -} \ No newline at end of file +} diff --git a/kotlin-native/runtime/src/mm/cpp/ThreadSuspension.cpp b/kotlin-native/runtime/src/mm/cpp/ThreadSuspension.cpp index e3ef95ca275..a893ef579ff 100644 --- a/kotlin-native/runtime/src/mm/cpp/ThreadSuspension.cpp +++ b/kotlin-native/runtime/src/mm/cpp/ThreadSuspension.cpp @@ -10,6 +10,8 @@ #include #include +#include "Logging.hpp" + namespace { bool isSuspendedOrNative(kotlin::mm::ThreadData& thread) noexcept { @@ -54,8 +56,11 @@ NO_EXTERNAL_CALLS_CHECK bool kotlin::mm::ThreadSuspensionData::suspendIfRequeste NO_EXTERNAL_CALLS_CHECK bool kotlin::mm::ThreadSuspensionData::suspendIfRequestedSlowPath() noexcept { std::unique_lock lock(gSuspensionMutex); if (IsThreadSuspensionRequested()) { + auto threadId = konan::currentThreadId(); + RuntimeLogDebug({kTagGC, kTagMM}, "Suspending thread %d", threadId); AutoReset scopedAssign(&suspended_, true); gSuspendsionCondVar.wait(lock, []() { return !IsThreadSuspensionRequested(); }); + RuntimeLogDebug({kTagGC, kTagMM}, "Resuming thread %d", threadId); return true; } return false; diff --git a/kotlin-native/runtime/src/test_support/cpp/CompilerGenerated.cpp b/kotlin-native/runtime/src/test_support/cpp/CompilerGenerated.cpp index 21f0f92f8d5..b0956eb509a 100644 --- a/kotlin-native/runtime/src/test_support/cpp/CompilerGenerated.cpp +++ b/kotlin-native/runtime/src/test_support/cpp/CompilerGenerated.cpp @@ -60,6 +60,7 @@ extern "C" { extern const int32_t KonanNeedDebugInfo = 1; extern const int32_t Kotlin_runtimeAssertsMode = static_cast(kotlin::compiler::RuntimeAssertsMode::kPanic); +extern const char* const Kotlin_runtimeLogs = nullptr; extern const TypeInfo* theAnyTypeInfo = theAnyTypeInfoHolder.typeInfo(); extern const TypeInfo* theArrayTypeInfo = theArrayTypeInfoHolder.typeInfo();