Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[API] Add user facing Logging API and Benchmarks #2094

Merged
merged 14 commits into from
Apr 23, 2023
Merged

[API] Add user facing Logging API and Benchmarks #2094

Show file tree
Hide file tree
Changes from 12 commits
Commits
Show all changes
14 commits
Select commit Hold shift + click to select a range
60fb322
Add user facing Logging API and Benchmarks
ThomsonTan Apr 7, 2023
a613863
Make minimum_severity_ mutable for interlocked read/write and add more
ThomsonTan Apr 14, 2023
4f6b360
Merge branch 'main' into LogAPIBenchmark_PR
ThomsonTan Apr 15, 2023
9c5080b
Format with clang-10
ThomsonTan Apr 15, 2023
6ab98fe
Fix unused parameters
ThomsonTan Apr 17, 2023
ca51896
Remove unused parameter in logger_benchmark
ThomsonTan Apr 17, 2023
d2a1a45
Remove extra unused parameters
ThomsonTan Apr 17, 2023
fc92d60
Address feedback
ThomsonTan Apr 18, 2023
c6e2296
Merge branch 'main' into LogAPIBenchmark_PR
ThomsonTan Apr 19, 2023
8e82391
Assign explicit number to Severity enum
ThomsonTan Apr 19, 2023
11ced70
Merge branch 'main' into LogAPIBenchmark_PR
ThomsonTan Apr 20, 2023
8e9c884
End event name with explicit 0
ThomsonTan Apr 21, 2023
b9846bf
Update changelog
ThomsonTan Apr 21, 2023
d6e96af
Merge branch 'main' into LogAPIBenchmark_PR
ThomsonTan Apr 22, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
26 changes: 26 additions & 0 deletions api/include/opentelemetry/common/macros.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@
# define OPENTELEMETRY_LIKELY_IF(...) \
if (__VA_ARGS__) \
[[likely]]

# endif
# endif
#endif
Expand Down Expand Up @@ -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
Expand Down
36 changes: 36 additions & 0 deletions api/include/opentelemetry/logs/event_id.h
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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());
Copy link
Member

@lalitb lalitb Apr 18, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This goes against the standard practice of not doing any memory copy at the API/SDK surface. The recordable interface design ensures that we can directly serialize the data at exporter, without creating any intermediate copies at the API/SDK level. One solution to avoid this copy operation can be to get rid of EventId class, and pass the event-id (as int64_t) and event-name (as notstd::string_view) directly to Log methods. Also we have only used primitive, or non-owningnostd types as API arguments. Even though we can debate that passing reference/pointer to a user created class mayn't break the ABI, in general good to avoid if we can.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This goes against the standard practice of not doing any memory copy at the API/SDK surface.

No memory will be allocated in our logging APIs. The EventId class is supposed to be created by the user with sort of global lifetime, it so copies the string instead of using any string_view on existing string because it then requires the user to manage the original string object explicitly. The allocation and free of such object is not in the scope of logging API as it only takes const reference on such object.

name_.get()[name.length()] = 0;
}

public:
int64_t id_;
nostd::unique_ptr<char[]> name_;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not use std::string name_; here? The usage of this variable above seems just like std::string, and do not add a tail \0 ?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

EventId can be read from both user and SDK code, which requires it to be ABI compatible. std::string cannot guarantee such ABI compatibility requirement across the boundary between user code/SDK so cannot be used. I'd expect there is nostd::string but we don't have it, then switch to primitive char pointer wrapped in nostd::unique_ptr. Let me know if this addresses the concern.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the explain, on the other hand, should we set name_[name.length()] = 0; here?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, that makes sense. Set the last element of name_ as 0.

};

} // namespace logs
OPENTELEMETRY_END_NAMESPACE
#endif
216 changes: 216 additions & 0 deletions api/include/opentelemetry/logs/logger.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -246,10 +247,225 @@ class Logger
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
{
Comment on lines +287 to +291
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need each of these helpers to be virtual functions ?

A simple inline function seem sufficient.

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);
}
Comment on lines +310 to +315
Copy link
Member

@marcalff marcalff Apr 18, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am confused about the intended usage for this helper:

Is the caller supposed to check Enabled for each call, as in:

if (logger->Enabled(xxx)) {
  logger->Trace(xxx);
}

or is Trace() responsible to check the severity flag itself, as in:

logger->Trace(xxx);

The benchmarks shows both usage, is this code writing un wanted traces in the second case ?
The check for Enabled() seems missing from the code path.

Beside, if the whole point of Logger::minimum_severity_ is to check the flags in the API before making a virtual function call, then why making calls here to virtual functions Log() and EmitLogRecord() ?

Suggested changes:

  • Call Enabled() in every user facing api.
  • Do not call a user facing api like Log() from another user facing api like Trace(), call EmitLogRecord directly, so the Enabled() flags are not checked multiple times.

For example:

inline void Trace(xxx) {
  if (Enabled(xxx)) {
    EmitLogRecord(xxx);
  }
}

Edit: If EmitLogRecord() is also considered user facing (it is in the spec), then:

inline void Trace(xxx) {
  if (Enabled(xxx)) {
    DoEmitLogRecord(xxx);
  }
}

where DoEmitLogRecord() is a protected virtual method.

This will add clarity:

  • user facing apis are public, inline, not virtual, and test if Enabled() up front
  • user facing api delegate to not user facing, after the Enabled() test.
  • not user facing apis are protected, virtual, and do not test Enabled().

Copy link
Contributor Author

@ThomsonTan ThomsonTan Apr 18, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the suggestion @marcalff .

Call Enabled() in every user facing api.
Enabled() should be called by the user's code instead of from our all our wrappers which is intentional. The idea is to avoid calculating any parameters which is only for logging. In the simple case, common::MakeAttributes({"key1", “value1}, {"key2", "value2"}} takes significant extra time than the Enabled() check. And there could be many other heavy query result which passed as parameters to query. Calling Enabled() in user's code can eliminate such heavy query from the first place.

logger->Trace("some message template", common::MakeAttributes({"some_value_takes_time_calculate", long_time_query()}));

If we are not going to call Enabled() in user facing API, then inline the call of DoLogRecord seems unnecessary for all the wrappers then? I don't have strong preference as the name implied they are just wrappers. But I can also revisit this part in the SDK support because changing the implementation will not break the user facing API.

Please let me know if anything is missed here.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just want to have a discuss.
We have a log macro like this before in our project.

#define WLOGDEBUG(logger, ...) \
  if(logger.check_level(log_level::DEBUG)) {
    logger->log(log_level::DEBUG, __VA_ARGS__);
  }

And when we use WLOGDEBUG(logger, "Debug message: {}", protobuf_message.DebugString()); and if the debug log is not enabled, protobuf_message.DebugString() will not be called and it's a high cost function.

Is there any way we can achieve a similar effect?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Perhaps we can define similar macro to help the user reduce boilerplate code, but it can avoid the logging cost. Based on the logging statement you shared, the the variable protobuf_message might be only need for logging, and it could do heavy initialization (like map or load string resources). This happens in the definition of protobuf_message which cannot be be optimized here.

  WLOGDEBUG(logger, "Debug message: {}", protobuf_message.DebugString());

While providing macros could help, the pointer in our API is make Enabled check explicit to the user, so they are aware of this and encouraged to do the optimization to archive high performance logging.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Let's continue the discussion about Enabled() in the next patch, for the SDK part.

The fact that the caller MAY use Enabled() to optimize paths that evaluate complex arguments is good.

Still we can't force that the caller MUST use Enabled() all the time, so the implementation will need to check it again at some point.


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*/,
Copy link
Member

@reyang reyang Apr 18, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Instead of having a function which child classes can derive from, I wonder if it makes sense to use a function pointer (similar to the severity level field which can be set by the implementations).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Assume this is for internal implementation so doesn't block the PR.

The virtual function here looks a restricted function pointer which is stored in the virtual table. If we store the pointer here like class Logger, it seems more flexible like not SDK but any other library can provide a function to do real Enabled() work. It might also be more risky if the function pointer is compromised then it can invoke anything as code. The virtual function is safer in this regard as it cannot be patched at runtime, and it is usually in the protected path.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I actually consider the patch as a bless than a curse. (and I don't see why virtual functions cannot be patched)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Virtual function tables are in read only area of memory in modern operation system which cannot be patched normally.

But I think the idea still applies to provider a mechanism for any related part to register its own Enabled() check to the API Logger. Opened #2105 to track this because it is NOT API breaking change.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

About the name, EnabledImplementation, discussion is deferred to the SDK patch if I understand correctly.

Using a function callback in a class member instead of a virtual method is asking for too much trouble in my opinion:

  • what if it changes, should the pointer itself be looked up using atomics, similar to the severity ?
  • Even after an atomic read, is the pointer still valid anyway (for all we know, it can be in a shared library), so is it safe to invoke ?

In short, the current proposal (virtual method) looks good to me, apart from the name to discuss later.

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
Expand Down
2 changes: 1 addition & 1 deletion api/include/opentelemetry/logs/logger_provider.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@ class OPENTELEMETRY_EXPORT LoggerProvider

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,
Expand Down
12 changes: 12 additions & 0 deletions api/include/opentelemetry/logs/logger_type_traits.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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>
{
Expand Down
Loading