Merge "tp: rationalise metatracing across trace processor" into main

include/perfetto/trace_processor/metatrace_config.h

@@ -16,25 +16,46 @@
 #define INCLUDE_PERFETTO_TRACE_PROCESSOR_METATRACE_CONFIG_H_
 
 #include <cstddef>
+#include <cstdint>
 
 namespace perfetto {
 namespace trace_processor {
 namespace metatrace {
 
-enum MetatraceCategories {
-  TOPLEVEL = 1 << 0,
-  QUERY = 1 << 1,
-  FUNCTION = 1 << 2,
+enum MetatraceCategories : uint32_t {
+  // Category for low-frequency events which provide a high-level timeline of
+  // SQL query execution.
+  QUERY_TIMELINE = 1 << 0,
+
+  // Category for high-frequency events which provide details about SQL query
+  // execution.
+  QUERY_DETAILED = 1 << 1,
+
+  // Category for high-frequency events which provide details about SQL function
+  // calls.
+  FUNCTION_CALL = 1 << 2,
+
+  // Category for high-frequency events which provide details about the columnar
+  // database operations.
   DB = 1 << 3,
 
+  // Category for low-frequency events which provide a high-level timeline of
+  // SQL query execution.
+  API_TIMELINE = 1 << 4,
+
+  // Alias for turning off all other categories.
   NONE = 0,
-  ALL = TOPLEVEL | QUERY | FUNCTION | DB,
+
+  // Alias for turning on all other categories.
+  ALL = QUERY_TIMELINE | QUERY_DETAILED | FUNCTION_CALL | DB | API_TIMELINE,
 };
 
 struct MetatraceConfig {
   MetatraceConfig();
 
-  MetatraceCategories categories = MetatraceCategories::TOPLEVEL;
+  MetatraceCategories categories = static_cast<MetatraceCategories>(
+      MetatraceCategories::QUERY_TIMELINE | MetatraceCategories::API_TIMELINE);
+
   // Requested buffer size. The implemenation may choose to allocate a larger
   // buffer size for efficiency.
   size_t override_buffer_size = 0;

protos/perfetto/trace_processor/metatrace_categories.proto

@@ -22,16 +22,17 @@ package perfetto.protos;
 // Keep in sync with TraceProcessor::MetatraceCategories.
 enum MetatraceCategories {
   // 1 << 0.
-  TOPLEVEL = 1;
+  QUERY_TIMELINE = 1;
   // 1 << 1.
-  QUERY = 2;
+  QUERY_DETAILED = 2;
   // 1 << 2.
-  FUNCTION = 4;
+  FUNCTION_CALL = 4;
   // 1 << 3.
   DB = 8;
+  // 1 << 4.
+  API_TIMELINE = 16;
 
   // Aliases for common subsets.
   NONE = 0;
-  // TOPLEVEL | QUERY | FUNCTION
-  ALL = 15;
+  ALL = 31;
 }

src/trace_processor/metrics/metrics.cc

@@ -729,7 +729,7 @@ base::Status ComputeMetrics(PerfettoSqlEngine* engine,
     auto output_query =
         "SELECT * FROM " + sql_metric.output_table_name.value() + ";";
     PERFETTO_TP_TRACE(
-        metatrace::Category::QUERY, "COMPUTE_METRIC_QUERY",
+        metatrace::Category::QUERY_TIMELINE, "COMPUTE_METRIC_QUERY",
         [&](metatrace::Record* r) { r->AddArg("SQL", output_query); });
 
     auto it = engine->ExecuteUntilLastStatement(

src/trace_processor/perfetto_sql/engine/created_function.cc

@@ -320,7 +320,7 @@ class RecursiveCallUnroller {
   }
 
   base::Status Run(Memoizer::MemoizedArgs initial_args) {
-    PERFETTO_TP_TRACE(metatrace::Category::FUNCTION,
+    PERFETTO_TP_TRACE(metatrace::Category::FUNCTION_CALL,
                       "UNROLL_RECURSIVE_FUNCTION_CALL",
                       [&](metatrace::Record* r) {
                         r->AddArg("Function", prototype_.function_name);
@@ -336,8 +336,8 @@ class RecursiveCallUnroller {
         state_ = State::kComputingFirstPass;
         Memoizer::MemoizedArgs args = first_pass_.front();
 
-        PERFETTO_TP_TRACE(metatrace::Category::FUNCTION, "SQL_FUNCTION_CALL",
-                          [&](metatrace::Record* r) {
+        PERFETTO_TP_TRACE(metatrace::Category::FUNCTION_CALL,
+                          "SQL_FUNCTION_CALL", [&](metatrace::Record* r) {
                             r->AddArg("Function", prototype_.function_name);
                             r->AddArg("Type", "UnrollRecursiveCall_FirstPass");
                             r->AddArg("Arg 0", std::to_string(args));
@@ -352,7 +352,7 @@ class RecursiveCallUnroller {
       state_ = State::kComputingSecondPass;
       Memoizer::MemoizedArgs args = second_pass_.top();
 
-      PERFETTO_TP_TRACE(metatrace::Category::FUNCTION, "SQL_FUNCTION_CALL",
+      PERFETTO_TP_TRACE(metatrace::Category::FUNCTION_CALL, "SQL_FUNCTION_CALL",
                         [&](metatrace::Record* r) {
                           r->AddArg("Function", prototype_.function_name);
                           r->AddArg("Type", "UnrollRecursiveCall_SecondPass");
@@ -640,7 +640,7 @@ base::Status CreatedFunction::Run(CreatedFunction::Context* ctx,
   }
 
   PERFETTO_TP_TRACE(
-      metatrace::Category::FUNCTION, "SQL_FUNCTION_CALL",
+      metatrace::Category::FUNCTION_CALL, "SQL_FUNCTION_CALL",
       [state, argv](metatrace::Record* r) {
         r->AddArg("Function", state->prototype().function_name.c_str());
         for (uint32_t i = 0; i < state->prototype().arguments.size(); ++i) {

src/trace_processor/perfetto_sql/engine/perfetto_sql_engine.cc

@@ -250,7 +250,7 @@ PerfettoSqlEngine::ExecuteUntilLastStatement(SqlSource sql_source) {
     // Try to get SQLite to prepare the statement.
     std::optional<SqliteEngine::PreparedStatement> cur_stmt;
     {
-      PERFETTO_TP_TRACE(metatrace::Category::QUERY, "QUERY_PREPARE");
+      PERFETTO_TP_TRACE(metatrace::Category::QUERY_TIMELINE, "QUERY_PREPARE");
       auto stmt = engine_->PrepareStatement(std::move(*source));
       RETURN_IF_ERROR(stmt.status());
       cur_stmt = std::move(stmt);
@@ -265,9 +265,11 @@ PerfettoSqlEngine::ExecuteUntilLastStatement(SqlSource sql_source) {
     // the previous statement so we don't have two clashing statements (e.g.
     // SELECT * FROM v and DROP VIEW v) partially stepped into.
     if (res && !res->IsDone()) {
-      PERFETTO_TP_TRACE(metatrace::Category::QUERY, "STMT_STEP_UNTIL_DONE",
+      PERFETTO_TP_TRACE(metatrace::Category::QUERY_TIMELINE,
+                        "STMT_STEP_UNTIL_DONE",
                         [&res](metatrace::Record* record) {
-                          record->AddArg("SQL", res->expanded_sql());
+                          record->AddArg("Original SQL", res->original_sql());
+                          record->AddArg("Executed SQL", res->sql());
                         });
       while (res->Step()) {
       }
@@ -280,11 +282,14 @@ PerfettoSqlEngine::ExecuteUntilLastStatement(SqlSource sql_source) {
     // Step the newly prepared statement once. This is considered to be
     // "executing" the statement.
     {
-      PERFETTO_TP_TRACE(metatrace::Category::TOPLEVEL, "STMT_FIRST_STEP",
+      PERFETTO_TP_TRACE(metatrace::Category::QUERY_TIMELINE, "STMT_FIRST_STEP",
                         [&res](metatrace::Record* record) {
-                          record->AddArg("SQL", res->expanded_sql());
+                          record->AddArg("Original SQL", res->original_sql());
+                          record->AddArg("Executed SQL", res->sql());
                         });
-      PERFETTO_DLOG("Executing statement: %s", res->sql());
+      PERFETTO_DLOG("Executing statement");
+      PERFETTO_DLOG("Original SQL: %s", res->original_sql());
+      PERFETTO_DLOG("Executed SQL: %s", res->sql());
       res->Step();
       RETURN_IF_ERROR(res->status());
     }
@@ -438,8 +443,8 @@ base::Status PerfettoSqlEngine::ExecuteInclude(
     const PerfettoSqlParser::Include& include,
     const PerfettoSqlParser& parser) {
   std::string key = include.key;
-  PERFETTO_TP_TRACE(metatrace::Category::TOPLEVEL, "Import",
-                    [key](metatrace::Record* r) { r->AddArg("Import", key); });
+  PERFETTO_TP_TRACE(metatrace::Category::QUERY_TIMELINE, "Include",
+                    [key](metatrace::Record* r) { r->AddArg("Module", key); });
   std::string module_name = sql_modules::GetModuleName(key);
   auto module = FindModule(module_name);
   if (!module)

src/trace_processor/perfetto_sql/engine/runtime_table_function.cc

@@ -126,7 +126,7 @@ RuntimeTableFunction::Cursor::~Cursor() {
 base::Status RuntimeTableFunction::Cursor::Filter(const QueryConstraints& qc,
                                                   sqlite3_value** argv,
                                                   FilterHistory) {
-  PERFETTO_TP_TRACE(metatrace::Category::FUNCTION, "TABLE_FUNCTION_CALL",
+  PERFETTO_TP_TRACE(metatrace::Category::FUNCTION_CALL, "TABLE_FUNCTION_CALL",
                     [this](metatrace::Record* r) {
                       r->AddArg("Function",
                                 state_->prototype.function_name.c_str());

src/trace_processor/perfetto_sql/intrinsics/operators/span_join_operator.cc

@@ -404,7 +404,7 @@ SpanJoinOperatorTable::Cursor::~Cursor() = default;
 base::Status SpanJoinOperatorTable::Cursor::Filter(const QueryConstraints& qc,
                                                    sqlite3_value** argv,
                                                    FilterHistory) {
-  PERFETTO_TP_TRACE(metatrace::Category::QUERY, "SPAN_JOIN_XFILTER");
+  PERFETTO_TP_TRACE(metatrace::Category::QUERY_DETAILED, "SPAN_JOIN_XFILTER");
 
   bool t1_partitioned_mixed =
       t1_.definition()->IsPartitioned() &&

src/trace_processor/rpc/rpc.cc

@@ -132,14 +132,16 @@ using ProtoEnum = protos::pbzero::MetatraceCategories;
 TraceProcessor::MetatraceCategories MetatraceCategoriesToPublicEnum(
     ProtoEnum categories) {
   switch (categories) {
-    case ProtoEnum::TOPLEVEL:
-      return TraceProcessor::MetatraceCategories::TOPLEVEL;
-    case ProtoEnum::QUERY:
-      return TraceProcessor::MetatraceCategories::QUERY;
-    case ProtoEnum::FUNCTION:
-      return TraceProcessor::MetatraceCategories::FUNCTION;
+    case ProtoEnum::QUERY_TIMELINE:
+      return TraceProcessor::MetatraceCategories::QUERY_TIMELINE;
+    case ProtoEnum::QUERY_DETAILED:
+      return TraceProcessor::MetatraceCategories::QUERY_DETAILED;
+    case ProtoEnum::FUNCTION_CALL:
+      return TraceProcessor::MetatraceCategories::FUNCTION_CALL;
     case ProtoEnum::DB:
       return TraceProcessor::MetatraceCategories::DB;
+    case ProtoEnum::API_TIMELINE:
+      return TraceProcessor::MetatraceCategories::API_TIMELINE;
     case ProtoEnum::ALL:
       return TraceProcessor::MetatraceCategories::ALL;
     case ProtoEnum::NONE:
@@ -288,7 +290,7 @@ void Rpc::ParseRpcRequest(const uint8_t* data, size_t len) {
 
 util::Status Rpc::Parse(const uint8_t* data, size_t len) {
   PERFETTO_TP_TRACE(
-      metatrace::Category::TOPLEVEL, "RPC_PARSE",
+      metatrace::Category::API_TIMELINE, "RPC_PARSE",
       [&](metatrace::Record* r) { r->AddArg("length", std::to_string(len)); });
   if (eof_) {
     // Reset the trace processor state if another trace has been previously
@@ -310,7 +312,8 @@ util::Status Rpc::Parse(const uint8_t* data, size_t len) {
 }
 
 void Rpc::NotifyEndOfFile() {
-  PERFETTO_TP_TRACE(metatrace::Category::TOPLEVEL, "RPC_NOTIFY_END_OF_FILE");
+  PERFETTO_TP_TRACE(metatrace::Category::API_TIMELINE,
+                    "RPC_NOTIFY_END_OF_FILE");
 
   trace_processor_->NotifyEndOfFile();
   eof_ = true;
@@ -372,7 +375,7 @@ Iterator Rpc::QueryInternal(const uint8_t* args, size_t len) {
   protos::pbzero::QueryArgs::Decoder query(args, len);
   std::string sql = query.sql_query().ToStdString();
   PERFETTO_DLOG("[RPC] Query < %s", sql.c_str());
-  PERFETTO_TP_TRACE(metatrace::Category::TOPLEVEL, "RPC_QUERY",
+  PERFETTO_TP_TRACE(metatrace::Category::API_TIMELINE, "RPC_QUERY",
                     [&](metatrace::Record* r) {
                       r->AddArg("SQL", sql);
                       if (query.has_tag()) {
@@ -402,7 +405,7 @@ void Rpc::ComputeMetricInternal(const uint8_t* data,
     metric_names.emplace_back(it->as_std_string());
   }
 
-  PERFETTO_TP_TRACE(metatrace::Category::TOPLEVEL, "RPC_COMPUTE_METRIC",
+  PERFETTO_TP_TRACE(metatrace::Category::API_TIMELINE, "RPC_COMPUTE_METRIC",
                     [&](metatrace::Record* r) {
                       for (const auto& metric : metric_names) {
                         r->AddArg("Metric", metric);

src/trace_processor/sqlite/db_sqlite_table.cc

@@ -506,9 +506,9 @@ base::Status DbSqliteTable::Cursor::Filter(const QueryConstraints& qc,
       TryCacheCreateSortedTable(qc, history);
       break;
     case TableComputation::kTableFunction: {
-      PERFETTO_TP_TRACE(metatrace::Category::QUERY, "DYNAMIC_TABLE_GENERATE",
-                        [this](metatrace::Record* r) {
-                          r->AddArg("Table", db_sqlite_table_->name());
+      PERFETTO_TP_TRACE(metatrace::Category::QUERY_DETAILED,
+                        "TABLE_FUNCTION_CALL", [this](metatrace::Record* r) {
+                          r->AddArg("Name", db_sqlite_table_->name());
                         });
       // If we have a dynamically created table, regenerate the table based on
       // the new constraints.
@@ -530,7 +530,7 @@ base::Status DbSqliteTable::Cursor::Filter(const QueryConstraints& qc,
   }
 
   PERFETTO_TP_TRACE(
-      metatrace::Category::QUERY, "DB_TABLE_FILTER_AND_SORT",
+      metatrace::Category::QUERY_DETAILED, "DB_TABLE_FILTER_AND_SORT",
       [this](metatrace::Record* r) {
         const Table* source = SourceTable();
         r->AddArg("Table", db_sqlite_table_->name());

src/trace_processor/sqlite/sql_source.h

@@ -88,6 +88,9 @@ class SqlSource {
   // Returns the SQL string backing this SqlSource instance;
   const std::string& sql() const { return root_.rewritten_sql; }
 
+  // Returns the original SQL string backing this SqlSource instance;
+  const std::string& original_sql() const { return root_.original_sql; }
+
   // Returns whether this SqlSource has been rewritten.
   bool IsRewritten() const { return root_.IsRewritten(); }
 

src/trace_processor/sqlite/sqlite_engine.cc

@@ -131,7 +131,7 @@ SqliteEngine::~SqliteEngine() {
 }
 
 SqliteEngine::PreparedStatement SqliteEngine::PrepareStatement(SqlSource sql) {
-  PERFETTO_TP_TRACE(metatrace::Category::QUERY, "QUERY_PREPARE");
+  PERFETTO_TP_TRACE(metatrace::Category::QUERY_DETAILED, "QUERY_PREPARE");
   sqlite3_stmt* raw_stmt = nullptr;
   int err =
       sqlite3_prepare_v2(db_.get(), sql.sql().c_str(), -1, &raw_stmt, nullptr);
@@ -222,12 +222,15 @@ void SqliteEngine::OnSqliteTableDestroyed(const std::string& name) {
 
 SqliteEngine::PreparedStatement::PreparedStatement(ScopedStmt stmt,
                                                    SqlSource source)
-    : stmt_(std::move(stmt)), sql_source_(std::move(source)) {}
+    : stmt_(std::move(stmt)),
+      expanded_sql_(sqlite3_expanded_sql(stmt_.get())),
+      sql_source_(std::move(source)) {}
 
 bool SqliteEngine::PreparedStatement::Step() {
-  PERFETTO_TP_TRACE(metatrace::Category::QUERY, "STMT_STEP",
+  PERFETTO_TP_TRACE(metatrace::Category::QUERY_DETAILED, "STMT_STEP",
                     [this](metatrace::Record* record) {
-                      record->AddArg("SQL", expanded_sql());
+                      record->AddArg("Original SQL", original_sql());
+                      record->AddArg("Executed SQL", sql());
                     });
 
   // Now step once into |cur_stmt| so that when we prepare the next statment
@@ -251,14 +254,11 @@ bool SqliteEngine::PreparedStatement::IsDone() const {
   return !sqlite3_stmt_busy(stmt_.get());
 }
 
-const char* SqliteEngine::PreparedStatement::sql() const {
-  return sqlite3_sql(stmt_.get());
+const char* SqliteEngine::PreparedStatement::original_sql() const {
+  return sql_source_.original_sql().c_str();
 }
 
-const char* SqliteEngine::PreparedStatement::expanded_sql() {
-  if (!expanded_sql_) {
-    expanded_sql_.reset(sqlite3_expanded_sql(stmt_.get()));
-  }
+const char* SqliteEngine::PreparedStatement::sql() const {
   return expanded_sql_.get();
 }
 

src/trace_processor/sqlite/sqlite_engine.h

@@ -58,8 +58,8 @@ class SqliteEngine {
     bool Step();
     bool IsDone() const;
 
+    const char* original_sql() const;
     const char* sql() const;
-    const char* expanded_sql();
 
     const base::Status& status() const { return status_; }
     sqlite3_stmt* sqlite_stmt() const { return stmt_.get(); }
@@ -70,8 +70,8 @@ class SqliteEngine {
     explicit PreparedStatement(ScopedStmt, SqlSource);
 
     ScopedStmt stmt_;
-    SqlSource sql_source_;
     ScopedSqliteString expanded_sql_;
+    SqlSource sql_source_;
     base::Status status_ = base::OkStatus();
   };
 

src/trace_processor/sqlite/sqlite_table.cc

@@ -184,8 +184,8 @@ bool SqliteTable::ReadConstraints(int idxNum, const char* idxStr, int argc) {
     cache_hit = false;
   }
 
-  PERFETTO_TP_TRACE(metatrace::Category::QUERY, "SQLITE_TABLE_READ_CONSTRAINTS",
-                    [&](metatrace::Record* r) {
+  PERFETTO_TP_TRACE(metatrace::Category::QUERY_DETAILED,
+                    "SQLITE_TABLE_READ_CONSTRAINTS", [&](metatrace::Record* r) {
                       r->AddArg("cache_hit", std::to_string(cache_hit));
                       r->AddArg("name", name_);
                       WriteQueryConstraintsToMetatrace(r, qc_cache_, schema_);
@@ -412,7 +412,7 @@ int TypedSqliteTableBase::xBestIndex(sqlite3_vtab* t, sqlite3_index_info* idx) {
   }
 
   PERFETTO_TP_TRACE(
-      metatrace::Category::QUERY, "SQLITE_TABLE_BEST_INDEX",
+      metatrace::Category::QUERY_TIMELINE, "SQLITE_TABLE_BEST_INDEX",
       [&](metatrace::Record* r) {
         r->AddArg("name", table->name());
         WriteQueryConstraintsToMetatrace(r, qc, table->schema());

src/trace_processor/tp_metatrace.cc

@@ -24,15 +24,19 @@ namespace {
 
 using ProtoEnum = protos::pbzero::MetatraceCategories;
 ProtoEnum MetatraceCategoriesToProtoEnum(MetatraceCategories categories) {
+  // Note: these are intentionally chained ifs and not else-ifs as it's possible
+  // for multiple of these if statements to be true.
   ProtoEnum result = ProtoEnum::NONE;
-  if (categories & MetatraceCategories::TOPLEVEL)
-    result = static_cast<ProtoEnum>(result | ProtoEnum::TOPLEVEL);
-  if (categories & MetatraceCategories::FUNCTION)
-    result = static_cast<ProtoEnum>(result | ProtoEnum::FUNCTION);
-  if (categories & MetatraceCategories::QUERY)
-    result = static_cast<ProtoEnum>(result | ProtoEnum::QUERY);
+  if (categories & MetatraceCategories::QUERY_TIMELINE)
+    result = static_cast<ProtoEnum>(result | ProtoEnum::QUERY_TIMELINE);
+  if (categories & MetatraceCategories::FUNCTION_CALL)
+    result = static_cast<ProtoEnum>(result | ProtoEnum::FUNCTION_CALL);
+  if (categories & MetatraceCategories::QUERY_DETAILED)
+    result = static_cast<ProtoEnum>(result | ProtoEnum::QUERY_DETAILED);
   if (categories & MetatraceCategories::DB)
     result = static_cast<ProtoEnum>(result | ProtoEnum::DB);
+  if (categories & MetatraceCategories::API_TIMELINE)
+    result = static_cast<ProtoEnum>(result | ProtoEnum::API_TIMELINE);
   return result;
 }