Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
26 changes: 25 additions & 1 deletion src/common/settings.json
Original file line number Diff line number Diff line change
Expand Up @@ -514,6 +514,14 @@
"default_scope": "global",
"default_value": "false"
},
{
"name": "enable_pipeline_trace",
"description": "Enables pipeline trace logging: prints the pipeline graph and outputs a Chrome Trace JSON timing report to stderr on query completion",
"type": "BOOLEAN",
"scope": "local",
"struct": "EnablePipelineTraceSetting",
"custom_implementation": true
},
{
"name": "enable_profiling",
"description": "Enables profiling, and sets the output format (JSON, QUERY_TREE, QUERY_TREE_OPTIMIZER)",
Expand Down Expand Up @@ -895,6 +903,22 @@
"scope": "global",
"default_value": "auto"
},
{
"name": "pipeline_graph_output",
"description": "File path for pipeline graph output when enable_pipeline_trace is true (empty = stderr)",
"type": "VARCHAR",
"scope": "local",
"struct": "PipelineGraphOutputSetting",
"custom_implementation": true
},
{
"name": "pipeline_trace_output",
"description": "File path for Chrome Trace JSON output when enable_pipeline_trace is true (empty = stderr)",
"type": "VARCHAR",
"scope": "local",
"struct": "PipelineTraceOutputSetting",
"custom_implementation": true
},
{
"name": "pivot_filter_threshold",
"description": "The threshold to switch from using filtered aggregates to LIST with a dedicated pivot operator",
Expand Down Expand Up @@ -1119,4 +1143,4 @@
"scope": "global",
"default_value": "4096"
}
]
]
4 changes: 4 additions & 0 deletions src/include/duckdb/execution/executor.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -155,6 +155,10 @@ class Executor {
vector<shared_ptr<Pipeline>> pipelines;
//! The root pipelines of the query
vector<shared_ptr<Pipeline>> root_pipelines;
//! Pipelines saved for trace output (persists after pipelines.clear())
vector<shared_ptr<Pipeline>> traced_pipelines;
//! Steady-clock nanoseconds at query initialization (base for Chrome trace timestamps)
int64_t pipeline_trace_start_ns = 0;
//! The recursive CTE's in this query plan
vector<reference<PhysicalOperator>> recursive_ctes;
//! The pipeline executor for the root pipeline
Expand Down
8 changes: 8 additions & 0 deletions src/include/duckdb/main/client_config.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -101,6 +101,14 @@ struct ClientConfig {
//! If HTTP logging is enabled or not.
bool enable_http_logging = true;

//! If pipeline trace logging is enabled (SET enable_pipeline_trace = true).
//! Prints the pipeline dependency graph and Chrome Trace JSON timing to stderr.
bool enable_pipeline_trace = false;
//! File path for pipeline graph output (empty = stderr).
string pipeline_graph_output;
//! File path for Chrome Trace JSON output (empty = stderr).
string pipeline_trace_output;

//! **DEPRECATED** The file to save query HTTP logging information to, instead of printing it to the console
//! (empty = output to the DuckDB logger)
string http_logging_output;
Expand Down
34 changes: 34 additions & 0 deletions src/include/duckdb/main/settings.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -780,6 +780,40 @@ struct EnableObjectCacheSetting {
static constexpr idx_t SettingIndex = 42;
};

struct EnablePipelineTraceSetting {
using RETURN_TYPE = bool;
static constexpr const char *Name = "enable_pipeline_trace";
static constexpr const char *Description =
"Enables pipeline trace logging: prints the pipeline graph and outputs a Chrome Trace JSON "
"timing report to stderr on query completion";
static constexpr const char *InputType = "BOOLEAN";
static void SetLocal(ClientContext &context, const Value &parameter);
static void ResetLocal(ClientContext &context);
static Value GetSetting(const ClientContext &context);
};

struct PipelineGraphOutputSetting {
using RETURN_TYPE = string;
static constexpr const char *Name = "pipeline_graph_output";
static constexpr const char *Description =
"File path for pipeline graph output when enable_pipeline_trace is true (empty = stderr)";
static constexpr const char *InputType = "VARCHAR";
static void SetLocal(ClientContext &context, const Value &parameter);
static void ResetLocal(ClientContext &context);
static Value GetSetting(const ClientContext &context);
};

struct PipelineTraceOutputSetting {
using RETURN_TYPE = string;
static constexpr const char *Name = "pipeline_trace_output";
static constexpr const char *Description =
"File path for Chrome Trace JSON output when enable_pipeline_trace is true (empty = stderr)";
static constexpr const char *InputType = "VARCHAR";
static void SetLocal(ClientContext &context, const Value &parameter);
static void ResetLocal(ClientContext &context);
static Value GetSetting(const ClientContext &context);
};

struct EnableProfilingSetting {
using RETURN_TYPE = string;
static constexpr const char *Name = "enable_profiling";
Expand Down
33 changes: 33 additions & 0 deletions src/include/duckdb/parallel/pipeline.hpp
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,15 @@ class PipelineTask : public ExecutorTask {

public:
TaskExecutionResult ExecuteTask(TaskExecutionMode mode) override;

private:
//! Wall-clock start time of this task's first ExecuteTask invocation (-1 = not yet started).
//! Captured once even if the task yields and is rescheduled, so the recorded interval covers
//! the whole task lifetime including any blocked periods between Execute calls.
int64_t task_start_ns = -1;
//! std::hash of this->thread::id at the time of first ExecuteTask. Used as Chrome Trace tid
//! so each worker thread gets its own row in Perfetto.
uint64_t task_thread_hash = 0;
};

class PipelineBuildState {
Expand Down Expand Up @@ -76,6 +85,7 @@ class Pipeline : public enable_shared_from_this<Pipeline> {
friend class PipelineFinishEvent;
friend class PipelineBuildState;
friend class MetaPipeline;
friend class PipelineTracer;

public:
explicit Pipeline(Executor &execution_context);
Expand All @@ -100,6 +110,22 @@ class Pipeline : public enable_shared_from_this<Pipeline> {
void Print() const;
void PrintDependencies() const;

//! Per-PipelineTask timing record. One entry per parallel task that ran this pipeline,
//! capturing first-Execute-entry → TASK_FINISHED return wall-clock interval and the
//! worker thread's hash.
struct TaskTiming {
int64_t start_ns;
int64_t end_ns;
uint64_t thread_hash;
};

//! Append a task timing record. Thread-safe; called by PipelineTask on completion.
void RecordTaskTiming(int64_t start_ns, int64_t end_ns, uint64_t thread_hash);

idx_t GetPipelineId() const {
return pipeline_id;
}

//! Returns query progress
bool GetProgress(ProgressData &progress_data);

Expand Down Expand Up @@ -132,6 +158,13 @@ class Pipeline : public enable_shared_from_this<Pipeline> {
atomic<bool> initialized;
//! The source of this pipeline
optional_ptr<PhysicalOperator> source;

//! Pipeline ID assigned by PipelineTracer::AssignIds (0-based)
idx_t pipeline_id = 0;
//! Per-task timing records. Appended to from worker threads via RecordTaskTiming under
//! task_timings_lock; read once at query end by PipelineTracer::PrintChromeTrace.
mutable mutex task_timings_lock;
vector<TaskTiming> task_timings;
//! The chain of intermediate operators
vector<reference<PhysicalOperator>> operators;
//! The sink (i.e. destination) for data; this is e.g. a hash table to-be-built
Expand Down
50 changes: 50 additions & 0 deletions src/include/duckdb/parallel/pipeline_tracer.hpp
Original file line number Diff line number Diff line change
@@ -0,0 +1,50 @@
//===----------------------------------------------------------------------===//
// DuckDB
//
// duckdb/parallel/pipeline_tracer.hpp
//
//
//===----------------------------------------------------------------------===//

#pragma once

#include "duckdb/common/common.hpp"

namespace duckdb {

class Pipeline;

//! PipelineTracer collects and outputs pipeline structure and execution timing.
//! Enabled by SET enable_pipeline_trace = true.
//!
//! Output destinations (empty string = stderr):
//! SET pipeline_graph_output = '/path/graph.txt' -- pipeline dependency graph
//! SET pipeline_trace_output = '/path/trace.json' -- Chrome Trace JSON (Perfetto)
class PipelineTracer {
public:
//! Assign sequential IDs (0, 1, 2, ...) to all pipelines.
//! Must be called before PrintGraph or PrintChromeTrace.
static void AssignIds(vector<shared_ptr<Pipeline>> &pipelines);

//! Print the static pipeline structure and dependency graph.
//! output_path: file path to write to, or empty string for stderr.
static void PrintGraph(const vector<shared_ptr<Pipeline>> &pipelines, const string &output_path);

//! Print Chrome Trace JSON (loadable in https://ui.perfetto.dev/).
//! query_start_ns: steady_clock nanoseconds since epoch at query start.
//! output_path: file path to write to, or empty string for stderr.
static void PrintChromeTrace(const vector<shared_ptr<Pipeline>> &pipelines, int64_t query_start_ns,
const string &output_path);

private:
//! Build a short human-readable description: "TableScan→HashJoinBuild→..."
static string Describe(const Pipeline &pipeline);

//! Write content to output_path if non-empty, otherwise to stderr.
//! append=true opens the file in append mode (used for the graph, which accumulates
//! across queries); append=false truncates (used for the Chrome Trace JSON, which
//! must remain a single valid JSON object per file).
static void WriteOutput(const string &content, const string &output_path, bool append);
};

} // namespace duckdb
11 changes: 7 additions & 4 deletions src/main/config.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -128,6 +128,7 @@ static const ConfigurationOption internal_options[] = {
DUCKDB_GLOBAL(EnableLogging),
DUCKDB_SETTING(EnableMacroDependenciesSetting),
DUCKDB_SETTING(EnableObjectCacheSetting),
DUCKDB_LOCAL(EnablePipelineTraceSetting),
DUCKDB_LOCAL(EnableProfilingSetting),
DUCKDB_LOCAL(EnableProgressBarSetting),
DUCKDB_LOCAL(EnableProgressBarPrintSetting),
Expand Down Expand Up @@ -177,6 +178,8 @@ static const ConfigurationOption internal_options[] = {
DUCKDB_SETTING(PasswordSetting),
DUCKDB_SETTING_CALLBACK(PerfectHtThresholdSetting),
DUCKDB_SETTING_CALLBACK(PinThreadsSetting),
DUCKDB_LOCAL(PipelineGraphOutputSetting),
DUCKDB_LOCAL(PipelineTraceOutputSetting),
DUCKDB_SETTING(PivotFilterThresholdSetting),
DUCKDB_SETTING(PivotLimitSetting),
DUCKDB_SETTING(PreferRangeJoinsSetting),
Expand Down Expand Up @@ -208,12 +211,12 @@ static const ConfigurationOption internal_options[] = {
DUCKDB_SETTING(ZstdMinStringLengthSetting),
FINAL_SETTING};

static const ConfigurationAlias setting_aliases[] = {DUCKDB_SETTING_ALIAS("memory_limit", 99),
static const ConfigurationAlias setting_aliases[] = {DUCKDB_SETTING_ALIAS("memory_limit", 100),
DUCKDB_SETTING_ALIAS("null_order", 43),
DUCKDB_SETTING_ALIAS("profiling_output", 118),
DUCKDB_SETTING_ALIAS("user", 133),
DUCKDB_SETTING_ALIAS("profiling_output", 121),
DUCKDB_SETTING_ALIAS("user", 136),
DUCKDB_SETTING_ALIAS("wal_autocheckpoint", 25),
DUCKDB_SETTING_ALIAS("worker_threads", 132),
DUCKDB_SETTING_ALIAS("worker_threads", 135),
FINAL_ALIAS};

vector<ConfigurationOption> DBConfig::GetOptions() {
Expand Down
48 changes: 48 additions & 0 deletions src/main/settings/custom_settings.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -1205,6 +1205,54 @@ Value EnableHTTPLoggingSetting::GetSetting(const ClientContext &context) {
return Value::BOOLEAN(config.enable_http_logging);
}

//===----------------------------------------------------------------------===//
// Enable Pipeline Trace
//===----------------------------------------------------------------------===//

void EnablePipelineTraceSetting::SetLocal(ClientContext &context, const Value &input) {
ClientConfig::GetConfig(context).enable_pipeline_trace = input.GetValue<bool>();
}

void EnablePipelineTraceSetting::ResetLocal(ClientContext &context) {
ClientConfig::GetConfig(context).enable_pipeline_trace = ClientConfig().enable_pipeline_trace;
}

Value EnablePipelineTraceSetting::GetSetting(const ClientContext &context) {
return Value::BOOLEAN(ClientConfig::GetConfig(context).enable_pipeline_trace);
}

//===----------------------------------------------------------------------===//
// Pipeline Graph Output
//===----------------------------------------------------------------------===//

void PipelineGraphOutputSetting::SetLocal(ClientContext &context, const Value &input) {
ClientConfig::GetConfig(context).pipeline_graph_output = input.GetValue<string>();
}

void PipelineGraphOutputSetting::ResetLocal(ClientContext &context) {
ClientConfig::GetConfig(context).pipeline_graph_output = ClientConfig().pipeline_graph_output;
}

Value PipelineGraphOutputSetting::GetSetting(const ClientContext &context) {
return Value(ClientConfig::GetConfig(context).pipeline_graph_output);
}

//===----------------------------------------------------------------------===//
// Pipeline Trace Output
//===----------------------------------------------------------------------===//

void PipelineTraceOutputSetting::SetLocal(ClientContext &context, const Value &input) {
ClientConfig::GetConfig(context).pipeline_trace_output = input.GetValue<string>();
}

void PipelineTraceOutputSetting::ResetLocal(ClientContext &context) {
ClientConfig::GetConfig(context).pipeline_trace_output = ClientConfig().pipeline_trace_output;
}

Value PipelineTraceOutputSetting::GetSetting(const ClientContext &context) {
return Value(ClientConfig::GetConfig(context).pipeline_trace_output);
}

//===----------------------------------------------------------------------===//
// Enable Mbedtls
//===----------------------------------------------------------------------===//
Expand Down
1 change: 1 addition & 0 deletions src/parallel/CMakeLists.txt
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ add_library_unity(
interrupt.cpp
pipeline.cpp
pipeline_complete_event.cpp
pipeline_tracer.cpp
pipeline_event.cpp
pipeline_executor.cpp
pipeline_finish_event.cpp
Expand Down
20 changes: 20 additions & 0 deletions src/parallel/executor.cpp
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
#include "duckdb/execution/executor.hpp"

#include "duckdb/common/chrono.hpp"
#include "duckdb/execution/execution_context.hpp"
#include "duckdb/execution/operator/helper/physical_result_collector.hpp"
#include "duckdb/execution/operator/scan/physical_table_scan.hpp"
Expand All @@ -16,6 +17,7 @@
#include "duckdb/parallel/pipeline_finish_event.hpp"
#include "duckdb/parallel/pipeline_initialize_event.hpp"
#include "duckdb/parallel/pipeline_prepare_finish_event.hpp"
#include "duckdb/parallel/pipeline_tracer.hpp"
#include "duckdb/parallel/task_scheduler.hpp"
#include "duckdb/parallel/thread_context.hpp"

Expand Down Expand Up @@ -424,6 +426,16 @@ void Executor::InitializeInternal(PhysicalOperator &plan) {
// finally, verify and schedule
VerifyPipelines();
ScheduleEvents(to_schedule);

// pipeline trace: assign IDs, record query start time, and print the static graph
auto &trace_config = ClientConfig::GetConfig(context);
if (trace_config.enable_pipeline_trace) {
PipelineTracer::AssignIds(pipelines);
pipeline_trace_start_ns = static_cast<int64_t>(
duration_cast<nanoseconds>(steady_clock::now().time_since_epoch()).count());
PipelineTracer::PrintGraph(pipelines, trace_config.pipeline_graph_output);
traced_pipelines = pipelines;
}
}
}

Expand Down Expand Up @@ -622,6 +634,12 @@ PendingExecutionResult Executor::ExecuteTask(bool dry_run) {
D_ASSERT(!task);

lock_guard<mutex> elock(executor_lock);
// emit Chrome Trace JSON before clearing pipelines (timing data lives in Pipeline objects)
if (!traced_pipelines.empty()) {
auto &trace_config = ClientConfig::GetConfig(context);
PipelineTracer::PrintChromeTrace(traced_pipelines, pipeline_trace_start_ns, trace_config.pipeline_trace_output);
traced_pipelines.clear();
}
pipelines.clear();
NextExecutor();
if (HasError()) { // LCOV_EXCL_START
Expand All @@ -647,6 +665,8 @@ void Executor::Reset() {
events.clear();
to_be_rescheduled_tasks.clear();
execution_result = PendingExecutionResult::RESULT_NOT_READY;
traced_pipelines.clear();
pipeline_trace_start_ns = 0;
}

shared_ptr<Pipeline> Executor::CreateChildPipeline(Pipeline &current, PhysicalOperator &op) {
Expand Down
Loading
Loading