trace_processor: fix up sqlstats table (and time reported in shell)
Make the new iterator API work with the sqlstats table by splitting
the time_ended column into a "first next" column (which reports the
time to the first Next call on the iterator) and the actual end column
when the iterator is destroyed.
Also fix a subtle issue in trace processor interactive mode reporting
negative execution time.
Bug: 131627868
Change-Id: I24edb5576d9603bf004d61a83307022dfe16f43a
diff --git a/include/perfetto/trace_processor/trace_processor.h b/include/perfetto/trace_processor/trace_processor.h
index e6751e8..13be4dd 100644
--- a/include/perfetto/trace_processor/trace_processor.h
+++ b/include/perfetto/trace_processor/trace_processor.h
@@ -95,7 +95,8 @@
// Executes a SQLite query on the loaded portion of the trace. The returned
// iterator can be used to load rows from the result.
- virtual Iterator ExecuteQuery(const std::string& sql) = 0;
+ virtual Iterator ExecuteQuery(const std::string& sql,
+ int64_t time_queued = 0) = 0;
// Computes the given metrics on the loded portion of the trace. If
// successful, the output argument |metrics_proto| will be filled with the
diff --git a/src/trace_processor/sql_stats_table.cc b/src/trace_processor/sql_stats_table.cc
index d9bef3d..25e4a17 100644
--- a/src/trace_processor/sql_stats_table.cc
+++ b/src/trace_processor/sql_stats_table.cc
@@ -41,6 +41,8 @@
Table::Column(Column::kQuery, "query", ColumnType::kString),
Table::Column(Column::kTimeQueued, "queued", ColumnType::kLong),
Table::Column(Column::kTimeStarted, "started", ColumnType::kLong),
+ Table::Column(Column::kTimeFirstNext, "first_next",
+ ColumnType::kLong),
Table::Column(Column::kTimeEnded, "ended", ColumnType::kLong),
},
{Column::kTimeQueued});
@@ -83,16 +85,16 @@
sqlite_utils::kSqliteStatic);
break;
case Column::kTimeQueued:
- sqlite3_result_int64(context,
- static_cast<int64_t>(stats.times_queued()[row_]));
+ sqlite3_result_int64(context, stats.times_queued()[row_]);
break;
case Column::kTimeStarted:
- sqlite3_result_int64(context,
- static_cast<int64_t>(stats.times_started()[row_]));
+ sqlite3_result_int64(context, stats.times_started()[row_]);
+ break;
+ case Column::kTimeFirstNext:
+ sqlite3_result_int64(context, stats.times_first_next()[row_]);
break;
case Column::kTimeEnded:
- sqlite3_result_int64(context,
- static_cast<int64_t>(stats.times_ended()[row_]));
+ sqlite3_result_int64(context, stats.times_ended()[row_]);
break;
}
return SQLITE_OK;
diff --git a/src/trace_processor/sql_stats_table.h b/src/trace_processor/sql_stats_table.h
index 4544ed4..ebbe120 100644
--- a/src/trace_processor/sql_stats_table.h
+++ b/src/trace_processor/sql_stats_table.h
@@ -36,7 +36,8 @@
kQuery = 0,
kTimeQueued = 1,
kTimeStarted = 2,
- kTimeEnded = 3,
+ kTimeFirstNext = 3,
+ kTimeEnded = 4,
};
// Implementation of the SQLite cursor interface.
diff --git a/src/trace_processor/trace_processor_impl.cc b/src/trace_processor/trace_processor_impl.cc
index 0f1e3b8..08cc5bd 100644
--- a/src/trace_processor/trace_processor_impl.cc
+++ b/src/trace_processor/trace_processor_impl.cc
@@ -295,7 +295,8 @@
}
TraceProcessor::Iterator TraceProcessorImpl::ExecuteQuery(
- const std::string& sql) {
+ const std::string& sql,
+ int64_t time_queued) {
sqlite3_stmt* raw_stmt;
int err = sqlite3_prepare_v2(*db_, sql.c_str(), static_cast<int>(sql.size()),
&raw_stmt, nullptr);
@@ -306,8 +307,14 @@
} else {
col_count = static_cast<uint32_t>(sqlite3_column_count(raw_stmt));
}
- std::unique_ptr<IteratorImpl> impl(
- new IteratorImpl(this, *db_, ScopedStmt(raw_stmt), col_count, error));
+
+ base::TimeNanos t_start = base::GetWallTimeNs();
+ uint32_t sql_stats_row =
+ context_.storage->mutable_sql_stats()->RecordQueryBegin(sql, time_queued,
+ t_start.count());
+
+ std::unique_ptr<IteratorImpl> impl(new IteratorImpl(
+ this, *db_, ScopedStmt(raw_stmt), col_count, error, sql_stats_row));
iterators_.emplace_back(impl.get());
return TraceProcessor::Iterator(std::move(impl));
}
@@ -330,12 +337,14 @@
sqlite3* db,
ScopedStmt stmt,
uint32_t column_count,
- base::Optional<std::string> error)
+ base::Optional<std::string> error,
+ uint32_t sql_stats_row)
: trace_processor_(trace_processor),
db_(db),
stmt_(std::move(stmt)),
column_count_(column_count),
- error_(error) {}
+ error_(error),
+ sql_stats_row_(sql_stats_row) {}
TraceProcessor::IteratorImpl::~IteratorImpl() {
if (trace_processor_) {
@@ -343,11 +352,21 @@
auto it = std::find(its->begin(), its->end(), this);
PERFETTO_CHECK(it != its->end());
its->erase(it);
+
+ base::TimeNanos t_end = base::GetWallTimeNs();
+ auto* sql_stats = trace_processor_->context_.storage->mutable_sql_stats();
+ sql_stats->RecordQueryEnd(sql_stats_row_, t_end.count());
}
}
void TraceProcessor::IteratorImpl::Reset() {
- *this = IteratorImpl(nullptr, nullptr, ScopedStmt(), 0, base::nullopt);
+ *this = IteratorImpl(nullptr, nullptr, ScopedStmt(), 0, base::nullopt, 0);
+}
+
+void TraceProcessor::IteratorImpl::RecordFirstNextInSqlStats() {
+ base::TimeNanos t_first_next = base::GetWallTimeNs();
+ auto* sql_stats = trace_processor_->context_.storage->mutable_sql_stats();
+ sql_stats->RecordQueryFirstNext(sql_stats_row_, t_first_next.count());
}
} // namespace trace_processor
diff --git a/src/trace_processor/trace_processor_impl.h b/src/trace_processor/trace_processor_impl.h
index fcab0e5..57449a8 100644
--- a/src/trace_processor/trace_processor_impl.h
+++ b/src/trace_processor/trace_processor_impl.h
@@ -59,7 +59,8 @@
void NotifyEndOfFile() override;
- Iterator ExecuteQuery(const std::string& sql) override;
+ Iterator ExecuteQuery(const std::string& sql,
+ int64_t time_queued = 0) override;
int ComputeMetric(const std::vector<std::string>& metric_names,
std::vector<uint8_t>* metrics) override;
@@ -90,7 +91,8 @@
sqlite3* db,
ScopedStmt,
uint32_t column_count,
- base::Optional<std::string> error);
+ base::Optional<std::string> error,
+ uint32_t sql_stats_row);
~IteratorImpl();
IteratorImpl(IteratorImpl&) noexcept = delete;
@@ -101,6 +103,13 @@
// Methods called by TraceProcessor::Iterator.
bool Next() {
+ // Delegate to the cc file to prevent trace_storage.h include in this
+ // file.
+ if (!called_next_) {
+ RecordFirstNextInSqlStats();
+ called_next_ = true;
+ }
+
if (PERFETTO_UNLIKELY(error_.has_value()))
return false;
@@ -149,11 +158,16 @@
void Reset();
private:
+ void RecordFirstNextInSqlStats();
+
TraceProcessorImpl* trace_processor_;
sqlite3* db_ = nullptr;
ScopedStmt stmt_;
uint32_t column_count_ = 0;
base::Optional<std::string> error_;
+
+ uint32_t sql_stats_row_ = 0;
+ bool called_next_ = false;
};
} // namespace trace_processor
diff --git a/src/trace_processor/trace_processor_shell.cc b/src/trace_processor/trace_processor_shell.cc
index 05215e4..c7d374b 100644
--- a/src/trace_processor/trace_processor_shell.cc
+++ b/src/trace_processor/trace_processor_shell.cc
@@ -265,7 +265,7 @@
if (input[0] == 'q')
break;
} else {
- t_end = base::GetWallTimeMs();
+ t_end = base::GetWallTimeNs();
}
for (uint32_t i = 0; i < it->ColumnCount(); i++)
printf("%20s ", it->GetColumName(i).c_str());
diff --git a/src/trace_processor/trace_storage.cc b/src/trace_processor/trace_storage.cc
index ee09777..a0892b4 100644
--- a/src/trace_processor/trace_storage.cc
+++ b/src/trace_processor/trace_storage.cc
@@ -71,25 +71,44 @@
*this = TraceStorage();
}
-void TraceStorage::SqlStats::RecordQueryBegin(const std::string& query,
- int64_t time_queued,
- int64_t time_started) {
+uint32_t TraceStorage::SqlStats::RecordQueryBegin(const std::string& query,
+ int64_t time_queued,
+ int64_t time_started) {
if (queries_.size() >= kMaxLogEntries) {
queries_.pop_front();
times_queued_.pop_front();
times_started_.pop_front();
+ times_first_next_.pop_front();
times_ended_.pop_front();
+ popped_queries_++;
}
queries_.push_back(query);
times_queued_.push_back(time_queued);
times_started_.push_back(time_started);
+ times_first_next_.push_back(0);
times_ended_.push_back(0);
+ return static_cast<uint32_t>(popped_queries_ + queries_.size() - 1);
}
-void TraceStorage::SqlStats::RecordQueryEnd(int64_t time_ended) {
- PERFETTO_DCHECK(!times_ended_.empty());
- PERFETTO_DCHECK(times_ended_.back() == 0);
- times_ended_.back() = time_ended;
+void TraceStorage::SqlStats::RecordQueryFirstNext(uint32_t row,
+ int64_t time_first_next) {
+ // This means we've popped this query off the queue of queries before it had
+ // a chance to finish. Just silently drop this number.
+ if (popped_queries_ > row)
+ return;
+ uint32_t queue_row = row - popped_queries_;
+ PERFETTO_DCHECK(queue_row < queries_.size());
+ times_first_next_[queue_row] = time_first_next;
+}
+
+void TraceStorage::SqlStats::RecordQueryEnd(uint32_t row, int64_t time_ended) {
+ // This means we've popped this query off the queue of queries before it had
+ // a chance to finish. Just silently drop this number.
+ if (popped_queries_ > row)
+ return;
+ uint32_t queue_row = row - popped_queries_;
+ PERFETTO_DCHECK(queue_row < queries_.size());
+ times_ended_[queue_row] = time_ended;
}
std::pair<int64_t, int64_t> TraceStorage::GetTraceTimestampBoundsNs() const {
diff --git a/src/trace_processor/trace_storage.h b/src/trace_processor/trace_storage.h
index 47366e1..f6f687a 100644
--- a/src/trace_processor/trace_storage.h
+++ b/src/trace_processor/trace_storage.h
@@ -443,20 +443,27 @@
class SqlStats {
public:
static constexpr size_t kMaxLogEntries = 100;
- void RecordQueryBegin(const std::string& query,
- int64_t time_queued,
- int64_t time_started);
- void RecordQueryEnd(int64_t time_ended);
+ uint32_t RecordQueryBegin(const std::string& query,
+ int64_t time_queued,
+ int64_t time_started);
+ void RecordQueryFirstNext(uint32_t row, int64_t time_first_next);
+ void RecordQueryEnd(uint32_t row, int64_t time_end);
size_t size() const { return queries_.size(); }
const std::deque<std::string>& queries() const { return queries_; }
const std::deque<int64_t>& times_queued() const { return times_queued_; }
const std::deque<int64_t>& times_started() const { return times_started_; }
+ const std::deque<int64_t>& times_first_next() const {
+ return times_first_next_;
+ }
const std::deque<int64_t>& times_ended() const { return times_ended_; }
private:
+ uint32_t popped_queries_ = 0;
+
std::deque<std::string> queries_;
std::deque<int64_t> times_queued_;
std::deque<int64_t> times_started_;
+ std::deque<int64_t> times_first_next_;
std::deque<int64_t> times_ended_;
};