Add some ftrace tracepoints
They're handy for debugging timing issues.
Change-Id: I6d836a2d90aedff4a704e55eed7204203dd5a855
diff --git a/aos/events/BUILD b/aos/events/BUILD
index d35f206..39a6a54 100644
--- a/aos/events/BUILD
+++ b/aos/events/BUILD
@@ -74,6 +74,7 @@
"//aos:configuration",
"//aos:configuration_fbs",
"//aos:flatbuffers",
+ "//aos:ftrace",
"//aos/ipc_lib:data_alignment",
"//aos/logging:implementations",
"//aos/time",
diff --git a/aos/events/event_loop.cc b/aos/events/event_loop.cc
index c03425e..da89d9b 100644
--- a/aos/events/event_loop.cc
+++ b/aos/events/event_loop.cc
@@ -14,6 +14,7 @@
RawSender::RawSender(EventLoop *event_loop, const Channel *channel)
: event_loop_(event_loop),
channel_(channel),
+ ftrace_prefix_(configuration::StrippedChannelToString(channel)),
timing_(event_loop_->ChannelIndex(channel)) {
event_loop_->NewSender(this);
}
@@ -23,6 +24,7 @@
RawFetcher::RawFetcher(EventLoop *event_loop, const Channel *channel)
: event_loop_(event_loop),
channel_(channel),
+ ftrace_prefix_(configuration::StrippedChannelToString(channel)),
timing_(event_loop_->ChannelIndex(channel)) {
context_.monotonic_event_time = monotonic_clock::min_time;
context_.monotonic_remote_time = monotonic_clock::min_time;
diff --git a/aos/events/event_loop.h b/aos/events/event_loop.h
index 7634479..454b976 100644
--- a/aos/events/event_loop.h
+++ b/aos/events/event_loop.h
@@ -14,6 +14,7 @@
#include "aos/events/event_loop_generated.h"
#include "aos/events/timing_statistics.h"
#include "aos/flatbuffers.h"
+#include "aos/ftrace.h"
#include "aos/ipc_lib/data_alignment.h"
#include "aos/json_to_flatbuffer.h"
#include "aos/time/time.h"
@@ -92,10 +93,12 @@
virtual std::pair<bool, monotonic_clock::time_point> DoFetchNext() = 0;
virtual std::pair<bool, monotonic_clock::time_point> DoFetch() = 0;
- EventLoop *event_loop_;
- const Channel *channel_;
+ EventLoop *const event_loop_;
+ const Channel *const channel_;
+ const std::string ftrace_prefix_;
internal::RawFetcherTiming timing_;
+ Ftrace ftrace_;
};
// Raw version of sender. Sends a block of data. This is used for reflection
@@ -174,10 +177,12 @@
aos::realtime_clock::time_point realtime_remote_time,
uint32_t remote_queue_index) = 0;
- EventLoop *event_loop_;
- const Channel *channel_;
+ EventLoop *const event_loop_;
+ const Channel *const channel_;
+ const std::string ftrace_prefix_;
internal::RawSenderTiming timing_;
+ Ftrace ftrace_;
ChannelPreallocatedAllocator fbb_allocator_{nullptr, 0, nullptr};
};
@@ -358,6 +363,7 @@
std::string name_;
internal::TimerTiming timing_;
+ Ftrace ftrace_;
};
// Interface for phased loops. They are built on timers.
@@ -404,6 +410,7 @@
int cycles_elapsed_ = 0;
internal::TimerTiming timing_;
+ Ftrace ftrace_;
};
inline cpu_set_t MakeCpusetFromCpus(std::initializer_list<int> cpus) {
diff --git a/aos/events/event_loop_tmpl.h b/aos/events/event_loop_tmpl.h
index 5534c83..877a946 100644
--- a/aos/events/event_loop_tmpl.h
+++ b/aos/events/event_loop_tmpl.h
@@ -1,7 +1,11 @@
#ifndef AOS_EVENTS_EVENT_LOOP_TMPL_H_
#define AOS_EVENTS_EVENT_LOOP_TMPL_H_
+#include <inttypes.h>
+#include <stdint.h>
+
#include <type_traits>
+
#include "aos/events/event_loop.h"
#include "glog/logging.h"
@@ -72,6 +76,13 @@
if (result.first) {
timing_.fetcher->mutate_count(timing_.fetcher->count() + 1);
const monotonic_clock::time_point monotonic_time = result.second;
+ ftrace_.FormatMessage(
+ "%.*s: fetch next: now=%" PRId64 " event=%" PRId64 " queue=%" PRIu32,
+ static_cast<int>(ftrace_prefix_.size()), ftrace_prefix_.data(),
+ static_cast<int64_t>(monotonic_time.time_since_epoch().count()),
+ static_cast<int64_t>(
+ context_.monotonic_event_time.time_since_epoch().count()),
+ context_.queue_index);
const float latency =
std::chrono::duration_cast<std::chrono::duration<float>>(
monotonic_time - context_.monotonic_event_time)
@@ -79,6 +90,12 @@
timing_.latency.Add(latency);
return true;
}
+ ftrace_.FormatMessage(
+ "%.*s: fetch next: still event=%" PRId64 " queue=%" PRIu32,
+ static_cast<int>(ftrace_prefix_.size()), ftrace_prefix_.data(),
+ static_cast<int64_t>(
+ context_.monotonic_event_time.time_since_epoch().count()),
+ context_.queue_index);
return false;
}
@@ -87,6 +104,13 @@
if (result.first) {
timing_.fetcher->mutate_count(timing_.fetcher->count() + 1);
const monotonic_clock::time_point monotonic_time = result.second;
+ ftrace_.FormatMessage(
+ "%.*s: fetch latest: now=%" PRId64 " event=%" PRId64 " queue=%" PRIu32,
+ static_cast<int>(ftrace_prefix_.size()), ftrace_prefix_.data(),
+ static_cast<int64_t>(monotonic_time.time_since_epoch().count()),
+ static_cast<int64_t>(
+ context_.monotonic_event_time.time_since_epoch().count()),
+ context_.queue_index);
const float latency =
std::chrono::duration_cast<std::chrono::duration<float>>(
monotonic_time - context_.monotonic_event_time)
@@ -94,6 +118,12 @@
timing_.latency.Add(latency);
return true;
}
+ ftrace_.FormatMessage(
+ "%.*s: fetch latest: still event=%" PRId64 " queue=%" PRIu32,
+ static_cast<int>(ftrace_prefix_.size()), ftrace_prefix_.data(),
+ static_cast<int64_t>(
+ context_.monotonic_event_time.time_since_epoch().count()),
+ context_.queue_index);
return false;
}
@@ -105,6 +135,11 @@
remote_queue_index)) {
timing_.size.Add(size);
timing_.sender->mutate_count(timing_.sender->count() + 1);
+ ftrace_.FormatMessage(
+ "%.*s: sent internal: event=%" PRId64 " queue=%" PRIu32,
+ static_cast<int>(ftrace_prefix_.size()), ftrace_prefix_.data(),
+ static_cast<int64_t>(monotonic_sent_time().time_since_epoch().count()),
+ sent_queue_index());
return true;
}
return false;
@@ -119,6 +154,11 @@
remote_queue_index)) {
timing_.size.Add(size);
timing_.sender->mutate_count(timing_.sender->count() + 1);
+ ftrace_.FormatMessage(
+ "%.*s: sent external: event=%" PRId64 " queue=%" PRIu32,
+ static_cast<int>(ftrace_prefix_.size()), ftrace_prefix_.data(),
+ static_cast<int64_t>(monotonic_sent_time().time_since_epoch().count()),
+ sent_queue_index());
return true;
}
return false;
@@ -138,6 +178,11 @@
event_loop_->context_.size = 0;
event_loop_->context_.data = nullptr;
+ ftrace_.FormatMessage(
+ "timer: %.*s: start now=%" PRId64 " event=%" PRId64,
+ static_cast<int>(name_.size()), name_.data(),
+ static_cast<int64_t>(monotonic_start_time.time_since_epoch().count()),
+ static_cast<int64_t>(event_time.time_since_epoch().count()));
{
const float start_latency =
std::chrono::duration_cast<std::chrono::duration<float>>(
@@ -149,6 +194,10 @@
fn_();
const monotonic_clock::time_point monotonic_end_time = get_time();
+ ftrace_.FormatMessage(
+ "timer: %.*s: end now=%" PRId64, static_cast<int>(name_.size()),
+ name_.data(),
+ static_cast<int64_t>(monotonic_end_time.time_since_epoch().count()));
const float handler_latency =
std::chrono::duration_cast<std::chrono::duration<float>>(
@@ -176,6 +225,13 @@
// Compute how many cycles elapsed and schedule the next wakeup.
Reschedule(schedule, monotonic_start_time);
+ ftrace_.FormatMessage(
+ "phased: %.*s: start now=%" PRId64 " event=%" PRId64 " cycles=%d",
+ static_cast<int>(name_.size()), name_.data(),
+ static_cast<int64_t>(monotonic_start_time.time_since_epoch().count()),
+ static_cast<int64_t>(
+ phased_loop_.sleep_time().time_since_epoch().count()),
+ cycles_elapsed_);
{
const float start_latency =
std::chrono::duration_cast<std::chrono::duration<float>>(
@@ -190,6 +246,10 @@
cycles_elapsed_ = 0;
const monotonic_clock::time_point monotonic_end_time = get_time();
+ ftrace_.FormatMessage(
+ "phased: %.*s: end now=%" PRId64, static_cast<int>(name_.size()),
+ name_.data(),
+ static_cast<int64_t>(monotonic_end_time.time_since_epoch().count()));
const float handler_latency =
std::chrono::duration_cast<std::chrono::duration<float>>(
@@ -210,7 +270,9 @@
WatcherState(
EventLoop *event_loop, const Channel *channel,
std::function<void(const Context &context, const void *message)> fn)
- : channel_index_(event_loop->ChannelIndex(channel)), fn_(std::move(fn)) {}
+ : channel_index_(event_loop->ChannelIndex(channel)),
+ ftrace_prefix_(configuration::StrippedChannelToString(channel)),
+ fn_(std::move(fn)) {}
virtual ~WatcherState() {}
@@ -222,6 +284,13 @@
CheckChannelDataAlignment(context.data, context.size);
}
const monotonic_clock::time_point monotonic_start_time = get_time();
+ ftrace_.FormatMessage(
+ "%.*s: watcher start: now=%" PRId64 " event=%" PRId64 " queue=%" PRIu32,
+ static_cast<int>(ftrace_prefix_.size()), ftrace_prefix_.data(),
+ static_cast<int64_t>(monotonic_start_time.time_since_epoch().count()),
+ static_cast<int64_t>(
+ context.monotonic_event_time.time_since_epoch().count()),
+ context.queue_index);
{
const float start_latency =
std::chrono::duration_cast<std::chrono::duration<float>>(
@@ -233,6 +302,10 @@
fn_(context, context.data);
const monotonic_clock::time_point monotonic_end_time = get_time();
+ ftrace_.FormatMessage(
+ "%.*s: watcher end: now=%" PRId64,
+ static_cast<int>(ftrace_prefix_.size()), ftrace_prefix_.data(),
+ static_cast<int64_t>(monotonic_end_time.time_since_epoch().count()));
const float handler_latency =
std::chrono::duration_cast<std::chrono::duration<float>>(
@@ -250,12 +323,15 @@
protected:
const int channel_index_;
+ const std::string ftrace_prefix_;
- std::function<void(const Context &context, const void *message)> fn_;
+ const std::function<void(const Context &context, const void *message)> fn_;
internal::TimingStatistic wakeup_latency_;
internal::TimingStatistic handler_time_;
timing::Watcher *watcher_ = nullptr;
+
+ Ftrace ftrace_;
};
template <typename T>