Add some ftrace tracepoints
They're handy for debugging timing issues.
Change-Id: I6d836a2d90aedff4a704e55eed7204203dd5a855
diff --git a/aos/BUILD b/aos/BUILD
index da558a4..d35e74c 100644
--- a/aos/BUILD
+++ b/aos/BUILD
@@ -526,3 +526,17 @@
"@com_github_google_glog//:glog",
],
)
+
+cc_library(
+ name = "ftrace",
+ srcs = [
+ "ftrace.cc",
+ ],
+ hdrs = [
+ "ftrace.h",
+ ],
+ visibility = ["//visibility:public"],
+ deps = [
+ "@com_github_google_glog//:glog",
+ ],
+)
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>
diff --git a/aos/ftrace.cc b/aos/ftrace.cc
new file mode 100644
index 0000000..af4964c
--- /dev/null
+++ b/aos/ftrace.cc
@@ -0,0 +1,45 @@
+#include "aos/ftrace.h"
+
+#include <stdarg.h>
+#include <stdio.h>
+
+namespace aos {
+
+Ftrace::~Ftrace() {
+ if (message_fd_ != -1) {
+ PCHECK(close(message_fd_) == 0);
+ }
+ if (message_fd_ != -1) {
+ PCHECK(close(on_fd_) == 0);
+ }
+}
+
+void Ftrace::FormatMessage(const char *format, ...) {
+ if (message_fd_ == -1) {
+ return;
+ }
+ char buffer[512];
+ va_list ap;
+ va_start(ap, format);
+ const int result = vsnprintf(buffer, sizeof(buffer), format, ap);
+ va_end(ap);
+ CHECK_LE(static_cast<size_t>(result), sizeof(buffer))
+ << ": Format string ended up too long: " << format;
+ WriteMessage(std::string_view(buffer, result));
+}
+
+void Ftrace::WriteMessage(std::string_view content) {
+ if (message_fd_ == -1) {
+ return;
+ }
+ const int result = write(message_fd_, content.data(), content.size());
+ if (result == -1 && errno == EBADF) {
+ // This just means tracing is turned off. Ignore it.
+ return;
+ }
+ PCHECK(result >= 0) << ": Failed to write ftrace message: " << content;
+ CHECK_EQ(static_cast<size_t>(result), content.size())
+ << ": Failed to write complete ftrace message: " << content;
+}
+
+} // namespace aos
diff --git a/aos/ftrace.h b/aos/ftrace.h
new file mode 100644
index 0000000..42147ad
--- /dev/null
+++ b/aos/ftrace.h
@@ -0,0 +1,51 @@
+#ifndef AOS_FTRACE_H_
+#define AOS_FTRACE_H_
+
+#include <fcntl.h>
+#include <sys/stat.h>
+#include <sys/types.h>
+#include <unistd.h>
+
+#include <string_view>
+
+#include "glog/logging.h"
+
+namespace aos {
+
+// Manages interacting with ftrace. Silently hides many errors, because they are
+// expected to occur when ftrace is not enabled, and we want calling code to
+// continue working in that case.
+class Ftrace {
+ public:
+ Ftrace()
+ : message_fd_(open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY)),
+ on_fd_(open("/sys/kernel/debug/tracing/tracing_on", O_WRONLY)) {}
+ ~Ftrace();
+
+ // Writes a message with a printf-style format.
+ //
+ // Silently does nothing if tracing is disabled.
+ void FormatMessage(const char *format, ...)
+ __attribute__((format(__printf__, 2, 3)));
+
+ // Writes a preformatted message.
+ //
+ // Silently does nothing if tracing is disabled.
+ void WriteMessage(std::string_view content);
+
+ // Turns tracing off, or CHECK-fails if tracing is inaccessible. Does nothing
+ // if tracing is currently available but off.
+ void TurnOffOrDie() {
+ CHECK(on_fd_ != -1)
+ << ": Failed to open tracing_on earlier, cannot turn off tracing";
+ char zero = '0';
+ CHECK_EQ(write(on_fd_, &zero, 1), 1) << ": Failed to turn tracing off";
+ }
+
+ private:
+ int message_fd_, on_fd_;
+};
+
+} // namespace aos
+
+#endif // AOS_FTRACE_H_