Add user facing Logging API and Benchmarks (#2094)

This commit is contained in:
Tom Tan 2023-04-23 07:52:43 -07:00 committed by GitHub
parent 22d0448ebc
commit a39e8b51ea
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
10 changed files with 626 additions and 26 deletions

View File

@ -17,6 +17,8 @@ Increment the:
* [BUILD] Build break with old curl, macro CURL_VERSION_BITS unknown
[#2102](https://github.com/open-telemetry/opentelemetry-cpp/pull/2102)
* [API] Add user facing Logging API and Benchmarks
[#2094](https://github.com/open-telemetry/opentelemetry-cpp/pull/2094)
Deprecations:

View File

@ -10,6 +10,7 @@
# define OPENTELEMETRY_LIKELY_IF(...) \
if (__VA_ARGS__) \
[[likely]]
# endif
# endif
#endif
@ -176,6 +177,31 @@ point.
#endif
//
// Atomic wrappers based on compiler intrinsics for memory read/write.
// The tailing number is read/write length in bits.
//
// N.B. Compiler instrinsic is used because the usage of C++ standard library is restricted in the
// OpenTelemetry C++ API.
//
#if defined(__GNUC__)
# define OPENTELEMETRY_ATOMIC_READ_8(ptr) __atomic_load_n(ptr, __ATOMIC_SEQ_CST)
# define OPENTELEMETRY_ATOMIC_WRITE_8(ptr, value) __atomic_store_n(ptr, value, __ATOMIC_SEQ_CST)
#elif defined(_MSC_VER)
# include <intrin.h>
# define OPENTELEMETRY_ATOMIC_READ_8(ptr) \
static_cast<uint8_t>(_InterlockedCompareExchange8(reinterpret_cast<char *>(ptr), 0, 0))
# define OPENTELEMETRY_ATOMIC_WRITE_8(ptr, value) \
_InterlockedExchange8(reinterpret_cast<char *>(ptr), static_cast<char>(value))
#else
# error port atomics read/write for the current platform
#endif
/* clang-format on */
//
// The if/elif order matters here. If both OPENTELEMETRY_BUILD_IMPORT_DLL and

View File

@ -0,0 +1,36 @@
// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0
#pragma once
#ifdef ENABLE_LOGS_PREVIEW
# include "opentelemetry/nostd/unique_ptr.h"
# include "opentelemetry/version.h"
OPENTELEMETRY_BEGIN_NAMESPACE
namespace logs
{
/**
* EventId class which acts the Id of the event with an optional name.
*/
class EventId
{
public:
EventId(int64_t id, nostd::string_view name) noexcept
{
id_ = id;
name_ = nostd::unique_ptr<char[]>{new char[name.length() + 1]};
std::copy(name.begin(), name.end(), name_.get());
name_.get()[name.length()] = 0;
}
public:
int64_t id_;
nostd::unique_ptr<char[]> name_;
};
} // namespace logs
OPENTELEMETRY_END_NAMESPACE
#endif

View File

@ -5,6 +5,7 @@
#ifdef ENABLE_LOGS_PREVIEW
# include "opentelemetry/common/key_value_iterable.h"
# include "opentelemetry/logs/event_id.h"
# include "opentelemetry/logs/log_record.h"
# include "opentelemetry/logs/logger_type_traits.h"
# include "opentelemetry/logs/severity.h"
@ -246,10 +247,225 @@ public:
this->EmitLogRecord(Severity::kFatal, std::forward<ArgumentType>(args)...);
}
//
// OpenTelemetry C++ user-facing Logs API
//
inline bool Enabled(Severity severity, const EventId &event_id) const noexcept
{
OPENTELEMETRY_LIKELY_IF(Enabled(severity) == false) { return false; }
return EnabledImplementation(severity, event_id);
}
inline bool Enabled(Severity severity, int64_t event_id) const noexcept
{
OPENTELEMETRY_LIKELY_IF(Enabled(severity) == false) { return false; }
return EnabledImplementation(severity, event_id);
}
inline bool Enabled(Severity severity) const noexcept
{
return static_cast<uint8_t>(severity) >= OPENTELEMETRY_ATOMIC_READ_8(&minimum_severity_);
}
/**
* Log an event
*
* @severity severity of the log
* @event_id event identifier of the log
* @format an utf-8 string following https://messagetemplates.org/
* @attributes key value pairs of the log
*/
virtual void Log(Severity severity,
const EventId &event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->EmitLogRecord(severity, event_id, format, attributes);
}
virtual void Log(Severity severity,
int64_t event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->EmitLogRecord(severity, event_id, format, attributes);
}
virtual void Log(Severity severity,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->EmitLogRecord(severity, format, attributes);
}
virtual void Log(Severity severity, nostd::string_view message) noexcept
{
this->EmitLogRecord(severity, message);
}
// Convenient wrappers based on virtual methods Log().
// https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/data-model.md#field-severitynumber
inline void Trace(const EventId &event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kTrace, event_id, format, attributes);
}
inline void Trace(int64_t event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kTrace, event_id, format, attributes);
}
inline void Trace(nostd::string_view format, const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kTrace, format, attributes);
}
inline void Trace(nostd::string_view message) noexcept { this->Log(Severity::kTrace, message); }
inline void Debug(const EventId &event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kDebug, event_id, format, attributes);
}
inline void Debug(int64_t event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kDebug, event_id, format, attributes);
}
inline void Debug(nostd::string_view format, const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kDebug, format, attributes);
}
inline void Debug(nostd::string_view message) noexcept { this->Log(Severity::kDebug, message); }
inline void Info(const EventId &event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kInfo, event_id, format, attributes);
}
inline void Info(int64_t event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kInfo, event_id, format, attributes);
}
inline void Info(nostd::string_view format, const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kInfo, format, attributes);
}
inline void Info(nostd::string_view message) noexcept { this->Log(Severity::kInfo, message); }
inline void Warn(const EventId &event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kWarn, event_id, format, attributes);
}
inline void Warn(int64_t event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kWarn, event_id, format, attributes);
}
inline void Warn(nostd::string_view format, const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kWarn, format, attributes);
}
inline void Warn(nostd::string_view message) noexcept { this->Log(Severity::kWarn, message); }
inline void Error(const EventId &event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kError, event_id, format, attributes);
}
inline void Error(int64_t event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kError, event_id, format, attributes);
}
inline void Error(nostd::string_view format, const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kError, format, attributes);
}
inline void Error(nostd::string_view message) noexcept { this->Log(Severity::kError, message); }
inline void Fatal(const EventId &event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kFatal, event_id, format, attributes);
}
inline void Fatal(int64_t event_id,
nostd::string_view format,
const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kFatal, event_id, format, attributes);
}
inline void Fatal(nostd::string_view format, const common::KeyValueIterable &attributes) noexcept
{
this->Log(Severity::kFatal, format, attributes);
}
inline void Fatal(nostd::string_view message) noexcept { this->Log(Severity::kFatal, message); }
//
// End of OpenTelemetry C++ user-facing Log API.
//
protected:
// TODO: discuss with community about naming for internal methods.
virtual bool EnabledImplementation(Severity /*severity*/,
const EventId & /*event_id*/) const noexcept
{
return false;
}
virtual bool EnabledImplementation(Severity /*severity*/, int64_t /*event_id*/) const noexcept
{
return false;
}
void SetMinimumSeverity(uint8_t severity_or_max) noexcept
{
OPENTELEMETRY_ATOMIC_WRITE_8(&minimum_severity_, severity_or_max);
}
private:
template <class... ValueType>
void IgnoreTraitResult(ValueType &&...)
{}
//
// minimum_severity_ can be updated concurrently by multiple threads/cores, so race condition on
// read/write should be handled. And std::atomic can not be used here because it is not ABI
// compatible for OpenTelemetry C++ API.
//
mutable uint8_t minimum_severity_{kMaxSeverity};
};
} // namespace logs
OPENTELEMETRY_END_NAMESPACE

View File

@ -35,7 +35,7 @@ public:
virtual nostd::shared_ptr<Logger> GetLogger(
nostd::string_view logger_name,
nostd::string_view library_name,
nostd::string_view library_name = "",
nostd::string_view library_version = "",
nostd::string_view schema_url = "",
bool include_trace_context = true,

View File

@ -10,6 +10,7 @@
# include "opentelemetry/common/attribute_value.h"
# include "opentelemetry/common/key_value_iterable.h"
# include "opentelemetry/common/timestamp.h"
# include "opentelemetry/logs/event_id.h"
# include "opentelemetry/logs/log_record.h"
# include "opentelemetry/logs/severity.h"
# include "opentelemetry/nostd/shared_ptr.h"
@ -43,6 +44,17 @@ struct LogRecordSetterTrait<Severity>
}
};
template <>
struct LogRecordSetterTrait<EventId>
{
template <class ArgumentType>
inline static LogRecord *Set(LogRecord *log_record, ArgumentType && /*arg*/) noexcept
{
// TODO: set log_record
return log_record;
}
};
template <>
struct LogRecordSetterTrait<trace::SpanContext>
{

View File

@ -13,36 +13,41 @@ namespace logs
/**
* Severity Levels assigned to log events, based on Log Data Model,
* with the addition of kInvalid (mapped to a severity number of 0).
*
* See
* https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/data-model.md#field-severitynumber
*/
enum class Severity : uint8_t
{
kInvalid,
kTrace,
kTrace2,
kTrace3,
kTrace4,
kDebug,
kDebug2,
kDebug3,
kDebug4,
kInfo,
kInfo2,
kInfo3,
kInfo4,
kWarn,
kWarn2,
kWarn3,
kWarn4,
kError,
kError2,
kError3,
kError4,
kFatal,
kFatal2,
kFatal3,
kFatal4
kInvalid = 0,
kTrace = 1,
kTrace2 = 2,
kTrace3 = 3,
kTrace4 = 4,
kDebug = 5,
kDebug2 = 6,
kDebug3 = 7,
kDebug4 = 8,
kInfo = 9,
kInfo2 = 10,
kInfo3 = 11,
kInfo4 = 12,
kWarn = 13,
kWarn2 = 14,
kWarn3 = 15,
kWarn4 = 16,
kError = 17,
kError2 = 18,
kError3 = 19,
kError4 = 20,
kFatal = 21,
kFatal2 = 22,
kFatal3 = 23,
kFatal4 = 24
};
const uint8_t kMaxSeverity = 255;
/**
* Mapping of the severity enum above, to a severity text string (in all caps).
* This severity text can be printed out by exporters. Capital letters follow the

View File

@ -10,3 +10,9 @@ foreach(testname provider_test logger_test)
TEST_PREFIX logs.
TEST_LIST logs_api_${testname})
endforeach()
if(WITH_BENCHMARK)
add_executable(logger_benchmark logger_benchmark.cc)
target_link_libraries(logger_benchmark benchmark::benchmark
${CMAKE_THREAD_LIBS_INIT} opentelemetry_api)
endif()

View File

@ -0,0 +1,260 @@
// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0
#ifdef ENABLE_LOGS_PREVIEW
# include "opentelemetry/common/timestamp.h"
# include "opentelemetry/logs/logger.h"
# include "opentelemetry/logs/provider.h"
# include "opentelemetry/nostd/shared_ptr.h"
# include <chrono>
# include <condition_variable>
# include <functional>
# include <mutex>
# include <thread>
# include <vector>
# include <benchmark/benchmark.h>
using opentelemetry::logs::EventId;
using opentelemetry::logs::Logger;
using opentelemetry::logs::LoggerProvider;
using opentelemetry::logs::Provider;
using opentelemetry::logs::Severity;
using opentelemetry::nostd::shared_ptr;
using opentelemetry::nostd::span;
using opentelemetry::nostd::string_view;
namespace common = opentelemetry::common;
namespace nostd = opentelemetry::nostd;
namespace trace = opentelemetry::trace;
namespace log_api = opentelemetry::logs;
namespace
{
constexpr int64_t kMaxIterations = 1000000000;
class Barrier
{
public:
explicit Barrier(std::size_t iCount) : mThreshold(iCount), mCount(iCount), mGeneration(0) {}
void Wait()
{
std::unique_lock<std::mutex> lLock{mMutex};
auto lGen = mGeneration;
if (!--mCount)
{
mGeneration++;
mCount = mThreshold;
mCond.notify_all();
}
else
{
mCond.wait(lLock, [this, lGen] { return lGen != mGeneration; });
}
}
private:
std::mutex mMutex;
std::condition_variable mCond;
std::size_t mThreshold;
std::size_t mCount;
std::size_t mGeneration;
};
static void ThreadRoutine(Barrier &barrier,
benchmark::State &state,
int thread_id,
std::function<void()> func)
{
barrier.Wait();
if (thread_id == 0)
{
state.ResumeTiming();
}
barrier.Wait();
func();
if (thread_id == 0)
{
state.PauseTiming();
}
barrier.Wait();
}
void MultiThreadRunner(benchmark::State &state, std::function<void()> func)
{
int num_threads = std::thread::hardware_concurrency();
Barrier barrier(num_threads);
std::vector<std::thread> threads;
for (int i = 0; i < num_threads; i++)
{
threads.emplace_back(ThreadRoutine, std::ref(barrier), std::ref(state), i, func);
}
for (auto &thread : threads)
{
thread.join();
}
}
static void BM_UnstructuredLog(benchmark::State &state)
{
auto lp = Provider::GetLoggerProvider();
auto logger = lp->GetLogger("UnstructuredLog");
for (auto _ : state)
{
state.PauseTiming();
MultiThreadRunner(state, [&logger]() {
for (int64_t i = 0; i < kMaxIterations; i++)
{
logger->Trace("This is a simple unstructured log message");
}
});
state.ResumeTiming();
}
}
BENCHMARK(BM_UnstructuredLog);
static void BM_StructuredLogWithTwoAttributes(benchmark::State &state)
{
auto lp = Provider::GetLoggerProvider();
auto logger = lp->GetLogger("StructuredLog");
for (auto _ : state)
{
state.PauseTiming();
MultiThreadRunner(state, [&logger]() {
for (int64_t i = 0; i < kMaxIterations; i++)
{
logger->Trace(
"This is a simple structured log message from {process_id}:{thread_id}",
opentelemetry::common::MakeAttributes({{"process_id", 12347}, {"thread_id", 12348}}));
}
});
state.ResumeTiming();
}
}
BENCHMARK(BM_StructuredLogWithTwoAttributes);
static void BM_StructuredLogWithEventIdAndTwoAttributes(benchmark::State &state)
{
auto lp = Provider::GetLoggerProvider();
auto logger = lp->GetLogger("StructuredLogWithEventId");
for (auto _ : state)
{
state.PauseTiming();
MultiThreadRunner(state, [&logger]() {
for (int64_t i = 0; i < kMaxIterations; i++)
{
logger->Trace(
"This is a simple structured log message from {process_id}:{thread_id}",
opentelemetry::common::MakeAttributes({{"process_id", 12347}, {"thread_id", 12348}}));
}
});
state.ResumeTiming();
}
}
BENCHMARK(BM_StructuredLogWithEventIdAndTwoAttributes);
static void BM_StructuredLogWithEventIdStructAndTwoAttributes(benchmark::State &state)
{
auto lp = Provider::GetLoggerProvider();
auto logger = lp->GetLogger("StructuredLogWithEventId");
const EventId function_name_event_id{0x12345678, "Company.Component.SubComponent.FunctionName"};
for (auto _ : state)
{
state.PauseTiming();
MultiThreadRunner(state, [&logger, &function_name_event_id]() {
for (int64_t i = 0; i < kMaxIterations; i++)
{
logger->Trace(
function_name_event_id,
"Simulate function enter trace message from {process_id}:{thread_id}",
opentelemetry::common::MakeAttributes({{"process_id", 12347}, {"thread_id", 12348}}));
}
});
state.ResumeTiming();
}
}
BENCHMARK(BM_StructuredLogWithEventIdStructAndTwoAttributes);
static void BM_EnabledOnSeverityReturnFalse(benchmark::State &state)
{
auto lp = Provider::GetLoggerProvider();
auto logger = lp->GetLogger("UnstructuredLogWithEnabledReturnFalse");
for (auto _ : state)
{
state.PauseTiming();
MultiThreadRunner(state, [&logger]() {
for (int64_t i = 0; i < kMaxIterations; i++)
{
if (logger->Enabled(Severity::kTrace))
{
logger->Trace("This log line would not be called");
}
}
});
state.ResumeTiming();
}
}
BENCHMARK(BM_EnabledOnSeverityReturnFalse);
static void BM_EnabledOnSeverityAndEventIdReturnFalse(benchmark::State &state)
{
auto lp = Provider::GetLoggerProvider();
auto logger = lp->GetLogger("UnstructuredLogWithEnabledReturnFalse");
for (auto _ : state)
{
state.PauseTiming();
MultiThreadRunner(state, [&logger]() {
for (int64_t i = 0; i < kMaxIterations; i++)
{
if (logger->Enabled(Severity::kTrace, 0x12345678))
{
logger->Trace("This log line would not be called");
}
}
});
state.ResumeTiming();
}
}
BENCHMARK(BM_EnabledOnSeverityAndEventIdReturnFalse);
} // namespace
int main(int argc, char **argv)
{
benchmark::Initialize(&argc, argv);
benchmark::RunSpecifiedBenchmarks();
}
#endif

View File

@ -12,6 +12,7 @@
# include "opentelemetry/logs/provider.h"
# include "opentelemetry/nostd/shared_ptr.h"
using opentelemetry::logs::EventId;
using opentelemetry::logs::Logger;
using opentelemetry::logs::LoggerProvider;
using opentelemetry::logs::Provider;
@ -52,6 +53,13 @@ TEST(Logger, LogMethodOverloads)
const std::string schema_url{"https://opentelemetry.io/schemas/1.11.0"};
auto logger = lp->GetLogger("TestLogger", "opentelelemtry_library", "", schema_url);
EventId trace_event_id{0x1, "TraceEventId"};
EventId debug_event_id{0x2, "DebugEventId"};
EventId info_event_id{0x3, "InfoEventId"};
EventId warn_event_id{0x4, "WarnEventId"};
EventId error_event_id{0x5, "ErrorEventId"};
EventId fatal_event_id{0x6, "FatalEventId"};
// Create a map to test the logs with
std::map<std::string, std::string> m = {{"key1", "value1"}};
@ -79,36 +87,65 @@ TEST(Logger, LogMethodOverloads)
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Trace(m);
logger->Trace(opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Trace(trace_event_id, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Trace(trace_event_id.id_, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Debug("Test log message");
logger->Debug("Test log message", m);
logger->Debug("Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Debug(m);
logger->Debug(opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Debug(debug_event_id, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Debug(debug_event_id.id_, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Info("Test log message");
logger->Info("Test log message", m);
logger->Info("Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Info(m);
logger->Info(opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Info(info_event_id, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Info(info_event_id.id_, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Warn("Test log message");
logger->Warn("Test log message", m);
logger->Warn("Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Warn(m);
logger->Warn(opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Warn(warn_event_id, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Warn(warn_event_id.id_, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Error("Test log message");
logger->Error("Test log message", m);
logger->Error("Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Error(m);
logger->Error(opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Error(error_event_id, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Error(error_event_id.id_, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Fatal("Test log message");
logger->Fatal("Test log message", m);
logger->Fatal("Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Fatal(m);
logger->Fatal(opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Fatal(fatal_event_id, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
logger->Fatal(fatal_event_id.id_, "Test log message",
opentelemetry::common::MakeAttributes({{"key1", "value 1"}, {"key2", 2}}));
}
TEST(Logger, EventLogMethodOverloads)