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.

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

Expose Peak memory usage in query statistics. #51946

Merged
merged 21 commits into from Jul 25, 2023

Conversation

kardymonds
Copy link
Contributor

Close #44805

Changelog category (leave one):

  • New Feature

Changelog entry (a user-readable short description of the changes that goes to CHANGELOG.md):

Added Peak Memory Usage (for query) to client final statistics, and to http header.

@nikitamikhaylov nikitamikhaylov added the can be tested Allows running workflows for external contributors label Jul 7, 2023
@robot-clickhouse-ci-1 robot-clickhouse-ci-1 added the pr-feature Pull request with new product feature label Jul 7, 2023
@robot-clickhouse-ci-1
Copy link
Contributor

robot-clickhouse-ci-1 commented Jul 7, 2023

This is an automated comment for commit d4d381d with description of existing statuses. It's updated for the latest CI running
The full report is available here
The overall status of the commit is 🟢 success

Check nameDescriptionStatus
AST fuzzerRuns randomly generated queries to catch program errors. The build type is optionally given in parenthesis. If it fails, ask a maintainer for help🟢 success
CI runningA meta-check that indicates the running CI. Normally, it's in success or pending state. The failed status indicates some problems with the PR🟢 success
ClickHouse build checkBuilds ClickHouse in various configurations for use in further steps. You have to fix the builds that fail. Build logs often has enough information to fix the error, but you might have to reproduce the failure locally. The cmake options can be found in the build log, grepping for cmake. Use these options and follow the general build process🟢 success
Compatibility checkChecks that clickhouse binary runs on distributions with old libc versions. If it fails, ask a maintainer for help🟢 success
Docker image for serversThe check to build and optionally push the mentioned image to docker hub🟢 success
Docs CheckBuilds and tests the documentation🟢 success
Fast testNormally this is the first check that is ran for a PR. It builds ClickHouse and runs most of stateless functional tests, omitting some. If it fails, further checks are not started until it is fixed. Look at the report to see which tests fail, then reproduce the failure locally as described here🟢 success
Flaky testsChecks if new added or modified tests are flaky by running them repeatedly, in parallel, with more randomization. Functional tests are run 100 times with address sanitizer, and additional randomization of thread scheduling. Integrational tests are run up to 10 times. If at least once a new test has failed, or was too long, this check will be red. We don't allow flaky tests, read the doc🟢 success
Install packagesChecks that the built packages are installable in a clear environment🟢 success
Integration testsThe integration tests report. In parenthesis the package type is given, and in square brackets are the optional part/total tests🟢 success
Mergeable CheckChecks if all other necessary checks are successful🟢 success
Performance ComparisonMeasure changes in query performance. The performance test report is described in detail here. In square brackets are the optional part/total tests🟢 success
Push to DockerhubThe check for building and pushing the CI related docker images to docker hub🟢 success
SQLancerFuzzing tests that detect logical bugs with SQLancer tool🟢 success
SqllogicRun clickhouse on the sqllogic test set against sqlite and checks that all statements are passed🟢 success
Stateful testsRuns stateful functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc🟢 success
Stateless testsRuns stateless functional tests for ClickHouse binaries built in various configurations -- release, debug, with sanitizers, etc🟢 success
Stress testRuns stateless functional tests concurrently from several clients to detect concurrency-related errors🟢 success
Style CheckRuns a set of checks to keep the code style clean. If some of tests failed, see the related log from the report🟢 success
Unit testsRuns the unit tests for different release types🟢 success
Upgrade checkRuns stress tests on server version from last release and then tries to upgrade it to the version from the PR. It checks if the new server can successfully startup without any errors, crashes or sanitizer asserts🟢 success

@CheSema
Copy link
Member

CheSema commented Jul 14, 2023

Please see here the error
https://s3.amazonaws.com/clickhouse-test-reports/51946/7704469defaa55fd5d226a63be1e09402684736f/stress_test__tsan_/stderr.log

I think it is related to the PR.

WARNING: ThreadSanitizer: data race (pid=1645)
  Write of size 8 at 0x7b4800710b48 by thread T626:
    #0 DB::WriteBufferFromHTTPServerResponse::onMemoryUsage(long) build_docker/./src/Server/HTTP/WriteBufferFromHTTPServerResponse.cpp:179:23 (clickhouse+0x211b1de1) (BuildId: f702f65e8055c253483bd28ea02f8ac5668b630a)
    #1 DB::HTTPHandler::processQuery(DB::HTTPServerRequest&, DB::HTMLForm&, DB::HTTPServerResponse&, DB::HTTPHandler::Output&, std::__1::optional<DB::CurrentThread::QueryScope>&)::$_4::operator()(DB::Progress const&) const build_docker/./src/Server/HTTPHandler.cpp:826:26 (clickhouse+0x211246f5) (BuildId: f702f65e8055c253483bd28ea02f8ac5668b630a)

Comment on lines +90 to 99
columns[i]->insert(snapshot.memory_usage);

i = 0;
columns[i++]->insertData(host_name.data(), host_name.size());
columns[i++]->insert(static_cast<UInt64>(snapshot.current_time));
columns[i++]->insert(static_cast<UInt64>(snapshot.thread_id));
columns[i++]->insert(Type::GAUGE);
columns[i++]->insertData(MemoryTracker::PEAK_USAGE_EVENT_NAME, strlen(MemoryTracker::PEAK_USAGE_EVENT_NAME));
columns[i]->insert(snapshot.peak_memory_usage);
}
Copy link
Member

Choose a reason for hiding this comment

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

Please explain those lines to me. I do not understand it.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

The data (ProfileEvents and memory events) between the server and the client passes through row in the sql block (DB::Block). I added one more row with my data (peak memory).
Columns:

static const NamesAndTypesList column_names_and_types = {
        {"host_name", std::make_shared<DataTypeString>()},
        {"current_time", std::make_shared<DataTypeDateTime>()},
        {"thread_id", std::make_shared<DataTypeUInt64>()},
        {"type", TypeEnum},
        {"name", std::make_shared<DataTypeString>()},
        {"value", std::make_shared<DataTypeInt64>()},
    };

Copy link
Member

Choose a reason for hiding this comment

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

That is Ok.
The diff itself looks strange.

image

Looks like one write is not enough and you added two :)

Copy link
Member

Choose a reason for hiding this comment

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

Oh, my bad.
That is right. You add one more row here.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I don't understand, what exactly is confusing? The first block write current_memory_usage. Insert() appends new value at the end of column (column's size is increased by 1). i++ in block ends is not necessary, i replaced to i;

@CheSema CheSema self-assigned this Jul 14, 2023
@@ -99,8 +99,8 @@ void ProgressIndication::writeFinalProgress()
if (elapsed_ns)
std::cout << " (" << formatReadableQuantity(progress.read_rows * 1000000000.0 / elapsed_ns) << " rows/s., "
<< formatReadableSizeWithDecimalSuffix(progress.read_bytes * 1000000000.0 / elapsed_ns) << "/s.)";
else
std::cout << ". ";
auto peak_memory_usage = getMemoryUsage().peak;
Copy link
Member

Choose a reason for hiding this comment

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

I have one concern here how a new client works with an old server. Client would print 0 as peak_memory_usage

Copy link
Contributor Author

Choose a reason for hiding this comment

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

It seems to me that this entire line is for information, and it is unlikely that the client will rely on this value.
Try not to display the value for old servers?

Copy link
Member

Choose a reason for hiding this comment

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

It would right and heavy. May be just enough not to log it when it zero. Just because memory usage never is zero.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Added check (not show if old server). I use '-1' (as default) because memory can be zero (I don't know why it works like this; on small queries always 0).

used_output.out->onProgress(progress);
auto thread_group = CurrentThread::getGroup();
auto peak_memory_usage = thread_group->memory_tracker.getPeak();
used_output.out->onMemoryUsage(peak_memory_usage);
Copy link
Member

Choose a reason for hiding this comment

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

Please clarify to me

  • when do you want to collect peak_memory_usage for the query
  • when do you want to send it to the client
  • which clients should receive peak_memory_usage and which are not suppose to see it.

The questions arose because I see the inconsistency in the logic, however I might be wrong.
I see that

  • 'peak_memory_usage' collected regularly for the query (this is why the data race occurs)
  • it is sent only at the end (only at finishSendHeaders)
  • only http protocol is affected

Copy link
Contributor Author

Choose a reason for hiding this comment

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

when do you want to collect peak_memory_usage for the query

It is already collected (it was implemented) for the query, I just pass it to http. I don't know exactly how it works. The server already displays this value in its log.

when do you want to send it to the client

I actually need to update once by the end, but there is no such moment here and I send it along with the progress statistics.

which clients should receive peak_memory_usage and which are not suppose to see it.

I did it for everyone (because I thought it was for information, and no one would be offended). But I don't have exact information on how clients use the X-ClickHouse-Summary field.

(this is why the data race occurs)

It looks like I forgot the mutex, now I'll try to fix it.

What does it look like (over curl):

curl -v 'http://localhost:8123/?send_progress_in_http_headers=1&query=SELECT%20number%20FROM%20numbers(100000000)%20FORMAT%20Null;'

...
< Keep-Alive: timeout=10
< X-ClickHouse-Progress: {"read_rows":"3989949","read_bytes":"31919592","written_rows":"0","written_bytes":"0","total_rows_to_read":"20000000","result_rows":"0","result_bytes":"0"}
< X-ClickHouse-Progress: {"read_rows":"8241534","read_bytes":"65932272","written_rows":"0","written_bytes":"0","total_rows_to_read":"20000000","result_rows":"0","result_bytes":"0"}
< X-ClickHouse-Progress: {"read_rows":"12493119","read_bytes":"99944952","written_rows":"0","written_bytes":"0","total_rows_to_read":"20000000","result_rows":"0","result_bytes":"0"}
< X-ClickHouse-Progress: {"read_rows":"16744704","read_bytes":"133957632","written_rows":"0","written_bytes":"0","total_rows_to_read":"20000000","result_rows":"0","result_bytes":"0"}
< X-ClickHouse-Summary: {"read_rows":"20015154","read_bytes":"160121232","written_rows":"0","written_bytes":"0","total_rows_to_read":"20000000","result_rows":"20000000","result_bytes":"160432128","peak_memory_usage":"0"}
....

in log
023.07.14 14:19:56.455771 [ 58613 ] {f97e1eb1-7d9b-44b7-930c-2e9efcef50ca} <Debug> MemoryTracker: Peak memory usage (for query): 0.00 B.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

only http protocol is affected

The task was also about clickhouse-client, and it has a binary protocol. In general, this task consists of two independent tasks: http + clickhouse-client,

Copy link
Member

Choose a reason for hiding this comment

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

Yes, I see now, sendProfileEvents works for all other protocols. Good.

Copy link
Member

@CheSema CheSema Jul 14, 2023

Choose a reason for hiding this comment

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

Now I understand why changes in http look so outstanding here. It because CH does't send ProfileEvents over http.

Interesting question. It is addressed not to you actually. What is the point to send progress as header? If CH is unable to buffer all response then no more headers are sent after data transmission started. Maybe CH really is able to buffer all response in the most cases.

Here I propose to send peak_memory_usage with each writeHeaderProgress() call as well. It make sense actually. Because one short peak might not be displayed in memory usage. But it may lead to the OOM.
I think that could make the code more straight.

Copy link
Member

Choose a reason for hiding this comment

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

What do you think about sending peak_memory_usage with each writeHeaderProgress() call?

In general I like this PR, and could approve it as it.
But I think it would be even better if just send that info with each progress header, not only the last one.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I'm already doing it now (I thought about doing it during development, but then I refused). Today I hope to fix it (writeHeaderProgress + do not display for old servers).

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Did (send memory in progress)

@CheSema
Copy link
Member

CheSema commented Jul 23, 2023

As it labeled "New Feature". The automatics checks that there are changes in docs files.
I have not found special sentences or paragraph about what CH return as progress tracking. But there are some examples with it. For example with 'X-ClickHouse-Summary' and X-ClickHouse-Progress. And that examples consist the list of entries in that headers. It is here https://github.com/ClickHouse/ClickHouse/blob/master/docs/en/interfaces/http.md#default-database-default-database

@CheSema CheSema merged commit 83d8698 into ClickHouse:master Jul 25, 2023
278 checks passed
@alexey-milovidov
Copy link
Member

I will remove it from clickhouse-client, because it isn't beautiful, and (for query) is redundant:

1 row in set. Elapsed: 18.719 sec. Processed 5.06 billion rows, 2.76 TB (270.28 million rows/s., 147.48 GB/s.)
Peak memory usage (for query) 7.30 GiB.

@alexey-milovidov
Copy link
Member

It's also non-obvious how it is related to distributed queries. Is it the maximum per server peak?

@kardymonds
Copy link
Contributor Author

It's also non-obvious how it is related to distributed queries. Is it the maximum per server peak?

I don’t know for sure, but rather it’s from only one host (it is the same value as in the log).

@rvasin
Copy link
Contributor

rvasin commented Jul 26, 2023

@alexey-milovidov as proposed by @den-crane in #44805 there is the second, shorter variant where is added as Mem: at the end:

1 row in set. Elapsed: 18.719 sec. Processed 5.06 billion rows, 2.76 TB (270.28 million rows/s., 147.48 GB/s.), Mem: 7.30 GiB

What do you think about this variant?

Also there is another variant: implement new configuration option (working name) show_memory_usage. Default value: false. So in pseudo code it will be like:

void ProgressIndication::writeFinalProgress()
{
/// skip
    if (show_memory_usage && peak_memory_usage >= 0)
        std::cout << "\nPeak memory usage (for query) " << formatReadableSizeWithBinarySuffix(peak_memory_usage) << ".";
}

Another variant: the whole text output in writeFinalProgress() is hardcoded now. Probably we may implement new configuration option like:

<clickhouse_client_final_progress_format>Processed {rows}, {bytes} ({rows_speed}. {bytes_speed}), Mem: {peak_memory}</clickhouse_client_final_progress_format>

Default value: if <clickhouse_client_final_progress_format> is undefined then it will produce exactly the same output as it was "before this PR": without peak memory usage statistics. The advantage of this approach is that in future DBAs may customize final progress format to according to their needs and it will be possible to add more stats parameters.

What do you think?

@alexey-milovidov
Copy link
Member

I think we will get it! But we need to figure out these details:

  1. Peak memory usage (for query) 7.30 GiB.

The (for query) looks redundant in clickhouse-client, because everything else is also "for query".
Also, one very small change will be to add : or is:

Peak memory usage: 7.30 GiB.

  1. When the server displays the progress bar, there is already very rich and unambiguous info:

Screenshot_20230727_201015

We should also disambiguate it on the peak memory usage indication with the same logic as is used for the progress bar.

@alexey-milovidov
Copy link
Member

alexey-milovidov commented Jul 27, 2023

Also there is another variant: implement new configuration option (working name) show_memory_usage

Another variant: the whole text output in writeFinalProgress() is hardcoded now. Probably we may implement new configuration option like

This is too complex (too many options), let's not do it.

@rvasin
Copy link
Contributor

rvasin commented Jul 28, 2023

@alexey-milovidov OK. Thank you for explanation. Unfortunately Dmitry Kardymon (@kardymonds) does not work anymore in our company. So Alexey Gerasimchuck (@Demilivor) will finish the required changes the next week. In new PR it would be nice to mention Dmitry Kardymon as original author of the PR.

@Demilivor
Copy link
Contributor

When the server displays the progress bar, there is already very rich and unambiguous info:
We should also disambiguate it on the peak memory usage indication with the same logic as is used for the progress bar.

@alexey-milovidov Does it mean I should also add peak memory usage to the progress bar?
Like this:
peak_in_progress

peak word is used for readability, but actually, I think we can omit it and use <current_memory>/<peak_memory> RAM pattern:
Progress: 71.82 million rows, 574.55 MB (13.51 million rows/s., 108.05 MB/s.) (0.0 CPU, 2.13 GB/2.15 GB RAM)

append_callback([&used_output](const Progress & progress) { used_output.out->onProgress(progress); });
append_callback([&used_output](const Progress & progress)
{
const auto& thread_group = CurrentThread::getGroup();
Copy link
Member

Choose a reason for hiding this comment

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

Wrong style: missing whitespace.

@@ -22,6 +22,9 @@ struct ThreadEventData
UInt64 user_ms = 0;
UInt64 system_ms = 0;
UInt64 memory_usage = 0;

// -1 used as flag 'is not show for old servers'
Copy link
Member

Choose a reason for hiding this comment

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

is not show -> is not shown

@@ -89,6 +89,8 @@ class WriteBufferFromHTTPServerResponse final : public BufferWithOwnMemory<Write
/// but not finish them with \r\n, allowing to send more headers subsequently.
void startSendHeaders();

// Used for write the header X-ClickHouse-Progress / X-ClickHouse-Summary
Copy link
Member

Choose a reason for hiding this comment

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

Used for write -> Used for writing

Copy link
Member

Choose a reason for hiding this comment

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

Double whitespace.

accumulated_progress.writeJSON(progress_string_writer);

writeCString("{", progress_string_writer);
accumulated_progress.writeJSON(progress_string_writer, false);
Copy link
Member

Choose a reason for hiding this comment

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

This looks like trash.

@@ -32,7 +32,7 @@ struct ProgressValues

void read(ReadBuffer & in, UInt64 server_revision);
void write(WriteBuffer & out, UInt64 client_revision) const;
void writeJSON(WriteBuffer & out) const;
void writeJSON(WriteBuffer & out, bool add_braces = true) const;
Copy link
Member

Choose a reason for hiding this comment

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

Default values are harmful.

alexey-milovidov added a commit that referenced this pull request Oct 8, 2023
alexey-milovidov added a commit that referenced this pull request Oct 8, 2023
alexey-milovidov added a commit that referenced this pull request Oct 8, 2023
robot-ch-test-poll3 added a commit that referenced this pull request Oct 9, 2023
…67503e36ba3c461a200a53980dd79

Cherry pick #55336 to 23.9: Review #51946 and partially revert it
alexey-milovidov added a commit that referenced this pull request Oct 9, 2023
Backport #55336 to 23.9: Review #51946 and partially revert it
kothiga pushed a commit to ClibMouse/ClickHouse that referenced this pull request Oct 25, 2023
kothiga pushed a commit to ClibMouse/ClickHouse that referenced this pull request Oct 25, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
can be tested Allows running workflows for external contributors pr-feature Pull request with new product feature
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Expose Peak memory usage in query statistics.
7 participants