[latency] New latency visualization tool (#36964)
Adds a build config - latent_see - that configures a module and some macros to allow recording of latency information through the stack and across threads. One can then use tools that understand the chromium event trace format (eg `ui.perfetto.dev`) to visualize the traces.
Closes #36964
COPYBARA_INTEGRATE_REVIEW=https://github.com/grpc/grpc/pull/36964 from ctiller:latent-see 2c109f9575
PiperOrigin-RevId: 647455107
pull/37081/head
Craig Tiller
11 months ago
committed by
Copybara-Service
parent
e7727bc223
commit
e1b61766fc
24 changed files with 509 additions and 1 deletions
@ -0,0 +1,10 @@ |
|||||||
|
Latent-see |
||||||
|
---------- |
||||||
|
|
||||||
|
This is a simple latency profiling tool. |
||||||
|
|
||||||
|
We record various timestamps throughout program execution, and then at exit format json |
||||||
|
to a file `latent_see.json` in the chrome event trace format. This format can be |
||||||
|
consumed by various tools (eg ui.perfetto.dev). |
||||||
|
|
||||||
|
Recording macros are documented in latent_see.h. |
||||||
@ -0,0 +1,113 @@ |
|||||||
|
// Copyright 2024 gRPC authors.
|
||||||
|
//
|
||||||
|
// Licensed under the Apache License, Version 2.0 (the "License");
|
||||||
|
// you may not use this file except in compliance with the License.
|
||||||
|
// You may obtain a copy of the License at
|
||||||
|
//
|
||||||
|
// http://www.apache.org/licenses/LICENSE-2.0
|
||||||
|
//
|
||||||
|
// Unless required by applicable law or agreed to in writing, software
|
||||||
|
// distributed under the License is distributed on an "AS IS" BASIS,
|
||||||
|
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||||
|
// See the License for the specific language governing permissions and
|
||||||
|
// limitations under the License.
|
||||||
|
|
||||||
|
#include "src/core/util/latent_see.h" |
||||||
|
|
||||||
|
#ifdef GRPC_ENABLE_LATENT_SEE |
||||||
|
#include <chrono> |
||||||
|
#include <cstdint> |
||||||
|
|
||||||
|
#include "absl/strings/str_cat.h" |
||||||
|
#include "absl/types/optional.h" |
||||||
|
|
||||||
|
namespace grpc_core { |
||||||
|
namespace latent_see { |
||||||
|
|
||||||
|
thread_local std::vector<Log::Event> Log::thread_events_; |
||||||
|
thread_local uint64_t Log::thread_id_ = Log::Get().next_thread_id_.fetch_add(1); |
||||||
|
std::atomic<uint64_t> Flow::next_flow_id_{1}; |
||||||
|
|
||||||
|
std::string Log::GenerateJson() { |
||||||
|
std::vector<RecordedEvent> events; |
||||||
|
for (auto& fragment : fragments_) { |
||||||
|
MutexLock lock(&fragment.mu); |
||||||
|
events.insert(events.end(), fragment.events.begin(), fragment.events.end()); |
||||||
|
} |
||||||
|
absl::optional<std::chrono::steady_clock::time_point> start_time; |
||||||
|
for (auto& event : events) { |
||||||
|
if (!start_time.has_value() || *start_time > event.event.timestamp) { |
||||||
|
start_time = event.event.timestamp; |
||||||
|
} |
||||||
|
} |
||||||
|
if (!start_time.has_value()) return "[]"; |
||||||
|
std::string json = "[\n"; |
||||||
|
bool first = true; |
||||||
|
for (const auto& event : events) { |
||||||
|
absl::string_view phase; |
||||||
|
bool has_id; |
||||||
|
switch (event.event.type) { |
||||||
|
case EventType::kBegin: |
||||||
|
phase = "B"; |
||||||
|
has_id = false; |
||||||
|
break; |
||||||
|
case EventType::kEnd: |
||||||
|
phase = "E"; |
||||||
|
has_id = false; |
||||||
|
break; |
||||||
|
case EventType::kFlowStart: |
||||||
|
phase = "s"; |
||||||
|
has_id = true; |
||||||
|
break; |
||||||
|
case EventType::kFlowEnd: |
||||||
|
phase = "f"; |
||||||
|
has_id = true; |
||||||
|
break; |
||||||
|
case EventType::kMark: |
||||||
|
phase = "i"; |
||||||
|
has_id = false; |
||||||
|
break; |
||||||
|
} |
||||||
|
if (!first) absl::StrAppend(&json, ",\n"); |
||||||
|
first = false; |
||||||
|
absl::StrAppend(&json, "{\"name\": ", event.event.metadata->name, |
||||||
|
", \"ph\": \"", phase, "\", \"ts\": ", |
||||||
|
std::chrono::duration<double, std::micro>( |
||||||
|
event.event.timestamp - *start_time) |
||||||
|
.count(), |
||||||
|
", \"pid\": 0, \"tid\": ", event.thread_id); |
||||||
|
if (has_id) { |
||||||
|
absl::StrAppend(&json, ", \"id\": ", event.event.id); |
||||||
|
} |
||||||
|
if (event.event.type == EventType::kFlowEnd) { |
||||||
|
absl::StrAppend(&json, ", \"bp\": \"e\""); |
||||||
|
} |
||||||
|
absl::StrAppend(&json, ", \"args\": {\"file\": \"", |
||||||
|
event.event.metadata->file, |
||||||
|
"\", \"line\": ", event.event.metadata->line, |
||||||
|
", \"batch\": ", event.batch_id, "}}"); |
||||||
|
} |
||||||
|
absl::StrAppend(&json, "\n]"); |
||||||
|
return json; |
||||||
|
} |
||||||
|
|
||||||
|
void Log::FlushThreadLog() { |
||||||
|
auto& thread_events = thread_events_; |
||||||
|
if (thread_events.empty()) return; |
||||||
|
auto& log = Get(); |
||||||
|
const auto batch_id = |
||||||
|
log.next_batch_id_.fetch_add(1, std::memory_order_relaxed); |
||||||
|
auto& fragment = log.fragments_.this_cpu(); |
||||||
|
const auto thread_id = thread_id_; |
||||||
|
{ |
||||||
|
MutexLock lock(&fragment.mu); |
||||||
|
for (auto event : thread_events) { |
||||||
|
fragment.events.push_back(RecordedEvent{thread_id, batch_id, event}); |
||||||
|
} |
||||||
|
} |
||||||
|
thread_events.clear(); |
||||||
|
} |
||||||
|
|
||||||
|
} // namespace latent_see
|
||||||
|
} // namespace grpc_core
|
||||||
|
#endif |
||||||
@ -0,0 +1,214 @@ |
|||||||
|
// Copyright 2024 gRPC authors.
|
||||||
|
//
|
||||||
|
// Licensed under the Apache License, Version 2.0 (the "License");
|
||||||
|
// you may not use this file except in compliance with the License.
|
||||||
|
// You may obtain a copy of the License at
|
||||||
|
//
|
||||||
|
// http://www.apache.org/licenses/LICENSE-2.0
|
||||||
|
//
|
||||||
|
// Unless required by applicable law or agreed to in writing, software
|
||||||
|
// distributed under the License is distributed on an "AS IS" BASIS,
|
||||||
|
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
||||||
|
// See the License for the specific language governing permissions and
|
||||||
|
// limitations under the License.
|
||||||
|
|
||||||
|
#ifndef GRPC_SRC_CORE_UTIL_LATENT_SEE_H |
||||||
|
#define GRPC_SRC_CORE_UTIL_LATENT_SEE_H |
||||||
|
|
||||||
|
#include <grpc/support/port_platform.h> |
||||||
|
|
||||||
|
#ifdef GRPC_ENABLE_LATENT_SEE |
||||||
|
#include <chrono> |
||||||
|
#include <cstdint> |
||||||
|
#include <utility> |
||||||
|
#include <vector> |
||||||
|
|
||||||
|
#include "absl/log/log.h" |
||||||
|
|
||||||
|
#include "src/core/lib/gprpp/per_cpu.h" |
||||||
|
#include "src/core/lib/gprpp/sync.h" |
||||||
|
|
||||||
|
namespace grpc_core { |
||||||
|
namespace latent_see { |
||||||
|
|
||||||
|
struct Metadata { |
||||||
|
const char* file; |
||||||
|
int line; |
||||||
|
const char* name; |
||||||
|
}; |
||||||
|
|
||||||
|
enum class EventType : uint8_t { kBegin, kEnd, kFlowStart, kFlowEnd, kMark }; |
||||||
|
|
||||||
|
class Log { |
||||||
|
public: |
||||||
|
static void FlushThreadLog(); |
||||||
|
|
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION static void Append( |
||||||
|
const Metadata* metadata, EventType type, uint64_t id) { |
||||||
|
thread_events_.push_back( |
||||||
|
Event{metadata, std::chrono::steady_clock::now(), id, type}); |
||||||
|
} |
||||||
|
|
||||||
|
private: |
||||||
|
Log() = default; |
||||||
|
|
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION static Log& Get() { |
||||||
|
static Log* log = []() { |
||||||
|
atexit([] { |
||||||
|
LOG(INFO) << "Writing latent_see.json in " << get_current_dir_name(); |
||||||
|
FILE* f = fopen("latent_see.json", "w"); |
||||||
|
if (f == nullptr) return; |
||||||
|
fprintf(f, "%s", log->GenerateJson().c_str()); |
||||||
|
fclose(f); |
||||||
|
}); |
||||||
|
return new Log(); |
||||||
|
}(); |
||||||
|
return *log; |
||||||
|
} |
||||||
|
|
||||||
|
std::string GenerateJson(); |
||||||
|
|
||||||
|
struct Event { |
||||||
|
const Metadata* metadata; |
||||||
|
std::chrono::steady_clock::time_point timestamp; |
||||||
|
uint64_t id; |
||||||
|
EventType type; |
||||||
|
}; |
||||||
|
struct RecordedEvent { |
||||||
|
uint64_t thread_id; |
||||||
|
uint64_t batch_id; |
||||||
|
Event event; |
||||||
|
}; |
||||||
|
std::atomic<uint64_t> next_thread_id_{1}; |
||||||
|
std::atomic<uint64_t> next_batch_id_{1}; |
||||||
|
static thread_local std::vector<Event> thread_events_; |
||||||
|
static thread_local uint64_t thread_id_; |
||||||
|
struct Fragment { |
||||||
|
Mutex mu; |
||||||
|
std::vector<RecordedEvent> events ABSL_GUARDED_BY(mu); |
||||||
|
}; |
||||||
|
PerCpu<Fragment> fragments_{PerCpuOptions()}; |
||||||
|
}; |
||||||
|
|
||||||
|
template <bool kFlush> |
||||||
|
class Scope { |
||||||
|
public: |
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION explicit Scope(const Metadata* metadata) |
||||||
|
: metadata_(metadata) { |
||||||
|
Log::Append(metadata_, EventType::kBegin, 0); |
||||||
|
} |
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION ~Scope() { |
||||||
|
Log::Append(metadata_, EventType::kEnd, 0); |
||||||
|
if (kFlush) Log::FlushThreadLog(); |
||||||
|
} |
||||||
|
|
||||||
|
Scope(const Scope&) = delete; |
||||||
|
Scope& operator=(const Scope&) = delete; |
||||||
|
|
||||||
|
private: |
||||||
|
const Metadata* const metadata_; |
||||||
|
}; |
||||||
|
|
||||||
|
using ParentScope = Scope<true>; |
||||||
|
using InnerScope = Scope<false>; |
||||||
|
|
||||||
|
class Flow { |
||||||
|
public: |
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION Flow() : metadata_(nullptr) {} |
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION explicit Flow(const Metadata* metadata) |
||||||
|
: metadata_(metadata), |
||||||
|
id_(next_flow_id_.fetch_add(1, std::memory_order_relaxed)) { |
||||||
|
Log::Append(metadata_, EventType::kFlowStart, id_); |
||||||
|
} |
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION ~Flow() { |
||||||
|
if (metadata_ != nullptr) { |
||||||
|
Log::Append(metadata_, EventType::kFlowEnd, id_); |
||||||
|
} |
||||||
|
} |
||||||
|
|
||||||
|
Flow(const Flow&) = delete; |
||||||
|
Flow& operator=(const Flow&) = delete; |
||||||
|
Flow(Flow&& other) noexcept |
||||||
|
: metadata_(std::exchange(other.metadata_, nullptr)), id_(other.id_) {} |
||||||
|
Flow& operator=(Flow&& other) noexcept { |
||||||
|
if (metadata_ != nullptr) Log::Append(metadata_, EventType::kFlowEnd, id_); |
||||||
|
metadata_ = std::exchange(other.metadata_, nullptr); |
||||||
|
id_ = other.id_; |
||||||
|
return *this; |
||||||
|
} |
||||||
|
|
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION bool is_active() const { |
||||||
|
return metadata_ != nullptr; |
||||||
|
} |
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION void End() { |
||||||
|
if (metadata_ == nullptr) return; |
||||||
|
Log::Append(metadata_, EventType::kFlowEnd, id_); |
||||||
|
metadata_ = nullptr; |
||||||
|
} |
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION void Begin(const Metadata* metadata) { |
||||||
|
if (metadata_ != nullptr) Log::Append(metadata_, EventType::kFlowEnd, id_); |
||||||
|
metadata_ = metadata; |
||||||
|
if (metadata_ == nullptr) return; |
||||||
|
id_ = next_flow_id_.fetch_add(1, std::memory_order_relaxed); |
||||||
|
Log::Append(metadata_, EventType::kFlowStart, id_); |
||||||
|
} |
||||||
|
|
||||||
|
private: |
||||||
|
const Metadata* metadata_; |
||||||
|
uint64_t id_; |
||||||
|
static std::atomic<uint64_t> next_flow_id_; |
||||||
|
}; |
||||||
|
|
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION inline void Mark(const Metadata* md) { |
||||||
|
Log::Append(md, EventType::kMark, 0); |
||||||
|
} |
||||||
|
|
||||||
|
} // namespace latent_see
|
||||||
|
} // namespace grpc_core
|
||||||
|
#define GRPC_LATENT_SEE_METADATA(name) \ |
||||||
|
[]() { \
|
||||||
|
static grpc_core::latent_see::Metadata metadata = {__FILE__, __LINE__, \
|
||||||
|
#name}; \ |
||||||
|
return &metadata; \
|
||||||
|
}() |
||||||
|
// Parent scope: logs a begin and end event, and flushes the thread log on scope
|
||||||
|
// exit. Because the flush takes some time it's better to place one parent scope
|
||||||
|
// at the top of the stack, and use lighter weight scopes within it.
|
||||||
|
#define GRPC_LATENT_SEE_PARENT_SCOPE(name) \ |
||||||
|
grpc_core::latent_see::ParentScope latent_see_scope##__LINE__( \
|
||||||
|
GRPC_LATENT_SEE_METADATA(name)) |
||||||
|
// Inner scope: logs a begin and end event. Lighter weight than parent scope,
|
||||||
|
// but does not flush the thread state - so should only be enclosed by a parent
|
||||||
|
// scope.
|
||||||
|
#define GRPC_LATENT_SEE_INNER_SCOPE(name) \ |
||||||
|
grpc_core::latent_see::InnerScope latent_see_scope##__LINE__( \
|
||||||
|
GRPC_LATENT_SEE_METADATA(name)) |
||||||
|
// Mark: logs a single event.
|
||||||
|
// This is not flushed automatically, and so should only be used within a parent
|
||||||
|
// scope.
|
||||||
|
#define GRPC_LATENT_SEE_MARK(name) \ |
||||||
|
grpc_core::latent_see::Mark(GRPC_LATENT_SEE_METADATA(name)) |
||||||
|
#else // !def(GRPC_ENABLE_LATENT_SEE)
|
||||||
|
namespace grpc_core { |
||||||
|
namespace latent_see { |
||||||
|
struct Metadata {}; |
||||||
|
struct Flow { |
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION bool is_active() const { return false; } |
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION void End() {} |
||||||
|
GPR_ATTRIBUTE_ALWAYS_INLINE_FUNCTION void Begin(Metadata*) {} |
||||||
|
}; |
||||||
|
} // namespace latent_see
|
||||||
|
} // namespace grpc_core
|
||||||
|
#define GRPC_LATENT_SEE_METADATA(name) nullptr |
||||||
|
#define GRPC_LATENT_SEE_PARENT_SCOPE(name) \ |
||||||
|
do { \
|
||||||
|
} while (0) |
||||||
|
#define GRPC_LATENT_SEE_INNER_SCOPE(name) \ |
||||||
|
do { \
|
||||||
|
} while (0) |
||||||
|
#define GRPC_LATENT_SEE_MARK(name) \ |
||||||
|
do { \
|
||||||
|
} while (0) |
||||||
|
#endif // GRPC_ENABLE_LATENT_SEE
|
||||||
|
|
||||||
|
#endif // GRPC_SRC_CORE_UTIL_LATENT_SEE_H
|
||||||
Loading…
Reference in new issue