| // 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/logger/status.h" |
| #include "src/logging.h" |
| #include "src/registry/metric_definition.pb.h" |
| #include "src/registry/report_definition.pb.h" |
| |
| namespace cobalt::logger { |
| |
| using local_aggregation::EventAggregator; |
| |
| using LoggerMethod = PerProjectLoggerCallsMadeMetricDimensionLoggerMethod; |
| |
| 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, |
| bool enable_replacement_metrics, InternalMetrics* internal_metrics) |
| : Logger(std::move(project_context), encoder, event_aggregator, local_aggregation, |
| observation_writer, system_data, nullptr, std::weak_ptr<UndatedEventManager>(), |
| 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, |
| std::weak_ptr<UndatedEventManager> undated_event_manager, |
| 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), |
| undated_event_manager_(std::move(undated_event_manager)), |
| enable_replacement_metrics_(enable_replacement_metrics), |
| internal_metrics_(internal_metrics) { |
| CHECK(project_context_); |
| CHECK(encoder_); |
| CHECK(event_aggregator_); |
| CHECK(local_aggregation_); |
| CHECK(observation_writer_); |
| 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; |
| if (event_aggregator_->UpdateAggregationConfigs(*project_context_) != kOK) { |
| LOG(ERROR) << "Failed to provide aggregation configurations to the " |
| "EventAggregator."; |
| } |
| } |
| |
| Status Logger::LogEvent(uint32_t metric_id, uint32_t event_code) { |
| auto event_record = std::make_unique<EventRecord>(project_context_, metric_id); |
| Status replacement_status = kOK; |
| if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) { |
| PauseInternalLogging(); |
| auto replacement_event_record = std::make_unique<EventRecord>( |
| 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 != kOK) { |
| LOG(WARNING) << "Failed to log replacement metric " |
| << replacement_event_record->FullMetricName() << " for metric " |
| << event_record->FullMetricName() << ": " << replacement_status; |
| } |
| } break; |
| default: |
| replacement_status = kInvalidConfig; |
| 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 != kOK) { |
| return replacement_status; |
| } |
| return status; |
| } |
| |
| Status Logger::LogEventCount(uint32_t metric_id, const std::vector<uint32_t>& event_codes, |
| const std::string& component, int64_t period_duration_micros, |
| uint32_t count) { |
| internal_metrics_.LoggerCalled(LoggerMethod::LogEventCount, project_context_->project()); |
| auto event_record = std::make_unique<EventRecord>(project_context_, metric_id); |
| Status replacement_status = kOK; |
| if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) { |
| PauseInternalLogging(); |
| auto replacement_event_record = std::make_unique<EventRecord>( |
| 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 != kOK) { |
| 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 != kOK) { |
| 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 != kOK) { |
| LOG(WARNING) << "Failed to log replacement metric " |
| << replacement_event_record->FullMetricName() << " for metric " |
| << event_record->FullMetricName() << ": " << replacement_status; |
| } |
| |
| } break; |
| default: |
| replacement_status = kInvalidConfig; |
| 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 != kOK) { |
| 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()); |
| auto event_record = std::make_unique<EventRecord>(project_context_, metric_id); |
| Status replacement_status = kOK; |
| if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) { |
| PauseInternalLogging(); |
| auto replacement_event_record = std::make_unique<EventRecord>( |
| 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 != kOK) { |
| LOG(WARNING) << "Failed to log replacement metric " |
| << replacement_event_record->FullMetricName() << " for metric " |
| << event_record->FullMetricName() << ": " << replacement_status; |
| } |
| } break; |
| default: |
| replacement_status = kInvalidConfig; |
| 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 != kOK) { |
| 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()); |
| auto event_record = std::make_unique<EventRecord>(project_context_, metric_id); |
| Status replacement_status = kOK; |
| if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) { |
| PauseInternalLogging(); |
| auto replacement_event_record = std::make_unique<EventRecord>( |
| project_context_, event_record->metric()->replacement_metric_id()); |
| switch (replacement_event_record->metric()->metric_type()) { |
| case MetricDefinition::INTEGER: { |
| replacement_status = |
| // NOLINTNEXTLINE readability-magic-numbers |
| LogInteger(replacement_event_record->metric()->id(), std::round(fps * 1000.0), |
| event_codes); |
| if (replacement_status != kOK) { |
| LOG(WARNING) << "Failed to log replacement metric " |
| << replacement_event_record->FullMetricName() << " for metric " |
| << event_record->FullMetricName() << ": " << replacement_status; |
| } |
| break; |
| } |
| default: |
| replacement_status = kInvalidConfig; |
| 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 != kOK) { |
| 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()); |
| auto event_record = std::make_unique<EventRecord>(project_context_, metric_id); |
| Status replacement_status = kOK; |
| if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) { |
| PauseInternalLogging(); |
| auto replacement_event_record = std::make_unique<EventRecord>( |
| 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 != kOK) { |
| LOG(WARNING) << "Failed to log replacement metric " |
| << replacement_event_record->FullMetricName() << " for metric " |
| << event_record->FullMetricName() << ": " << replacement_status; |
| } |
| break; |
| } |
| default: |
| replacement_status = kInvalidConfig; |
| 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 != kOK) { |
| 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()); |
| auto event_record = std::make_unique<EventRecord>(project_context_, metric_id); |
| Status replacement_status = kOK; |
| if (event_record->metric()->replacement_metric_id() != 0 && enable_replacement_metrics_) { |
| PauseInternalLogging(); |
| auto replacement_event_record = std::make_unique<EventRecord>( |
| 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 != kOK) { |
| LOG(WARNING) << "Failed to log replacement metric " |
| << replacement_event_record->FullMetricName() << " for metric " |
| << event_record->FullMetricName() << ": " << replacement_status; |
| } |
| break; |
| } |
| default: |
| replacement_status = kInvalidConfig; |
| 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 != kOK) { |
| return replacement_status; |
| } |
| return status; |
| } |
| |
| 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()); |
| auto event_record = std::make_unique<EventRecord>(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)); |
| } |
| |
| 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()); |
| auto event_record = std::make_unique<EventRecord>(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()); |
| auto event_record = std::make_unique<EventRecord>(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()); |
| auto event_record = std::make_unique<EventRecord>(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()); |
| auto event_record = std::make_unique<EventRecord>(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()); |
| auto event_record = std::make_unique<EventRecord>(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) { |
| 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_); |
| Status validation_result = |
| event_logger->PrepareAndValidateEvent(metric_id, metric_type, event_record.get()); |
| if (validation_result != kOK) { |
| 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. |
| LOG(ERROR) << "Clock is invalid but there is no UndatedEventManager that will save the " |
| "event, dropping event for metric: " |
| << metric_id; |
| return Status::kOther; |
| } |
| } |
| |
| 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 |
