diff --git a/kotlin-native/runtime/src/main/cpp/Logging.cpp b/kotlin-native/runtime/src/main/cpp/Logging.cpp index 0818954b3d0..72f06abb97f 100644 --- a/kotlin-native/runtime/src/main/cpp/Logging.cpp +++ b/kotlin-native/runtime/src/main/cpp/Logging.cpp @@ -6,8 +6,7 @@ #include "Logging.hpp" #include - - +#include #include "Format.h" #include "KAssert.h" @@ -133,6 +132,24 @@ std_support::span FormatTags(std_support::span buffer, std_support:: return FormatToSpan(buffer, "]"); } +std_support::span FormatTimestamp(std_support::span buffer, kotlin::nanoseconds timestamp) noexcept { + auto s = static_cast(timestamp.count().value) / 1'000'000'000; + return FormatToSpan(buffer, "[%.3fs]", s); +} + +std_support::span FormatThread(std_support::span buffer, int threadId) noexcept { + return FormatToSpan(buffer, "[tid#%d]", threadId); +} + +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()) {} +}; + } // namespace std_support::unique_ptr logging::internal::CreateLogFilter(std::string_view tagsFilter) noexcept { @@ -147,11 +164,15 @@ std_support::span logging::internal::FormatLogEntry( std_support::span buffer, logging::Level level, std_support::span tags, + int threadId, + kotlin::nanoseconds timestamp, const char* format, std::va_list args) noexcept { auto subbuffer = buffer.subspan(0, buffer.size() - 1); subbuffer = FormatLevel(subbuffer, level); subbuffer = FormatTags(subbuffer, tags); + subbuffer = FormatThread(subbuffer, threadId); + subbuffer = FormatTimestamp(subbuffer, timestamp); subbuffer = FormatToSpan(subbuffer, " "); subbuffer = VFormatToSpan(subbuffer, format, args); buffer = buffer.subspan(subbuffer.data() - buffer.data()); @@ -164,12 +185,14 @@ void logging::internal::Log( const Logger& logger, Level level, std_support::span tags, + int threadId, + kotlin::nanoseconds timestamp, 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); + auto rest = FormatLogEntry(logEntry, level, tags, threadId, timestamp, format, args); logger.Log(level, tags, std::string_view(logEntry.data(), rest.data() - logEntry.data())); } @@ -181,9 +204,10 @@ void logging::Log(Level level, std::initializer_list tags, const ch } void logging::VLog(Level level, std::initializer_list tags, const char* format, std::va_list args) noexcept { - [[clang::no_destroy]] static auto logFilter = internal::CreateLogFilter(compiler::runtimeLogs()); - [[clang::no_destroy]] static auto logger = internal::CreateStderrLogger(); + [[clang::no_destroy]] static DefaultLogContext ctx(compiler::runtimeLogs()); 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); + auto threadId = konan::currentThreadId(); + auto timestamp = kotlin::steady_clock::now(); + internal::Log(ctx.logFilter, ctx.logger, level, tagsSpan, threadId, timestamp - ctx.initialTimestamp, format, args); } diff --git a/kotlin-native/runtime/src/main/cpp/Logging.hpp b/kotlin-native/runtime/src/main/cpp/Logging.hpp index df0183eb90d..abcb1b2fcc6 100644 --- a/kotlin-native/runtime/src/main/cpp/Logging.hpp +++ b/kotlin-native/runtime/src/main/cpp/Logging.hpp @@ -21,6 +21,7 @@ using string_view = std::experimental::string_view; #error "No " #endif +#include "Clock.hpp" #include "CompilerConstants.hpp" #include "std_support/Memory.hpp" #include "std_support/Span.hpp" @@ -60,6 +61,8 @@ std_support::span FormatLogEntry( std_support::span buffer, Level level, std_support::span tags, + int threadId, + kotlin::nanoseconds timestamp, const char* format, std::va_list args) noexcept; @@ -68,6 +71,8 @@ void Log( const Logger& logger, Level level, std_support::span tags, + int threadId, + kotlin::nanoseconds timestamp, const char* format, std::va_list args) noexcept; diff --git a/kotlin-native/runtime/src/main/cpp/LoggingTest.cpp b/kotlin-native/runtime/src/main/cpp/LoggingTest.cpp index 550635d0293..af7a45fe523 100644 --- a/kotlin-native/runtime/src/main/cpp/LoggingTest.cpp +++ b/kotlin-native/runtime/src/main/cpp/LoggingTest.cpp @@ -17,11 +17,17 @@ using ::testing::_; namespace { std_support::span FormatLogEntry( - std_support::span buffer, logging::Level level, std::initializer_list tags, const char* format, ...) { + std_support::span buffer, + logging::Level level, + std::initializer_list tags, + int threadId, + kotlin::nanoseconds timestamp, + 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); + auto result = logging::internal::FormatLogEntry(buffer, level, tagsSpan, threadId, timestamp, format, args); va_end(args); return result; } @@ -56,57 +62,57 @@ public: 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\n")); + 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")); } 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\n")); + 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")); } 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\n")); + 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")); } 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\n")); + 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")); } 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\n")); + 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")); } 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\n")); + 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")); } 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\n")); + 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")); } 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\n")); + 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")); } TEST(LoggingTest, FormatLogEntry_Overflow) { std::array buffer; - FormatLogEntry(buffer, logging::Level::kError, {"t1", "t2"}, "Log #%d", 42); + FormatLogEntry(buffer, logging::Level::kError, {"t1", "t2"}, 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] Log\n")); + EXPECT_THAT(buffer.data(), testing::StrEq("[ERROR][t1,t2][tid\n")); } TEST(LoggingDeathTest, StderrLogger) { @@ -187,11 +193,18 @@ namespace { class LoggingLogTest : public testing::Test { public: - void Log(logging::Level level, std::initializer_list tags, const char* format, ...) { + void Log( + logging::Level level, + std::initializer_list 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(std::data(tags), std::size(tags)), format, args); + logFilter_, logger_, level, std_support::span(std::data(tags), std::size(tags)), threadId, timestamp, + format, args); va_end(args); } @@ -217,13 +230,13 @@ 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); + 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 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\n")); - Log(level, tags, "Message %d", 42); + 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); }