[K/N] Make runtime logs enablement compile-time evaluatable

This commit is contained in:
Aleksei.Glushko
2023-10-16 20:41:10 +02:00
committed by Space Team
parent beeb016a9f
commit 2b2b8dd090
15 changed files with 321 additions and 308 deletions
@@ -118,7 +118,40 @@ class KonanConfig(val project: Project, val configuration: CompilerConfiguration
configuration.report(CompilerMessageSeverity.STRONG_WARNING, "Legacy exception handling in workers is deprecated")
}
} ?: WorkerExceptionHandling.USE_HOOK
val runtimeLogs: String? get() = configuration.get(KonanConfigKeys.RUNTIME_LOGS)
val runtimeLogsEnabled: Boolean by lazy {
configuration.get(KonanConfigKeys.RUNTIME_LOGS) != null
}
val runtimeLogs: Map<LoggingTag, LoggingLevel> by lazy {
val default = LoggingTag.entries.associateWith { LoggingLevel.None }
val cfgString = configuration.get(KonanConfigKeys.RUNTIME_LOGS) ?: return@lazy default
fun <T> error(message: String): T? {
configuration.report(CompilerMessageSeverity.STRONG_WARNING, "$message. No logging will be performed.")
return null
}
fun parseSingleTagLevel(tagLevel: String): Pair<LoggingTag, LoggingLevel>? {
val parts = tagLevel.split("=")
val tagStr = parts[0]
val tag = tagStr.let {
LoggingTag.parse(it) ?: error("Failed to parse log tag at \"$tagStr\"")
}
val levelStr = parts.getOrNull(1) ?: error("Failed to parse log tag-level pair at \"$tagLevel\"")
val level = parts.getOrNull(1)?.let {
LoggingLevel.parse(it) ?: error("Failed to parse log level at \"$levelStr\"")
}
if (level == LoggingLevel.None) return error("Invalid log level: \"$levelStr\"")
return tag?.let { t -> level?.let { l -> Pair(t, l) } }
}
val configured = cfgString.split(",").map { parseSingleTagLevel(it) ?: return@lazy default }
default + configured
}
val suspendFunctionsFromAnyThreadFromObjC: Boolean by lazy { configuration.get(BinaryOptions.objcExportSuspendFunctionLaunchThreadRestriction) == ObjCExportSuspendFunctionLaunchThreadRestriction.NONE }
val freezing: Freezing get() = configuration.get(BinaryOptions.freezing)?.also {
if (it != Freezing.Disabled) {
@@ -474,7 +507,7 @@ class KonanConfig(val project: Project, val configuration: CompilerConfiguration
internal val ignoreCacheReason = when {
optimizationsEnabled -> "for optimized compilation"
sanitizer != null -> "with sanitizers enabled"
runtimeLogs != null -> "with runtime logs"
runtimeLogsEnabled -> "with runtime logs"
else -> null
}
@@ -0,0 +1,38 @@
/*
* Copyright 2010-2023 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.
*/
package org.jetbrains.kotlin.backend.konan
// Must match `Level` in Logging.hpp
enum class LoggingLevel(val ord: Int) {
None(0), // marks disable logs, should not be used for other purposes
Error(1),
Warning(2),
Info(3),
Debug(4);
companion object {
fun parse(str: String) = LoggingLevel.entries.firstOrNull {
it.name.equals(str, ignoreCase = true)
}
}
}
// Must match `Tag` in Logging.hpp
enum class LoggingTag(val ord: Int) {
Logging(0),
RT(1),
GC(2),
MM(3),
TLS(4),
Pause(5),
Alloc(6),
Balancing(7);
companion object {
fun parse(str: String) = entries.firstOrNull {
it.name.equals(str, ignoreCase = true)
}
}
}
@@ -3039,9 +3039,10 @@ internal fun NativeGenerationState.generateRuntimeConstantsModule() : LLVMModule
setRuntimeConstGlobal("Kotlin_runtimeAssertsMode", llvm.constInt32(config.runtimeAssertsMode.value))
setRuntimeConstGlobal("Kotlin_disableMmap", llvm.constInt32(if (config.disableMmap) 1 else 0))
setRuntimeConstGlobal("Kotlin_disableAllocatorOverheadEstimate", llvm.constInt32(if (config.disableAllocatorOverheadEstimate) 1 else 0))
val runtimeLogs = config.runtimeLogs?.let {
static.cStringLiteral(it)
} ?: NullPointer(llvm.int8Type)
val runtimeLogs = ConstArray(llvm.int32Type, LoggingTag.entries.sortedBy { it.ord }.map {
config.runtimeLogs[it]!!.ord.let { llvm.constInt32(it) }
})
setRuntimeConstGlobal("Kotlin_runtimeLogs", runtimeLogs)
setRuntimeConstGlobal("Kotlin_freezingEnabled", llvm.constInt32(if (config.freezing.enableFreezeAtRuntime) 1 else 0))
setRuntimeConstGlobal("Kotlin_freezingChecksEnabled", llvm.constInt32(if (config.freezing.enableFreezeChecks) 1 else 0))
@@ -831,6 +831,31 @@ standaloneTest("cleaner_in_tls_worker") {
flags = ['-opt-in=kotlin.native.internal.InternalForKotlinNative']
}
standaloneTest('logging') {
outputChecker = { out ->
out.toLowerCase().contains("[logging]") && // loging reports configured log levels on info level
out.toLowerCase().contains("logging = debug") &&
out.toLowerCase().contains("gc = info") &&
out.toLowerCase().contains("mm = warning") &&
out.toLowerCase().contains("tls = error") &&
out.toLowerCase().contains("[gc]") // gc reports initialization on info level
}
source = "runtime/basic/logging.kt"
flags = ['-Xruntime-logs=gc=info,mm=warning,tls=error,logging=debug']
}
standaloneTest('logging_invalid') {
outputChecker = { it.isEmpty() }
source = "runtime/basic/logging.kt"
flags = ['-Xruntime-logs=invalid=unknown,logging=debug']
}
standaloneTest('logging_override') {
outputChecker = { it.isEmpty() }
source = "runtime/basic/logging.kt"
flags = ['-Xruntime-logs=logging=info,logging=debug,logging=none']
}
standaloneTest("worker_bound_reference0") {
source = "runtime/concurrent/worker_bound_reference0.kt"
flags = ['-tr']
@@ -0,0 +1,6 @@
/*
* Copyright 2010-2023 JetBrains s.r.o. and Kotlin Programming Language contributors.
* Use of this source code is governed by the Apache 2.0 license that can be found in the license/LICENSE.txt file.
*/
fun main() {}
@@ -8,9 +8,9 @@
#include "Logging.hpp"
#define CustomAllocInfo(format, ...) RuntimeLogInfo({"alloc"}, format, ##__VA_ARGS__)
#define CustomAllocDebug(format, ...) RuntimeLogDebug({"alloc"}, format, ##__VA_ARGS__)
#define CustomAllocWarning(format, ...) RuntimeLogWarning({"alloc"}, format, ##__VA_ARGS__)
#define CustomAllocError(format, ...) RuntimeLogError({"alloc"}, format, ##__VA_ARGS__)
#define CustomAllocInfo(format, ...) RuntimeLogInfo({kotlin::logging::Tag::kAlloc}, format, ##__VA_ARGS__)
#define CustomAllocDebug(format, ...) RuntimeLogDebug({kotlin::logging::Tag::kAlloc}, format, ##__VA_ARGS__)
#define CustomAllocWarning(format, ...) RuntimeLogWarning({kotlin::logging::Tag::kAlloc}, format, ##__VA_ARGS__)
#define CustomAllocError(format, ...) RuntimeLogError({kotlin::logging::Tag::kAlloc}, format, ##__VA_ARGS__)
#endif
@@ -26,7 +26,7 @@ extern "C" const int32_t Kotlin_needDebugInfo;
extern "C" const int32_t Kotlin_runtimeAssertsMode;
extern "C" const int32_t Kotlin_disableMmap;
extern "C" const int32_t Kotlin_disableAllocatorOverheadEstimate;
extern "C" const char* const Kotlin_runtimeLogs;
extern "C" const int32_t Kotlin_runtimeLogs[];
extern "C" const int32_t Kotlin_concurrentWeakSweep;
extern "C" const int32_t Kotlin_gcMarkSingleThreaded;
extern "C" const int32_t Kotlin_freezingEnabled;
@@ -82,8 +82,8 @@ ALWAYS_INLINE inline bool disableAllocatorOverheadEstimate() noexcept {
return Kotlin_disableAllocatorOverheadEstimate != 0;
}
ALWAYS_INLINE inline std::string_view runtimeLogs() noexcept {
return Kotlin_runtimeLogs == nullptr ? std::string_view() : std::string_view(Kotlin_runtimeLogs);
ALWAYS_INLINE inline const int32_t* runtimeLogs() noexcept {
return Kotlin_runtimeLogs;
}
ALWAYS_INLINE inline bool freezingEnabled() noexcept {
+35 -115
View File
@@ -20,115 +20,23 @@ using namespace kotlin;
namespace {
template <typename T>
struct ParseResult {
std::optional<T> value;
std::string_view rest;
};
ParseResult<std::string_view> 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<std::string_view> 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<logging::Level> 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;
}
std::map<std::string, logging::Level> ParseTagsFilter(std::string_view tagsFilter) noexcept {
if (tagsFilter.empty()) return {};
std::map<std::string, logging::Level> 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(std::string(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<const char* const> 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.
std::map<std::string, logging::Level> tagLevelMap_;
};
class StderrLogger : public logging::internal::Logger {
public:
void Log(logging::Level level, std_support::span<const char* const> tags, std::string_view message) const noexcept override {
void Log(logging::Level level, std_support::span<const logging::Tag> tags, std::string_view message) const noexcept override {
konan::consoleErrorUtf8(message.data(), message.size());
}
};
std_support::span<char> FormatLevel(std_support::span<char> 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]");
}
return FormatToSpan(buffer, "[%s]", logging::internal::name(level));
}
std_support::span<char> FormatTags(std_support::span<char> buffer, std_support::span<const char* const> tags) noexcept {
std_support::span<char> FormatTags(std_support::span<char> buffer, std_support::span<const logging::Tag> tags) noexcept {
// `tags` cannot be empty.
auto firstTag = tags.front();
buffer = FormatToSpan(buffer, "[%s", firstTag);
buffer = FormatToSpan(buffer, "[%s", logging::internal::name(firstTag));
for (auto tag : tags.subspan(1)) {
buffer = FormatToSpan(buffer, ",%s", tag);
buffer = FormatToSpan(buffer, ",%s", logging::internal::name(tag));
}
return FormatToSpan(buffer, "]");
}
@@ -143,20 +51,12 @@ std_support::span<char> FormatThread(std_support::span<char> buffer, int threadI
}
struct DefaultLogContext {
::LogFilter logFilter;
StderrLogger logger;
kotlin::steady_clock::time_point initialTimestamp;
explicit DefaultLogContext(std::string_view tagsFilter) noexcept :
logFilter(tagsFilter), initialTimestamp(kotlin::steady_clock::now()) {}
kotlin::steady_clock::time_point initialTimestamp = kotlin::steady_clock::now();
};
} // namespace
std::unique_ptr<logging::internal::LogFilter> logging::internal::CreateLogFilter(std::string_view tagsFilter) noexcept {
return std::make_unique<::LogFilter>(tagsFilter);
}
std::unique_ptr<logging::internal::Logger> logging::internal::CreateStderrLogger() noexcept {
return std::make_unique<StderrLogger>();
}
@@ -164,7 +64,7 @@ std::unique_ptr<logging::internal::Logger> logging::internal::CreateStderrLogger
std_support::span<char> logging::internal::FormatLogEntry(
std_support::span<char> buffer,
logging::Level level,
std_support::span<const char* const> tags,
std_support::span<const logging::Tag> tags,
int threadId,
kotlin::nanoseconds timestamp,
const char* format,
@@ -182,35 +82,55 @@ std_support::span<char> logging::internal::FormatLogEntry(
}
void logging::internal::Log(
const LogFilter& logFilter,
const Logger& logger,
Level level,
std_support::span<const char* const> tags,
std_support::span<const logging::Tag> tags,
int threadId,
kotlin::nanoseconds timestamp,
const char* format,
std::va_list args) noexcept {
if (!logFilter.Enabled(level, tags)) return;
RuntimeAssert(enabled(level, tags, compiler::runtimeLogs()), "Caller must ensure that the logging requested is enabled");
// TODO: This might be suboptimal.
std::array<char, 1024> logEntry;
auto rest = FormatLogEntry(logEntry, level, tags, threadId, timestamp, format, args);
logger.Log(level, tags, std::string_view(logEntry.data(), rest.data() - logEntry.data()));
}
void logging::Log(Level level, std::initializer_list<const char*> tags, const char* format, ...) noexcept {
void logging::OnRuntimeInit() noexcept {
if (internal::enabled(Level::kInfo, {Tag::kLogging})) {
std::array<char, 1024> buf;
std_support::span<char> span = buf;
bool printedFirstTag = false;
for (size_t tagOrd = 0; tagOrd < static_cast<std::size_t>(Tag::kEnumSize); ++tagOrd) {
auto tag = static_cast<Tag>(tagOrd);
auto maxLevel = internal::maxLevel(tag, compiler::runtimeLogs());
if (maxLevel > Level::kNone) {
if (printedFirstTag) {
span = FormatToSpan(span, ", ");
}
printedFirstTag = true;
span = FormatToSpan(span, "%s = %s", internal::name(tag), internal::name(maxLevel));
}
}
RuntimeAssert(printedFirstTag, "At least logging=info must be enabled and printed");
Log(Level::kInfo, {logging::Tag::kLogging}, "Logging enabled for: %s", buf.data());
}
}
void logging::Log(Level level, std::initializer_list<logging::Tag> 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<const char*> tags, const char* format, std::va_list args) noexcept {
void logging::VLog(Level level, std::initializer_list<logging::Tag> tags, const char* format, std::va_list args) noexcept {
CallsCheckerIgnoreGuard guard;
[[clang::no_destroy]] static DefaultLogContext ctx(compiler::runtimeLogs());
[[clang::no_destroy]] static DefaultLogContext ctx;
RuntimeAssert(tags.size() > 0, "Cannot Log without tags");
std_support::span<const char* const> tagsSpan(std::data(tags), std::size(tags));
std_support::span<const logging::Tag> tagsSpan(std::data(tags), std::size(tags));
auto threadId = konan::currentThreadId();
auto timestamp = kotlin::steady_clock::now();
internal::Log(ctx.logFilter, ctx.logger, level, tagsSpan, threadId, timestamp - ctx.initialTimestamp, format, args);
internal::Log(ctx.logger, level, tagsSpan, threadId, timestamp - ctx.initialTimestamp, format, args);
}
+76 -25
View File
@@ -18,30 +18,80 @@
namespace kotlin {
namespace logging {
enum class Level {
kDebug,
kInfo,
kWarning,
kError,
// Must match LoggingLevel in RuntimeLogging.kt
enum class Level : int32_t {
kNone = 0,
kError = 1,
kWarning = 2,
kInfo = 3,
kDebug = 4,
};
// Must match LoggingTag in RuntimeLogging.kt
enum class Tag : int32_t {
kLogging = 0,
kRT = 1,
kGC = 2,
kMM = 3,
kTLS = 4,
kPause = 5,
kAlloc = 6,
kBalancing = 7,
kEnumSize = 8
};
namespace internal {
class LogFilter {
public:
virtual ~LogFilter() = default;
inline const char* name(Level level) {
switch (level) {
case Level::kNone: return "NONE";
case Level::kError: return "ERROR";
case Level::kWarning: return "WARNING";
case Level::kInfo: return "INFO";
case Level::kDebug: return "DEBUG";
}
}
virtual bool Empty() const noexcept = 0;
virtual bool Enabled(Level level, std_support::span<const char* const> tags) const noexcept = 0;
};
inline const char* name(Tag tag) {
switch (tag) {
case Tag::kLogging: return "logging";
case Tag::kRT: return "rt";
case Tag::kGC: return "gc";
case Tag::kMM: return "mm";
case Tag::kTLS: return "tls";
case Tag::kPause: return "pause";
case Tag::kAlloc: return "alloc";
case Tag::kBalancing: return "balancing";
std::unique_ptr<LogFilter> CreateLogFilter(std::string_view tagsFilter) noexcept;
case Tag::kEnumSize: break;
}
RuntimeFail("Unexpected logging tag %d", tag);
}
ALWAYS_INLINE inline Level maxLevel(Tag tag, const int32_t logLevels[]) {
return static_cast<logging::Level>(logLevels[static_cast<int>(tag)]);
}
ALWAYS_INLINE inline bool enabled(logging::Level level, std_support::span<const logging::Tag> tags, const int32_t logLevels[]) {
for (auto tag: tags) {
if (level <= maxLevel(tag, logLevels)) {
return true;
}
}
return false;
}
ALWAYS_INLINE inline bool enabled(logging::Level level, std::initializer_list<const logging::Tag> tags) noexcept {
std_support::span<const logging::Tag> tagsSpan(std::data(tags), std::size(tags));
return enabled(level, tagsSpan, compiler::runtimeLogs());
}
class Logger {
public:
virtual ~Logger() = default;
virtual void Log(Level level, std_support::span<const char* const> tags, std::string_view message) const noexcept = 0;
virtual void Log(Level level, std_support::span<const Tag> tags, std::string_view message) const noexcept = 0;
};
std::unique_ptr<Logger> CreateStderrLogger() noexcept;
@@ -49,17 +99,16 @@ std::unique_ptr<Logger> CreateStderrLogger() noexcept;
std_support::span<char> FormatLogEntry(
std_support::span<char> buffer,
Level level,
std_support::span<const char* const> tags,
std_support::span<const Tag> tags,
int threadId,
kotlin::nanoseconds timestamp,
const char* format,
std::va_list args) noexcept;
void Log(
const LogFilter& logFilter,
const Logger& logger,
Level level,
std_support::span<const char* const> tags,
std_support::span<const Tag> tags,
int threadId,
kotlin::nanoseconds timestamp,
const char* format,
@@ -67,18 +116,20 @@ void Log(
} // namespace internal
__attribute__((format(printf, 3, 4))) void Log(Level level, std::initializer_list<const char*> tags, const char* format, ...) noexcept;
void VLog(Level level, std::initializer_list<const char*> tags, const char* format, std::va_list args) noexcept;
void OnRuntimeInit() noexcept;
__attribute__((format(printf, 3, 4)))
void Log(Level level, std::initializer_list<Tag> tags, const char* format, ...) noexcept;
void VLog(Level level, std::initializer_list<Tag> 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";
inline constexpr const char* kTagTLS = "tls";
inline constexpr const char* kTagPause = "pause";
inline constexpr auto kTagGC = logging::Tag::kGC;
inline constexpr auto kTagMM = logging::Tag::kMM;
inline constexpr auto kTagTLS = logging::Tag::kTLS;
inline constexpr auto kTagBalancing = logging::Tag::kBalancing;
} // namespace kotlin
@@ -89,14 +140,14 @@ inline constexpr const char* kTagPause = "pause";
#define RuntimeLog(level, tags, format, ...) \
do { \
if (!::kotlin::compiler::runtimeLogs().empty()) { \
if (::kotlin::logging::internal::enabled(level, tags)) { \
::kotlin::logging::Log(level, tags, format, ##__VA_ARGS__); \
} \
} while (false)
#define RuntimeVLog(level, tags, format, args) \
do { \
if (!::kotlin::compiler::runtimeLogs().empty()) { \
if (::kotlin::logging::internal::enabled(level, tags)) { \
::kotlin::logging::VLog(level, tags, format, args); \
} \
} while (false)
@@ -19,12 +19,12 @@ namespace {
std_support::span<char> FormatLogEntry(
std_support::span<char> buffer,
logging::Level level,
std::initializer_list<const char*> tags,
std::initializer_list<logging::Tag> tags,
int threadId,
kotlin::nanoseconds timestamp,
const char* format,
...) {
std_support::span<const char* const> tagsSpan(std::data(tags), std::size(tags));
std_support::span<const logging::Tag> tagsSpan(std::data(tags), std::size(tags));
std::va_list args;
va_start(args, format);
auto result = logging::internal::FormatLogEntry(buffer, level, tagsSpan, threadId, timestamp, format, args);
@@ -32,87 +32,61 @@ std_support::span<char> FormatLogEntry(
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<const char*> tags) const {
std_support::span<const char* const> tagsSpan(std::data(tags), std::size(tags));
return logFilter_->Enabled(level, tagsSpan);
}
private:
std::unique_ptr<logging::internal::LogFilter> 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 char* const>), (const, noexcept, override));
};
class MockLogger : public logging::internal::Logger {
public:
MOCK_METHOD(void, Log, (logging::Level, std_support::span<const char* const>, std::string_view), (const, noexcept, override));
};
} // namespace
TEST(LoggingTest, FormatLogEntry_Debug_OneTag) {
std::array<char, 1024> buffer;
FormatLogEntry(buffer, logging::Level::kDebug, {"t1"}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[DEBUG][t1][tid#123][42.500s] Log #42\n"));
FormatLogEntry(buffer, logging::Level::kDebug, {logging::Tag::kRT}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[DEBUG][rt][tid#123][42.500s] Log #42\n"));
}
TEST(LoggingTest, FormatLogEntry_Debug_TwoTags) {
std::array<char, 1024> buffer;
FormatLogEntry(buffer, logging::Level::kDebug, {"t1", "t2"}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[DEBUG][t1,t2][tid#123][42.500s] Log #42\n"));
FormatLogEntry(buffer, logging::Level::kDebug, {logging::Tag::kRT, logging::Tag::kGC}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[DEBUG][rt,gc][tid#123][42.500s] Log #42\n"));
}
TEST(LoggingTest, FormatLogEntry_Info_OneTag) {
std::array<char, 1024> buffer;
FormatLogEntry(buffer, logging::Level::kInfo, {"t1"}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[INFO][t1][tid#123][42.500s] Log #42\n"));
FormatLogEntry(buffer, logging::Level::kInfo, {logging::Tag::kRT}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[INFO][rt][tid#123][42.500s] Log #42\n"));
}
TEST(LoggingTest, FormatLogEntry_Info_TwoTags) {
std::array<char, 1024> buffer;
FormatLogEntry(buffer, logging::Level::kInfo, {"t1", "t2"}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[INFO][t1,t2][tid#123][42.500s] Log #42\n"));
FormatLogEntry(buffer, logging::Level::kInfo, {logging::Tag::kRT, logging::Tag::kGC}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[INFO][rt,gc][tid#123][42.500s] Log #42\n"));
}
TEST(LoggingTest, FormatLogEntry_Warning_OneTag) {
std::array<char, 1024> buffer;
FormatLogEntry(buffer, logging::Level::kWarning, {"t1"}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[WARN][t1][tid#123][42.500s] Log #42\n"));
FormatLogEntry(buffer, logging::Level::kWarning, {logging::Tag::kRT}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[WARNING][rt][tid#123][42.500s] Log #42\n"));
}
TEST(LoggingTest, FormatLogEntry_Warning_TwoTags) {
std::array<char, 1024> buffer;
FormatLogEntry(buffer, logging::Level::kWarning, {"t1", "t2"}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[WARN][t1,t2][tid#123][42.500s] Log #42\n"));
FormatLogEntry(buffer, logging::Level::kWarning, {logging::Tag::kRT, logging::Tag::kGC}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[WARNING][rt,gc][tid#123][42.500s] Log #42\n"));
}
TEST(LoggingTest, FormatLogEntry_Error_OneTag) {
std::array<char, 1024> buffer;
FormatLogEntry(buffer, logging::Level::kError, {"t1"}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1][tid#123][42.500s] Log #42\n"));
FormatLogEntry(buffer, logging::Level::kError, {logging::Tag::kRT}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][rt][tid#123][42.500s] Log #42\n"));
}
TEST(LoggingTest, FormatLogEntry_Error_TwoTags) {
std::array<char, 1024> buffer;
FormatLogEntry(buffer, logging::Level::kError, {"t1", "t2"}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1,t2][tid#123][42.500s] Log #42\n"));
FormatLogEntry(buffer, logging::Level::kError, {logging::Tag::kRT, logging::Tag::kGC}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][rt,gc][tid#123][42.500s] Log #42\n"));
}
TEST(LoggingTest, FormatLogEntry_Overflow) {
std::array<char, 20> buffer;
FormatLogEntry(buffer, logging::Level::kError, {"t1", "t2"}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
FormatLogEntry(buffer, logging::Level::kError, {logging::Tag::kRT, logging::Tag::kGC}, 123, kotlin::nanoseconds(42'500'000'000), "Log #%d", 42);
// Only 18 characters are used for the log string contents, another 2 are \n and \0.
EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1,t2][tid\n"));
EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][rt,gc][tid\n"));
}
TEST(LoggingDeathTest, StderrLogger) {
@@ -125,118 +99,80 @@ TEST(LoggingDeathTest, StderrLogger) {
"Message for the log");
}
TEST(LoggingTest, LogFilter_Empty) {
LogFilter filter("");
EXPECT_TRUE(filter.Empty());
namespace {
class LogFilter {
public:
explicit LogFilter(std::map<logging::Tag, logging::Level> tagToLevel) {
logLevels_.resize(static_cast<size_t>(logging::Tag::kEnumSize));
for (auto [tag, level] : tagToLevel) {
logLevels_[static_cast<size_t>(tag)] = static_cast<int32_t>(level);
}
}
bool Empty() const {
return std::all_of(logLevels_.begin(), logLevels_.end(), [](int32_t levelOrd){
return static_cast<logging::Level>(levelOrd) == logging::Level::kNone;
});
}
bool Enabled(logging::Level level, std::initializer_list<logging::Tag> tags) const {
std_support::span<const logging::Tag> tagsSpan(std::data(tags), std::size(tags));
return logging::internal::enabled(level, tagsSpan, logLevels_.data());
}
private:
std::vector<int32_t> logLevels_;
};
}
TEST(LoggingTest, LogFilter_EnableOne) {
LogFilter filter("t1=info");
LogFilter filter({{logging::Tag::kRT, logging::Level::kInfo}});
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, {logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kError, {logging::Tag::kRT}));
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, {logging::Tag::kGC}));
EXPECT_FALSE(filter.Enabled(logging::Level::kInfo, {logging::Tag::kGC}));
EXPECT_FALSE(filter.Enabled(logging::Level::kWarning, {logging::Tag::kGC}));
EXPECT_FALSE(filter.Enabled(logging::Level::kError, {logging::Tag::kGC}));
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, {logging::Tag::kRT, logging::Tag::kGC}));
EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {logging::Tag::kRT, logging::Tag::kGC}));
EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {logging::Tag::kRT, logging::Tag::kGC}));
EXPECT_TRUE(filter.Enabled(logging::Level::kError, {logging::Tag::kRT, logging::Tag::kGC}));
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"}));
EXPECT_FALSE(filter.Enabled(logging::Level::kDebug, {logging::Tag::kGC, logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {logging::Tag::kGC, logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {logging::Tag::kGC, logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kError, {logging::Tag::kGC, logging::Tag::kRT}));
}
TEST(LoggingTest, LogFilter_EnableTwo) {
LogFilter filter("t1=info,t2=warning");
LogFilter filter({{logging::Tag::kRT, logging::Level::kInfo}, {logging::Tag::kGC, logging::Level::kWarning}});
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, {logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kError, {logging::Tag::kRT}));
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, {logging::Tag::kGC}));
EXPECT_FALSE(filter.Enabled(logging::Level::kInfo, {logging::Tag::kGC}));
EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {logging::Tag::kGC}));
EXPECT_TRUE(filter.Enabled(logging::Level::kError, {logging::Tag::kGC}));
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, {logging::Tag::kRT, logging::Tag::kGC}));
EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {logging::Tag::kRT, logging::Tag::kGC}));
EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {logging::Tag::kRT, logging::Tag::kGC}));
EXPECT_TRUE(filter.Enabled(logging::Level::kError, {logging::Tag::kRT, logging::Tag::kGC}));
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<const char*> tags,
int threadId,
kotlin::nanoseconds timestamp,
const char* format,
...) {
std::va_list args;
va_start(args, format);
logging::internal::Log(
logFilter_, logger_, level, std_support::span<const char* const>(std::data(tags), std::size(tags)), threadId, timestamp,
format, args);
va_end(args);
}
MockLogFilter& logFilter() { return logFilter_; }
MockLogger& logger() { return logger_; }
private:
testing::StrictMock<MockLogFilter> logFilter_;
testing::StrictMock<MockLogger> logger_;
};
MATCHER_P(TagsAre, tags, "") {
std::vector<std::string_view> 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<const char*> tags = {"t1", "t2"};
EXPECT_CALL(logFilter(), Enabled(level, TagsAre(tags))).WillOnce(testing::Return(false));
Log(level, tags, 123, kotlin::nanoseconds(42'500'000'000), "Message %d", 42);
}
TEST_F(LoggingLogTest, Log_Success) {
constexpr auto level = logging::Level::kInfo;
const std::initializer_list<const char*> tags = {"t1", "t2"};
EXPECT_CALL(logFilter(), Enabled(level, TagsAre(tags))).WillOnce(testing::Return(true));
EXPECT_CALL(logger(), Log(level, TagsAre(tags), "[INFO][t1,t2][tid#123][42.500s] Message 42\n"));
Log(level, tags, 123, kotlin::nanoseconds(42'500'000'000), "Message %d", 42);
EXPECT_FALSE(filter.Enabled(logging::Level::kDebug, {logging::Tag::kGC, logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kInfo, {logging::Tag::kGC, logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kWarning, {logging::Tag::kGC, logging::Tag::kRT}));
EXPECT_TRUE(filter.Enabled(logging::Level::kError, {logging::Tag::kGC, logging::Tag::kRT}));
}
@@ -77,7 +77,7 @@ public:
public:
explicit Worker(ParallelProcessor& dispatcher) : dispatcher_(dispatcher) {
dispatcher_.registeredWorkers_.fetch_add(1, std::memory_order_relaxed);
RuntimeLogDebug({ "balancing" }, "Worker registered");
RuntimeLogDebug({ kTagBalancing }, "Worker registered");
}
ALWAYS_INLINE bool localEmpty() const noexcept {
@@ -96,7 +96,7 @@ public:
if (batch_.full()) {
bool released = dispatcher_.releaseBatch(std::move(batch_));
if (!released) {
RuntimeLogDebug({ "balancing" }, "Batches pool overflow");
RuntimeLogDebug({ kTagBalancing }, "Batches pool overflow");
batch_.transferAllInto(overflowList_);
}
batch_ = Batch{};
@@ -111,7 +111,7 @@ public:
if (!acquired) {
if (!overflowList_.empty()) {
batch_.fillFrom(overflowList_);
RuntimeLogDebug({ "balancing" }, "Acquired %zu elements from the overflow list", batch_.elementsCount());
RuntimeLogDebug({ kTagBalancing }, "Acquired %zu elements from the overflow list", batch_.elementsCount());
} else {
bool newWorkAvailable = waitForMoreWork();
if (newWorkAvailable) continue;
@@ -134,7 +134,7 @@ public:
std::unique_lock lock(dispatcher_.waitMutex_);
auto nowWaiting = dispatcher_.waitingWorkers_.fetch_add(1, std::memory_order_relaxed) + 1;
RuntimeLogDebug({ "balancing" }, "Worker goes to sleep (now sleeping %zu of %zu)",
RuntimeLogDebug({ kTagBalancing }, "Worker goes to sleep (now sleeping %zu of %zu)",
nowWaiting, dispatcher_.registeredWorkers_.load(std::memory_order_relaxed));
if (dispatcher_.allDone_) {
@@ -144,7 +144,7 @@ public:
if (nowWaiting == dispatcher_.registeredWorkers_.load(std::memory_order_relaxed)) {
// we are the last ones awake
RuntimeLogDebug({ "balancing" }, "Worker has detected termination");
RuntimeLogDebug({ kTagBalancing }, "Worker has detected termination");
dispatcher_.allDone_ = true;
lock.unlock();
dispatcher_.waitCV_.notify_all();
@@ -157,7 +157,7 @@ public:
if (dispatcher_.allDone_) {
return false;
}
RuntimeLogDebug({ "balancing" }, "Worker woke up");
RuntimeLogDebug({ kTagBalancing }, "Worker woke up");
return true;
}
@@ -181,7 +181,7 @@ public:
private:
bool releaseBatch(Batch&& batch) {
RuntimeAssert(!batch.empty(), "A batch to release into shared pool must be non-empty");
RuntimeLogDebug({ "balancing" }, "Releasing batch of %zu elements", batch.elementsCount());
RuntimeLogDebug({ kTagBalancing }, "Releasing batch of %zu elements", batch.elementsCount());
bool shared = sharedBatches_.enqueue(std::move(batch));
if (shared) {
if (waitingWorkers_.load(std::memory_order_relaxed) > 0) {
@@ -196,7 +196,7 @@ private:
auto acquired = sharedBatches_.dequeue();
if (acquired) {
dst = std::move(*acquired);
RuntimeLogDebug({ "balancing" }, "Acquired a batch of %zu elements", dst.elementsCount());
RuntimeLogDebug({ kTagBalancing }, "Acquired a batch of %zu elements", dst.elementsCount());
return true;
}
return false;
@@ -10,6 +10,7 @@
#include "KAssert.h"
#include "MainQueueProcessor.hpp"
#include "Memory.h"
#include "Logging.hpp"
#include "ObjCExportInit.h"
#include "Porting.h"
#include "Runtime.h"
@@ -139,6 +140,7 @@ RuntimeState* initRuntime() {
Kotlin_ObjCExport_initialize();
#endif
InitOrDeinitGlobalVariables(INIT_GLOBALS, result->memoryState);
logging::OnRuntimeInit();
}
InitOrDeinitGlobalVariables(INIT_THREAD_LOCAL_GLOBALS, result->memoryState);
RuntimeAssert(result->status == RuntimeStatus::kUninitialized, "Runtime must still be in the uninitialized state");
@@ -22,7 +22,7 @@ void internal::setCurrentThreadName(std::string_view name) noexcept {
// TODO: On Linux the maximum thread name is 16 characters. Handle automatically?
int result = pthread_setname_np(pthread_self(), name.data());
if (result != 0) {
RuntimeLogWarning({"rt"}, "Failed to set thread name: %s", std::strerror(result));
RuntimeLogWarning({logging::Tag::kRT}, "Failed to set thread name: %s", std::strerror(result));
}
#endif
}
@@ -31,7 +31,7 @@ ALWAYS_INLINE mm::ThreadSuspensionData::MutatorPauseHandle::MutatorPauseHandle(c
auto prevState = threadData_.suspensionData().setStateNoSafePoint(ThreadState::kNative);
// no special reason, fill free to implement pause from native if needed
RuntimeAssert(prevState == ThreadState::kRunnable, "Expected runnable state");
RuntimeLogDebug({kTagPause}, "Suspending mutation (%s)", reason_);
RuntimeLogDebug({logging::Tag::kPause}, "Suspending mutation (%s)", reason_);
}
ALWAYS_INLINE mm::ThreadSuspensionData::MutatorPauseHandle::~MutatorPauseHandle() noexcept {
@@ -43,7 +43,7 @@ ALWAYS_INLINE void mm::ThreadSuspensionData::MutatorPauseHandle::resume() noexce
auto prevState = threadData_.suspensionData().setStateNoSafePoint(ThreadState::kRunnable);
RuntimeAssert(prevState == ThreadState::kNative, "Expected native state");
auto pauseTimeMicros = konan::getTimeMicros() - pauseStartTimeMicros_;
RuntimeLogInfo({kTagPause}, "Resuming mutation after %" PRIu64 " microseconds of suspension (%s)", pauseTimeMicros, reason_);
RuntimeLogInfo({logging::Tag::kPause}, "Resuming mutation after %" PRIu64 " microseconds of suspension (%s)", pauseTimeMicros, reason_);
resumed = true;
}
@@ -5,6 +5,7 @@
#include "TestSupportCompilerGenerated.hpp"
#include "Logging.hpp"
#include "ObjectTestSupport.hpp"
#include "Types.h"
@@ -74,7 +75,7 @@ extern const int32_t Kotlin_disableMmap = 1;
extern const int32_t Kotlin_disableMmap = 0;
#endif
extern const int32_t Kotlin_disableAllocatorOverheadEstimate = 0;
extern const char* const Kotlin_runtimeLogs = nullptr;
extern const int32_t Kotlin_runtimeLogs[static_cast<size_t>(kotlin::logging::Tag::kEnumSize)] = {0};
extern const int32_t Kotlin_concurrentWeakSweep = 1;
#if KONAN_WINDOWS
// parallel mark tests hang on mingw due to (presumably) a bug in winpthread