azalea/kotlin-fork
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

[K/N] Tweak runtime logging ^KT-55364

Browse Source 
Print thread id and process uptime.
This commit is contained in:
Alexander Shabalin
2023-04-11 12:21:25 +02:00
committed by Space Cloud
parent a6d93797ee
commit f4c89148b8
3 changed files with 73 additions and 31 deletions
Download Patch File Download Diff File Expand all files Collapse all files
kotlin-native/runtime/src/main/cpp/Logging.cpp
+30 -6
View File
@@ -6,8 +6,7 @@
#include "Logging.hpp"
#include <array>
#include <cinttypes>
#include "Format.h"
#include "KAssert.h"
@@ -133,6 +132,24 @@ std_support::span<char> FormatTags(std_support::span<char> buffer, std_support::
return FormatToSpan(buffer, "]");
}
std_support::span<char> FormatTimestamp(std_support::span<char> buffer, kotlin::nanoseconds timestamp) noexcept {
auto s = static_cast<double>(timestamp.count().value) / 1'000'000'000;
return FormatToSpan(buffer, "[%.3fs]", s);
}
std_support::span<char> FormatThread(std_support::span<char> 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::LogFilter> logging::internal::CreateLogFilter(std::string_view tagsFilter) noexcept {
@@ -147,11 +164,15 @@ std_support::span<char> logging::internal::FormatLogEntry(
std_support::span<char> buffer,
logging::Level level,
std_support::span<const char* const> 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<const char* const> 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<char, 1024> 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<const char*> tags, const ch
}
void logging::VLog(Level level, std::initializer_list<const char*> 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<const char* const> 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);
}
kotlin-native/runtime/src/main/cpp/Logging.hpp
+5
View File
@@ -21,6 +21,7 @@ using string_view = std::experimental::string_view;
#error "No <string_view>"
#endif
#include "Clock.hpp"
#include "CompilerConstants.hpp"
#include "std_support/Memory.hpp"
#include "std_support/Span.hpp"
@@ -60,6 +61,8 @@ std_support::span<char> FormatLogEntry(
std_support::span<char> buffer,
Level level,
std_support::span<const char* const> 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<const char* const> tags,
int threadId,
kotlin::nanoseconds timestamp,
const char* format,
std::va_list args) noexcept;
kotlin-native/runtime/src/main/cpp/LoggingTest.cpp
+38 -25
View File
@@ -17,11 +17,17 @@ using ::testing::_;
namespace {
std_support::span<char> FormatLogEntry(
std_support::span<char> buffer, logging::Level level, std::initializer_list<const char*> tags, const char* format, ...) {
std_support::span<char> buffer,
logging::Level level,
std::initializer_list<const char*> tags,
int threadId,
kotlin::nanoseconds timestamp,
const char* format,
...) {
std_support::span<const char* const> 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<char, 1024> 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<char, 1024> 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<char, 1024> 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<char, 1024> 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<char, 1024> 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<char, 1024> 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<char, 1024> 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<char, 1024> 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<char, 20> 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<const char*> tags, const char* format, ...) {
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)), format, args);
logFilter_, logger_, level, std_support::span<const char* const>(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<const char*> 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<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] 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);
}