blob: 279775e7c3257e99a65f854f0aa1171970949b4b [file] [log] [blame]
// Copyright 2018 The Fuchsia Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
#include "src/logger/logger.h"
#include <memory>
#include <string>
#include "google/protobuf/repeated_field.h"
#include "src/logger/event_loggers.h"
#include "src/logger/event_record.h"
#include "src/logging.h"
#include "src/public/lib/statusor/status_macros.h"
#include "src/registry/metric_definition.pb.h"
#include "src/registry/report_definition.pb.h"
namespace cobalt::logger {
using local_aggregation::EventAggregator;
using LoggerMethod = PerProjectLoggerCallsMadeMigratedMetricDimensionLoggerMethod;
namespace {
template <class EventType>
void CopyEventCodesAndComponent(const std::vector<uint32_t>& event_codes,
const std::string& component, EventType* event) {
for (auto event_code : event_codes) {
event->add_event_code(event_code);
}
event->set_component(component);
}
template <class EventType>
void CopyEventCodes(const std::vector<uint32_t>& event_codes, EventType* event) {
for (auto event_code : event_codes) {
event->add_event_code(event_code);
}
}
} // namespace
Logger::Logger(std::unique_ptr<ProjectContext> project_context, const Encoder& encoder,
EventAggregator& event_aggregator,
local_aggregation::LocalAggregation* local_aggregation,
ObservationWriter* observation_writer, system_data::SystemDataInterface* system_data,
util::CivilTimeConverterInterface* civil_time_converter,
std::vector<uint32_t> experiment_ids, bool enable_replacement_metrics,
InternalMetrics* internal_metrics)
: Logger(std::move(project_context), encoder, event_aggregator, local_aggregation,
observation_writer, system_data, nullptr, civil_time_converter,
std::weak_ptr<UndatedEventManager>(), std::move(experiment_ids),
enable_replacement_metrics, internal_metrics) {}
Logger::Logger(std::unique_ptr<ProjectContext> project_context, const Encoder& encoder,
EventAggregator& event_aggregator,
local_aggregation::LocalAggregation* local_aggregation,
ObservationWriter* observation_writer, system_data::SystemDataInterface* system_data,
util::ValidatedClockInterface* validated_clock,
util::CivilTimeConverterInterface* civil_time_converter,
std::weak_ptr<UndatedEventManager> undated_event_manager,
std::vector<uint32_t> experiment_ids, bool enable_replacement_metrics,
InternalMetrics* internal_metrics)
: project_context_(std::move(project_context)),
encoder_(encoder),
event_aggregator_(event_aggregator),
local_aggregation_(local_aggregation),
observation_writer_(observation_writer),
system_data_(system_data),
validated_clock_(validated_clock),
civil_time_converter_(civil_time_converter),
undated_event_manager_(std::move(undated_event_manager)),
experiment_ids_(std::move(experiment_ids)),
enable_replacement_metrics_(enable_replacement_metrics),
internal_metrics_(internal_metrics) {
CHECK(project_context_);
CHECK(local_aggregation_);
CHECK(observation_writer_);
CHECK(civil_time_converter_);
if (!validated_clock_) {
local_validated_clock_ =
std::make_unique<util::AlwaysAccurateClock>(std::make_unique<util::SystemClock>());
validated_clock_ = local_validated_clock_.get();
}
// If we were passed an internal Logger then we are not an internal Logger.
is_internal_logger_ = !internal_metrics;
Status status = event_aggregator_.UpdateAggregationConfigs(*project_context_);
if (!status.ok()) {
LOG(ERROR) << "Failed to provide aggregation configurations to the "
"EventAggregator. "
<< status;
}
}
// TODO(fxbug.dev/85571): NOLINTNEXTLINE(bugprone-easily-swappable-parameters)
Status Logger::LogEvent(uint32_t metric_id, uint32_t event_code) {
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
Status replacement_status = Status::OK;
if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) {
PauseInternalLogging();
CB_ASSIGN_OR_RETURN(auto replacement_event_record,
EventRecord::MakeEventRecord(
project_context_, event_record->metric()->replacement_metric_id()));
switch (replacement_event_record->metric()->metric_type()) {
case MetricDefinition::OCCURRENCE: {
replacement_status =
LogOccurrence(replacement_event_record->metric()->id(), 1, {event_code});
if (!replacement_status.ok()) {
LOG(WARNING) << "Failed to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
}
} break;
default:
replacement_status = Status(StatusCode::OUT_OF_RANGE, "Invalid metric");
LOG(WARNING) << "Unable to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
break;
}
ResumeInternalLogging();
}
internal_metrics_.LoggerCalled(LoggerMethod::LogEvent, project_context_->project());
auto* event_occurred_event = event_record->event()->mutable_event_occurred_event();
event_occurred_event->set_event_code(event_code);
Status status = Log(metric_id, MetricDefinition::EVENT_OCCURRED, std::move(event_record));
if (!replacement_status.ok()) {
return replacement_status;
}
return status;
}
Status Logger::LogEventCount(
uint32_t metric_id, const std::vector<uint32_t>& event_codes,
// TODO(fxbug.dev/85571): NOLINTNEXTLINE(bugprone-easily-swappable-parameters)
const std::string& component, int64_t period_duration_micros, uint32_t count) {
internal_metrics_.LoggerCalled(LoggerMethod::LogEventCount, project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
Status replacement_status = Status::OK;
if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) {
PauseInternalLogging();
CB_ASSIGN_OR_RETURN(auto replacement_event_record,
EventRecord::MakeEventRecord(
project_context_, event_record->metric()->replacement_metric_id()));
switch (replacement_event_record->metric()->metric_type()) {
case MetricDefinition::OCCURRENCE: {
replacement_status =
LogOccurrence(replacement_event_record->metric()->id(), count, event_codes);
if (!replacement_status.ok()) {
LOG(WARNING) << "Failed to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
}
} break;
case MetricDefinition::STRING: {
for (int i = 0; i < count; i++) {
replacement_status =
LogString(replacement_event_record->metric()->id(), component, event_codes);
if (!replacement_status.ok()) {
LOG(WARNING) << "Failed to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
}
}
} break;
case MetricDefinition::INTEGER: {
replacement_status =
LogInteger(replacement_event_record->metric()->id(), count, event_codes);
if (!replacement_status.ok()) {
LOG(WARNING) << "Failed to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
}
} break;
default:
replacement_status = Status(StatusCode::OUT_OF_RANGE, "Invalid metric");
LOG(WARNING) << "Unable to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
break;
}
ResumeInternalLogging();
}
auto* event_count_event = event_record->event()->mutable_event_count_event();
CopyEventCodesAndComponent(event_codes, component, event_count_event);
event_count_event->set_period_duration_micros(period_duration_micros);
event_count_event->set_count(count);
Status status = Log(metric_id, MetricDefinition::EVENT_COUNT, std::move(event_record));
if (!replacement_status.ok()) {
return replacement_status;
}
return status;
}
const int64_t kNanosecondsPerMicrosecond = 1000;
const int64_t kMicrosecondsPerMillisecond = 1000;
const int64_t kMicrosecondsPerSecond = kMicrosecondsPerMillisecond * 1000;
const int64_t kMicrosecondsPerMinute = kMicrosecondsPerSecond * 60;
Status Logger::LogElapsedTime(uint32_t metric_id, const std::vector<uint32_t>& event_codes,
const std::string& component, int64_t elapsed_micros) {
internal_metrics_.LoggerCalled(LoggerMethod::LogElapsedTime, project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
Status replacement_status = Status::OK;
if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) {
PauseInternalLogging();
CB_ASSIGN_OR_RETURN(auto replacement_event_record,
EventRecord::MakeEventRecord(
project_context_, event_record->metric()->replacement_metric_id()));
switch (replacement_event_record->metric()->metric_type()) {
case MetricDefinition::INTEGER: {
int64_t converted_value = 0;
switch (replacement_event_record->metric()->metric_units()) {
case cobalt::MetricUnits::NANOSECONDS:
converted_value = elapsed_micros * kNanosecondsPerMicrosecond;
break;
case cobalt::MetricUnits::MICROSECONDS:
converted_value = elapsed_micros;
break;
case cobalt::MetricUnits::MILLISECONDS:
converted_value = elapsed_micros / kMicrosecondsPerMillisecond;
break;
case cobalt::MetricUnits::SECONDS:
converted_value = elapsed_micros / kMicrosecondsPerSecond;
break;
case cobalt::MetricUnits::MINUTES:
converted_value = elapsed_micros / kMicrosecondsPerMinute;
break;
default:
// We can't reasonably convert this value, so we use the original value.
converted_value = elapsed_micros;
break;
}
replacement_status =
LogInteger(replacement_event_record->metric()->id(), converted_value, event_codes);
if (!replacement_status.ok()) {
LOG(WARNING) << "Failed to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
}
} break;
default:
replacement_status = Status(StatusCode::OUT_OF_RANGE, "Invalid metric");
LOG(WARNING) << "Unable to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
break;
}
ResumeInternalLogging();
}
auto* elapsed_time_event = event_record->event()->mutable_elapsed_time_event();
CopyEventCodesAndComponent(event_codes, component, elapsed_time_event);
elapsed_time_event->set_elapsed_micros(elapsed_micros);
Status status = Log(metric_id, MetricDefinition::ELAPSED_TIME, std::move(event_record));
if (!replacement_status.ok()) {
return replacement_status;
}
return status;
}
Status Logger::LogFrameRate(uint32_t metric_id, const std::vector<uint32_t>& event_codes,
const std::string& component, float fps) {
internal_metrics_.LoggerCalled(LoggerMethod::LogFrameRate, project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
Status replacement_status = Status::OK;
if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) {
PauseInternalLogging();
CB_ASSIGN_OR_RETURN(auto replacement_event_record,
EventRecord::MakeEventRecord(
project_context_, event_record->metric()->replacement_metric_id()));
switch (replacement_event_record->metric()->metric_type()) {
case MetricDefinition::INTEGER: {
replacement_status = LogInteger(
replacement_event_record->metric()->id(),
static_cast<int64_t>(std::round(fps * 1000.0)), // NOLINT readability-magic-numbers
event_codes);
if (!replacement_status.ok()) {
LOG(WARNING) << "Failed to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
}
break;
}
default:
replacement_status = Status(StatusCode::OUT_OF_RANGE, "Invalid metric");
LOG(WARNING) << "Unable to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
break;
}
ResumeInternalLogging();
}
auto* frame_rate_event = event_record->event()->mutable_frame_rate_event();
CopyEventCodesAndComponent(event_codes, component, frame_rate_event);
// NOLINTNEXTLINE readability-magic-numbers
frame_rate_event->set_frames_per_1000_seconds(std::round(fps * 1000.0));
Status status = Log(metric_id, MetricDefinition::FRAME_RATE, std::move(event_record));
if (!replacement_status.ok()) {
return replacement_status;
}
return status;
}
Status Logger::LogMemoryUsage(uint32_t metric_id, const std::vector<uint32_t>& event_codes,
const std::string& component, int64_t bytes) {
internal_metrics_.LoggerCalled(LoggerMethod::LogMemoryUsage, project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
Status replacement_status = Status::OK;
if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) {
PauseInternalLogging();
CB_ASSIGN_OR_RETURN(auto replacement_event_record,
EventRecord::MakeEventRecord(
project_context_, event_record->metric()->replacement_metric_id()));
switch (replacement_event_record->metric()->metric_type()) {
case MetricDefinition::INTEGER: {
replacement_status =
LogInteger(replacement_event_record->metric()->id(), bytes, event_codes);
if (!replacement_status.ok()) {
LOG(WARNING) << "Failed to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
}
break;
}
default:
replacement_status = Status(StatusCode::OUT_OF_RANGE, "Invalid metric");
LOG(WARNING) << "Unable to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
break;
}
ResumeInternalLogging();
}
auto* memory_usage_event = event_record->event()->mutable_memory_usage_event();
CopyEventCodesAndComponent(event_codes, component, memory_usage_event);
memory_usage_event->set_bytes(bytes);
Status status = Log(metric_id, MetricDefinition::MEMORY_USAGE, std::move(event_record));
if (!replacement_status.ok()) {
return replacement_status;
}
return status;
}
Status Logger::LogIntHistogram(uint32_t metric_id, const std::vector<uint32_t>& event_codes,
const std::string& component, HistogramPtr histogram) {
internal_metrics_.LoggerCalled(LoggerMethod::LogIntHistogram, project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
Status replacement_status = Status::OK;
if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) {
PauseInternalLogging();
CB_ASSIGN_OR_RETURN(auto replacement_event_record,
EventRecord::MakeEventRecord(
project_context_, event_record->metric()->replacement_metric_id()));
switch (replacement_event_record->metric()->metric_type()) {
case MetricDefinition::INTEGER_HISTOGRAM: {
auto histogram_copy =
std::make_unique<google::protobuf::RepeatedPtrField<cobalt::HistogramBucket>>();
histogram_copy->CopyFrom(*histogram.get());
replacement_status = LogIntegerHistogram(replacement_event_record->metric()->id(),
std::move(histogram_copy), event_codes);
if (!replacement_status.ok()) {
LOG(WARNING) << "Failed to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
}
break;
}
default:
replacement_status = Status(StatusCode::OUT_OF_RANGE, "Invalid metric");
LOG(WARNING) << "Unable to log replacement metric "
<< replacement_event_record->FullMetricName() << " for metric "
<< event_record->FullMetricName() << ": " << replacement_status;
break;
}
ResumeInternalLogging();
}
auto* int_histogram_event = event_record->event()->mutable_int_histogram_event();
CopyEventCodesAndComponent(event_codes, component, int_histogram_event);
int_histogram_event->mutable_buckets()->Swap(histogram.get());
Status status = Log(metric_id, MetricDefinition::INT_HISTOGRAM, std::move(event_record));
if (!replacement_status.ok()) {
return replacement_status;
}
return status;
}
// TODO(fxbug.dev/85571): NOLINTNEXTLINE(bugprone-easily-swappable-parameters)
Status Logger::LogOccurrence(uint32_t metric_id, uint64_t count,
const std::vector<uint32_t>& event_codes) {
internal_metrics_.LoggerCalled(LoggerMethod::LogOccurrence, project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
OccurrenceEvent* occurrence_event = event_record->event()->mutable_occurrence_event();
CopyEventCodes(event_codes, occurrence_event);
occurrence_event->set_count(count);
return Log(metric_id, MetricDefinition::OCCURRENCE, std::move(event_record));
}
// TODO(fxbug.dev/85571): NOLINTNEXTLINE(bugprone-easily-swappable-parameters)
Status Logger::LogInteger(uint32_t metric_id, int64_t value,
const std::vector<uint32_t>& event_codes) {
internal_metrics_.LoggerCalled(LoggerMethod::LogInteger, project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
IntegerEvent* integer_event = event_record->event()->mutable_integer_event();
CopyEventCodes(event_codes, integer_event);
integer_event->set_value(value);
return Log(metric_id, MetricDefinition::INTEGER, std::move(event_record));
}
Status Logger::LogIntegerHistogram(uint32_t metric_id, HistogramPtr histogram,
const std::vector<uint32_t>& event_codes) {
internal_metrics_.LoggerCalled(LoggerMethod::LogIntegerHistogram, project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
IntegerHistogramEvent* integer_histogram_event =
event_record->event()->mutable_integer_histogram_event();
CopyEventCodes(event_codes, integer_histogram_event);
integer_histogram_event->mutable_buckets()->Swap(histogram.get());
return Log(metric_id, MetricDefinition::INTEGER_HISTOGRAM, std::move(event_record));
}
Status Logger::LogString(uint32_t metric_id, const std::string& string_value,
const std::vector<uint32_t>& event_codes) {
internal_metrics_.LoggerCalled(LoggerMethod::LogString, project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
StringEvent* string_event = event_record->event()->mutable_string_event();
CopyEventCodes(event_codes, string_event);
string_event->set_string_value(string_value);
return Log(metric_id, MetricDefinition::STRING, std::move(event_record));
}
Status Logger::LogCustomEvent(uint32_t metric_id, EventValuesPtr event_values) {
internal_metrics_.LoggerCalled(LoggerMethod::LogCustomEvent, project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
auto* custom_event = event_record->event()->mutable_custom_event();
custom_event->mutable_values()->swap(*event_values);
return Log(metric_id, MetricDefinition::CUSTOM, std::move(event_record));
}
Status Logger::LogSerializedCustomEvent(uint32_t metric_id,
std::unique_ptr<std::string> serialized_proto) {
internal_metrics_.LoggerCalled(LoggerMethod::LogSerializedCustomEvent,
project_context_->project());
CB_ASSIGN_OR_RETURN(auto event_record, EventRecord::MakeEventRecord(project_context_, metric_id));
auto* custom_event = event_record->event()->mutable_custom_event();
custom_event->mutable_serialized_proto()->swap(*serialized_proto);
return Log(metric_id, MetricDefinition::CUSTOM, std::move(event_record));
}
Status Logger::Log(uint32_t metric_id, MetricDefinition::MetricType metric_type,
std::unique_ptr<EventRecord> event_record) {
// For Cobalt 1.1 Local Aggregation, the SystemProfile must be included with the event.
if (metric_type == MetricDefinition::OCCURRENCE || metric_type == MetricDefinition::INTEGER ||
metric_type == MetricDefinition::INTEGER_HISTOGRAM ||
metric_type == MetricDefinition::STRING) {
// Get the current unfiltered global system profile to log with this event.
event_record->system_profile()->CopyFrom(system_data_->system_profile());
// Add any non-global system profile data to the event's system profile.
for (const uint32_t& id : experiment_ids_) {
event_record->system_profile()->add_experiment_ids(id);
}
}
const int kVerboseLoggingLevel = (is_internal_logger_ ? 9 : 7);
VLOG(kVerboseLoggingLevel) << "Received logged event for " << event_record->FullMetricName();
auto event_logger =
internal::EventLogger::Create(metric_type, encoder_, event_aggregator_, local_aggregation_,
observation_writer_, system_data_, civil_time_converter_);
Status validation_result =
event_logger->PrepareAndValidateEvent(metric_id, metric_type, event_record.get());
if (!validation_result.ok()) {
return validation_result;
}
auto now = validated_clock_->now();
if (!now) {
VLOG(kVerboseLoggingLevel)
<< "Buffering logged event because we don't yet have an accurate clock. ";
// Missing system time means that the clock is not valid, so save the event until it is.
auto undated_event_manager = undated_event_manager_.lock();
if (undated_event_manager) {
return undated_event_manager->Save(std::move(event_record));
}
// A missing UndatedEventManager is handled by retrying the clock, which should now be valid.
// If we fall through to here, then a race condition has occurred in which the clock that we
// thought was not validated, has become validated. Retrying the clock should succeed.
now = validated_clock_->now();
if (!now) {
// This should never happen, if it does then it's a bug.
return util::StatusBuilder(
StatusCode::FAILED_PRECONDITION,
"Clock is invalid but there is no UndatedEventManager that will save the "
"event, dropping event for metric: ")
.AppendMsg(metric_id)
.LogError()
.Build();
}
}
Status result = event_logger->Log(std::move(event_record), *now);
// Flush queued internal metrics.
internal_metrics_.Flush();
return result;
}
void Logger::PauseInternalLogging() { internal_metrics_.PauseLogging(); }
void Logger::ResumeInternalLogging() { internal_metrics_.ResumeLogging(); }
} // namespace cobalt::logger