Skip to content

Performance Improvements in traces and logs #122

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

Merged
merged 5 commits into from
May 22, 2024
Merged

Performance Improvements in traces and logs #122

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
68a6960
refactor startSpan in TracerProxy to improve performance
duncanpo May 14, 2024
454ae64
metrics performance tests
duncanpo May 16, 2024
a16b03e
logs performance test and some refactoring of metrics performance test
duncanpo May 17, 2024
438453b
Performance improvement in logs
duncanpo May 20, 2024
bb7fc22
use keepMeasuring in performance tests instead of explicit looping
duncanpo May 21, 2024
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
96 changes: 59 additions & 37 deletions api/logs/+opentelemetry/+logs/Logger.m
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -65,8 +65,10 @@ function emitLogRecord(obj, severity, body, trailingnames, trailingvalues)
% severity text
% Support 24 valid severity levels: trace, trace2, trace3,
% trace4, debug, debug2, debug3, ...
severitylist = ["trace", "debug", "info", "warn", "error", "fatal"];
severitylist = reshape(severitylist + [""; "2"; "3"; "4"], 1, []);
severitylist = ["trace" "trace2" "trace3" "trace4" "debug" ...
"debug2" "debug3" "debug4" "info" "info2" "info3" "info4" ...
"warn" "warn2" "warn3" "warn4" "error" "error2" "error3" ...
"error4" "fatal" "fatal2" "fatal3" "fatal4"];
d = dictionary(severitylist, 1:length(severitylist));
try
severity = d(lower(severity));
Expand All @@ -81,39 +83,59 @@ function emitLogRecord(obj, severity, body, trailingnames, trailingvalues)
% body
body = convertCharsToStrings(body); % force char rows into strings

% validate the trailing names and values
optionnames = ["Context", "Timestamp", "Attributes"];

% define default values
contextid = intmax("uint64"); % default value which means no context supplied
timestamp = NaN;
attributekeys = string.empty();
attributevalues = {};

% Loop through Name-Value pairs
for i = 1:length(trailingnames)
try
namei = validatestring(trailingnames{i}, optionnames);
catch
% invalid option, ignore
continue
end
if strcmp(namei, "Context")
context = trailingvalues{i};
if isa(context, "opentelemetry.context.Context")
contextid = context.Proxy.ID;
if nargin <= 3
obj.Proxy.emitLogRecord(severity, body);
else
% validate the trailing names and values
optionnames = ["Context", "Timestamp", "Attributes"];

% define default values
contextid = intmax("uint64"); % default value which means no context supplied
timestamp = NaN;
attributekeys = string.empty();
attributevalues = {};

% variables to keep track of which proxy function to call
specifyoptions = false;
specifyattributes = false;

% Loop through Name-Value pairs
for i = 1:length(trailingnames)
try
namei = validatestring(trailingnames{i}, optionnames);
catch
% invalid option, ignore
continue
end
elseif strcmp(namei, "Timestamp")
valuei = trailingvalues{i};
if isdatetime(valuei) && isscalar(valuei) && ~isnat(valuei)
timestamp = posixtime(valuei);
if strcmp(namei, "Context")
context = trailingvalues{i};
if isa(context, "opentelemetry.context.Context")
contextid = context.Proxy.ID;
specifyoptions = true;
end
elseif strcmp(namei, "Timestamp")
valuei = trailingvalues{i};
if isdatetime(valuei) && isscalar(valuei) && ~isnat(valuei)
timestamp = posixtime(valuei);
specifyoptions = true;
end
elseif strcmp(namei, "Attributes")
[attributekeys, attributevalues] = processAttributes(trailingvalues{i}, true);
specifyattributes = true;
end
elseif strcmp(namei, "Attributes")
[attributekeys, attributevalues] = processAttributes(trailingvalues{i}, true);
end

if ~specifyoptions && ~specifyattributes
obj.Proxy.emitLogRecord(severity, body);
elseif specifyoptions && ~specifyattributes
obj.Proxy.emitLogRecord(severity, body, contextid, timestamp);
elseif ~specifyoptions && specifyattributes
obj.Proxy.emitLogRecord(severity, body, attributekeys, attributevalues);
else % specifyoptions && specifyattributes
obj.Proxy.emitLogRecord(severity, body, contextid, timestamp, ...
attributekeys, attributevalues);
end
end
obj.Proxy.emitLogRecord(severity, body, contextid, timestamp, ...
attributekeys, attributevalues);
end

function trace(obj, body, varargin)
Expand All @@ -134,7 +156,7 @@ function trace(obj, body, varargin)
% OPENTELEMETRY.LOGS.INFO, OPENTELEMETRY.LOGS.WARN,
% OPENTELEMETRY.LOGS.ERROR, OPENTELEMETRY.LOGS.FATAL,
% OPENTELEMETRY.LOGS.EMITLOGRECORD
emitLogRecord(obj, "trace", body, varargin{:});
emitLogRecord(obj, 1, body, varargin{:});
end

function debug(obj, body, varargin)
Expand All @@ -155,7 +177,7 @@ function debug(obj, body, varargin)
% OPENTELEMETRY.LOGS.INFO, OPENTELEMETRY.LOGS.WARN,
% OPENTELEMETRY.LOGS.ERROR, OPENTELEMETRY.LOGS.FATAL,
% OPENTELEMETRY.LOGS.EMITLOGRECORD
emitLogRecord(obj, "debug", body, varargin{:});
emitLogRecord(obj, 5, body, varargin{:});
end

function info(obj, body, varargin)
Expand All @@ -176,7 +198,7 @@ function info(obj, body, varargin)
% OPENTELEMETRY.LOGS.DEBUG, OPENTELEMETRY.LOGS.WARN,
% OPENTELEMETRY.LOGS.ERROR, OPENTELEMETRY.LOGS.FATAL,
% OPENTELEMETRY.LOGS.EMITLOGRECORD
emitLogRecord(obj, "info", body, varargin{:});
emitLogRecord(obj, 9, body, varargin{:});
end

function warn(obj, body, varargin)
Expand All @@ -197,7 +219,7 @@ function warn(obj, body, varargin)
% OPENTELEMETRY.LOGS.DEBUG, OPENTELEMETRY.LOGS.INFO,
% OPENTELEMETRY.LOGS.ERROR, OPENTELEMETRY.LOGS.FATAL,
% OPENTELEMETRY.LOGS.EMITLOGRECORD
emitLogRecord(obj, "warn", body, varargin{:});
emitLogRecord(obj, 13, body, varargin{:});
end

function error(obj, body, varargin)
Expand All @@ -218,7 +240,7 @@ function error(obj, body, varargin)
% OPENTELEMETRY.LOGS.DEBUG, OPENTELEMETRY.LOGS.INFO,
% OPENTELEMETRY.LOGS.WARN, OPENTELEMETRY.LOGS.FATAL,
% OPENTELEMETRY.LOGS.EMITLOGRECORD
emitLogRecord(obj, "error", body, varargin{:});
emitLogRecord(obj, 17, body, varargin{:});
end

function fatal(obj, body, varargin)
Expand All @@ -239,7 +261,7 @@ function fatal(obj, body, varargin)
% OPENTELEMETRY.LOGS.DEBUG, OPENTELEMETRY.LOGS.INFO,
% OPENTELEMETRY.LOGS.WARN, OPENTELEMETRY.LOGS.ERROR,
% OPENTELEMETRY.LOGS.EMITLOGRECORD
emitLogRecord(obj, "fatal", body, varargin{:});
emitLogRecord(obj, 21, body, varargin{:});
end
end

Expand Down
80 changes: 45 additions & 35 deletions api/logs/src/LoggerProxy.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,17 +20,10 @@ namespace nostd = opentelemetry::nostd;

namespace libmexclass::opentelemetry {
void LoggerProxy::emitLogRecord(libmexclass::proxy::method::Context& context) {
const size_t ninputs = context.inputs.getNumberOfElements();
matlab::data::TypedArray<double> severity_mda = context.inputs[0];
int severity = static_cast<int>(severity_mda[0]);
matlab::data::Array body_mda = context.inputs[1];
matlab::data::TypedArray<uint64_t> contextid_mda = context.inputs[2];
libmexclass::proxy::ID contextid = contextid_mda[0];
libmexclass::proxy::ID nocontextid(-1); // wrap around to intmax
matlab::data::TypedArray<double> timestamp_mda = context.inputs[3];
double timestamp = timestamp_mda[0]; // number of seconds since 1/1/1970 (i.e. POSIX time)
matlab::data::StringArray attrnames_mda = context.inputs[4];
size_t nattrs = attrnames_mda.getNumberOfElements();
matlab::data::CellArray attrvalues_mda = context.inputs[5];

// log body
ProcessedAttributes bodyattrs;
Expand All @@ -47,39 +40,56 @@ void LoggerProxy::emitLogRecord(libmexclass::proxy::method::Context& context) {

nostd::unique_ptr<logs_api::LogRecord> rec = CppLogger->CreateLogRecord();

// context
if (contextid != nocontextid) {
context_api::Context supplied_context = std::static_pointer_cast<ContextProxy>(
libmexclass::proxy::ProxyManager::getProxy(contextid))->getInstance();
trace_api::SpanContext sc = trace_api::GetSpan(supplied_context)->GetContext();
rec->SetTraceId(sc.trace_id());
rec->SetSpanId(sc.span_id());
rec->SetTraceFlags(sc.trace_flags());
// Add size attribute if body is nonscalar
if (array_body) {
rec->SetAttribute(bodyattrs.Attributes.back().first, bodyattrs.Attributes.back().second);
}

// timestamp
if (timestamp == timestamp) { // not NaN. NaN means not specified
rec->SetTimestamp(common::SystemTimestamp{std::chrono::duration<double>(timestamp)});
}
if (ninputs > 2) {
size_t curridx = 2;
matlab::data::Array firstoption = context.inputs[curridx]; // check third input type whether it's a proxy ID
bool first_option_is_id = (firstoption.getType() == matlab::data::ArrayType::UINT64);
if (first_option_is_id) {
// context
matlab::data::TypedArray<uint64_t> contextid_mda = context.inputs[curridx++];
libmexclass::proxy::ID contextid = contextid_mda[0];
const libmexclass::proxy::ID nocontextid = -1; // wrap around to intmax
if (contextid != nocontextid) {
context_api::Context supplied_context = std::static_pointer_cast<ContextProxy>(
libmexclass::proxy::ProxyManager::getProxy(contextid))->getInstance();
trace_api::SpanContext sc = trace_api::GetSpan(supplied_context)->GetContext();
rec->SetTraceId(sc.trace_id());
rec->SetSpanId(sc.span_id());
rec->SetTraceFlags(sc.trace_flags());
}

// attributes
ProcessedAttributes attrs;
if (nattrs > 0) {
for (size_t i = 0; i < nattrs; ++i) {
std::string attrname = static_cast<std::string>(attrnames_mda[i]);
matlab::data::Array attrvalue = attrvalues_mda[i];
// timestamp
matlab::data::TypedArray<double> timestamp_mda = context.inputs[curridx++];
double timestamp = timestamp_mda[0]; // number of seconds since 1/1/1970 (i.e. POSIX time)
if (timestamp == timestamp) { // not NaN. NaN means not specified
rec->SetTimestamp(common::SystemTimestamp{std::chrono::duration<double>(timestamp)});
}
}

if (!first_option_is_id || ninputs > 4) {
// attributes
matlab::data::StringArray attrnames_mda = context.inputs[curridx++];
size_t nattrs = attrnames_mda.getNumberOfElements();
matlab::data::CellArray attrvalues_mda = context.inputs[curridx];
ProcessedAttributes attrs;
if (nattrs > 0) {
for (size_t i = 0; i < nattrs; ++i) {
std::string attrname = static_cast<std::string>(attrnames_mda[i]);
matlab::data::Array attrvalue = attrvalues_mda[i];

processAttribute(attrname, attrvalue, attrs);
processAttribute(attrname, attrvalue, attrs);
}
auto record_attribute = [&](const std::pair<std::string, common::AttributeValue> attr)
{rec->SetAttribute(attr.first, attr.second);};
std::for_each(attrs.Attributes.cbegin(), attrs.Attributes.cend(), record_attribute);
}
}
auto record_attribute = [&](const std::pair<std::string, common::AttributeValue> attr)
{rec->SetAttribute(attr.first, attr.second);};
std::for_each(attrs.Attributes.cbegin(), attrs.Attributes.cend(), record_attribute);
}
// Add size attribute if body is nonscalar
if (array_body) {
rec->SetAttribute(bodyattrs.Attributes.back().first, bodyattrs.Attributes.back().second);
}

CppLogger->EmitLogRecord(std::move(rec), static_cast<logs_api::Severity>(severity), log_body);
}
} // namespace libmexclass::opentelemetry
7 changes: 3 additions & 4 deletions api/trace/+opentelemetry/+trace/Span.m
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -45,16 +45,15 @@ function endSpan(obj, endtime)
%
% See also OPENTELEMETRY.TRACE.TRACER.STARTSPAN
if nargin < 2
endposixtime = NaN;
obj.Proxy.endSpan();
else
if ~(isdatetime(endtime) && isscalar(endtime) && ~isnat(endtime))
% invalid end time, ignore
endposixtime = NaN;
obj.Proxy.endSpan();
else
endposixtime = posixtime(endtime);
obj.Proxy.endSpan(posixtime(endtime));
end
end
obj.Proxy.endSpan(endposixtime);
obj.Ended = true;
end

Expand Down
Loading