Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Opentracing minimal changes for processors #37837

Merged
merged 5 commits into from
Jun 9, 2022
Merged

Opentracing minimal changes for processors #37837

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
a12357d
Leave minimal changes for now
qoega Jun 3, 2022
09a9edc
fix includes
qoega Jun 3, 2022
49a6b2f
Fix race
nikitamikhaylov Jun 7, 2022
b012ffe
Merge branch 'master' into opentracing-minimal
mergify[bot] Jun 7, 2022
d39e724
Merge branch 'master' into opentracing-minimal
mergify[bot] Jun 7, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
8 changes: 5 additions & 3 deletions src/Interpreters/OpenTelemetrySpanLog.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -118,11 +118,14 @@ OpenTelemetrySpanHolder::~OpenTelemetrySpanHolder()
auto * thread_group = CurrentThread::getGroup().get();
// Not sure whether and when this can be null.
if (!thread_group)
{
return;

ContextPtr context;
{
std::lock_guard lock(thread_group->mutex);
context = thread_group->query_context.lock();
}

auto context = thread_group->query_context.lock();
if (!context)
{
// Both global and query contexts can be null when executing a
Expand Down Expand Up @@ -266,4 +269,3 @@ std::string OpenTelemetryTraceContext::composeTraceparentHeader() const


}

2 changes: 1 addition & 1 deletion src/Processors/Executors/CompletedPipelineExecutor.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,7 +33,7 @@ struct CompletedPipelineExecutor::Data

static void threadFunction(CompletedPipelineExecutor::Data & data, ThreadGroupStatusPtr thread_group, size_t num_threads)
{
setThreadName("QueryPipelineEx");
setThreadName("QueryCompPipeEx");

try
{
Expand Down
13 changes: 11 additions & 2 deletions src/Processors/Executors/ExecutionThreadContext.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
#include <Processors/Executors/ExecutionThreadContext.h>
#include <QueryPipeline/ReadProgressCallback.h>
#include <Common/Stopwatch.h>
#include <Interpreters/OpenTelemetrySpanLog.h>

namespace DB
{
Expand Down Expand Up @@ -70,6 +71,7 @@ static void executeJob(ExecutingGraph::Node * node, ReadProgressCallback * read_

bool ExecutionThreadContext::executeTask()
{
OpenTelemetrySpanHolder span("ExecutionThreadContext::executeTask() " + node->processor->getName());
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems like it creates too many spans, so 00974_query_profiler sometimes fail with

 <Error> SystemLog (system.opentelemetry_span_log): Queue is full for system log 'DB::OpenTelemetrySpanLog' at 955525

Example: https://s3.amazonaws.com/clickhouse-test-reports/0/e13dc23d344454ecda401df4b23b696a691421fe/stateless_tests__release__databaseordinary__actions_.html
More failures: https://play.clickhouse.com/play?user=play#c2VsZWN0IAp0b1N0YXJ0T2ZEYXkoY2hlY2tfc3RhcnRfdGltZSkgYXMgZCwKY291bnQoKSwgZ3JvdXBVbmlxQXJyYXkocHVsbF9yZXF1ZXN0X251bWJlciksICBhbnkocmVwb3J0X3VybCkKZnJvbSBjaGVja3Mgd2hlcmUgJzIwMjItMDQtMDEnIDw9IGNoZWNrX3N0YXJ0X3RpbWUgYW5kIHRlc3RfbmFtZSBsaWtlICclMDA5NzRfcXVlcnlfcHJvZmlsZXIlJyBhbmQgdGVzdF9zdGF0dXMgaW4gKCdGQUlMJywgJ0ZMQUtZJykgZ3JvdXAgYnkgZCBvcmRlciBieSBkIGRlc2M=

@qoega, should we revert it?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

More failures: https://play.clickhouse.com/play?user=play#c2VsZWN0IAp0b1N0YXJ0T2ZEYXkoY2hlY2tfc3RhcnRfdGltZSkgYXMgZCwKY291bnQoKSwgZ3JvdXBVbmlxQXJyYXkocHVsbF9yZXF1ZXN0X251bWJlciksICBhbnkocmVwb3J0X3VybCkKZnJvbSBjaGVja3Mgd2hlcmUgJzIwMjItMDQtMDEnIDw9IGNoZWNrX3N0YXJ0X3RpbWUgYW5kIHRlc3RfbmFtZSBsaWtlICclMDA5NzRfcXVlcnlfcHJvZmlsZXIlJyBhbmQgdGVzdF9zdGF0dXMgaW4gKCdGQUlMJywgJ0ZMQUtZJykgZ3JvdXAgYnkgZCBvcmRlciBieSBkIGRlc2M=

not all of them. Probably some.

Too many spans is not the reason we have sanitiser alerts. For 00974_query_profiler we better just disable opentelemetry_span_log with 'set opentelemetry_start_trace_probability=1'. It is enabled there by random settings fuzzer.

I will build asan debug build and will try to reproduce sanitiser alert.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Too many spans is not the reason we have sanitiser alerts.

Yes, most likely it's two independent issues.

For 00974_query_profiler we better just disable opentelemetry_span_log with 'set opentelemetry_start_trace_probability=1'.

Are you sure that it will not produce to many spans in a production environment?

std::optional<Stopwatch> execution_time_watch;

#ifndef NDEBUG
Expand All @@ -90,12 +92,19 @@ bool ExecutionThreadContext::executeTask()
}

if (profile_processors)
node->processor->elapsed_us += execution_time_watch->elapsedMicroseconds();

{
UInt64 elapsed_microseconds = execution_time_watch->elapsedMicroseconds();
node->processor->elapsed_us += elapsed_microseconds;
span.addAttribute("execution_time_ms", elapsed_microseconds);
}
#ifndef NDEBUG
execution_time_ns += execution_time_watch->elapsed();
span.addAttribute("execution_time_ns", execution_time_watch->elapsed());
#endif

span.addAttribute("thread_number", thread_number);
span.addAttribute("processor.description", node->processor->getDescription());

return node->exception == nullptr;
}

Expand Down
3 changes: 0 additions & 3 deletions src/Processors/Executors/PipelineExecutor.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,6 @@
#include <Processors/ISource.h>
#include <Interpreters/ProcessList.h>
#include <Interpreters/Context.h>
#include <Interpreters/OpenTelemetrySpanLog.h>
#include <Common/scope_guard_safe.h>

#ifndef NDEBUG
Expand Down Expand Up @@ -275,8 +274,6 @@ void PipelineExecutor::initializeExecution(size_t num_threads)

void PipelineExecutor::executeImpl(size_t num_threads)
{
OpenTelemetrySpanHolder span("PipelineExecutor::executeImpl()");

initializeExecution(num_threads);

using ThreadsData = std::vector<ThreadFromGlobalPool>;
Expand Down
2 changes: 1 addition & 1 deletion src/Processors/Executors/PullingAsyncPipelineExecutor.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -69,7 +69,7 @@ const Block & PullingAsyncPipelineExecutor::getHeader() const

static void threadFunction(PullingAsyncPipelineExecutor::Data & data, ThreadGroupStatusPtr thread_group, size_t num_threads)
{
setThreadName("QueryPipelineEx");
setThreadName("QueryPullPipeEx");

try
{
Expand Down
2 changes: 1 addition & 1 deletion src/Processors/Executors/PushingAsyncPipelineExecutor.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -98,7 +98,7 @@ struct PushingAsyncPipelineExecutor::Data

static void threadFunction(PushingAsyncPipelineExecutor::Data & data, ThreadGroupStatusPtr thread_group, size_t num_threads)
{
setThreadName("QueryPipelineEx");
setThreadName("QueryPushPipeEx");

try
{
Expand Down