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

parallel_view_processing behavior has changed. #10241

Closed
den-crane opened this issue Apr 13, 2020 · 6 comments · Fixed by #10757 or #11330
Closed

parallel_view_processing behavior has changed. #10241

den-crane opened this issue Apr 13, 2020 · 6 comments · Fixed by #10757 or #11330
Assignees
@KochetovNicolai
Labels
performance

Comments

@den-crane
Copy link
Contributor

den-crane commented Apr 13, 2020 •
edited

parallel_view_processing=1

drop table if exists testX;
drop table if exists testXA;
drop table if exists testXB;
drop table if exists testXC;
create table testX ( A Int64) engine=MergeTree order by tuple();

create materialized view testXA engine=MergeTree order by tuple() 
as select sleep(1) from testX;

create materialized view testXB engine=MergeTree order by tuple() 
as select sleep(2),throwIf(A=1) from testX;

create materialized view testXC engine=MergeTree order by tuple() 
as select sleep(1) from testX;

insert into testX select number from numbers(10);
select count() from testX;
select count() from testXA;
select count() from testXB;
select count() from testXC;

18.14.18
10
10
0
10

19.13.7.57
10
0
0
0

18.14.18

26.891574 [ 23 ]  <Debug> executeQuery: (from [::1]:33136) insert into testX select number from numbers(10)
26.891788 [ 23 ]  <Trace> InterpreterSelectQuery: FetchColumns -> Complete
26.891846 [ 23 ]  <Debug> executeQuery: Query pipeline:
26.892203 [ 208 ]  <Trace> dw.testX (Data): Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
26.892487 [ 209 ]  <Trace> InterpreterSelectQuery: FetchColumns -> Complete
26.892528 [ 211 ]  <Trace> InterpreterSelectQuery: FetchColumns -> Complete
26.892531 [ 210 ]  <Trace> InterpreterSelectQuery: FetchColumns -> Complete
27.892829 [ 209 ]  <Trace> dw..inner.testXC (Data): Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
27.892862 [ 211 ]  <Trace> dw..inner.testXA (Data): Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
28.892788 [ 210 ]  <Trace> ThreadStatus: Thread 210 exited
28.892788 [ 209 ]  <Trace> ThreadStatus: Thread 209 exited
28.892829 [ 211 ]  <Trace> ThreadStatus: Thread 211 exited
28.892956 [ 208 ]  <Trace> ThreadStatus: Thread 208 exited
28.893027 [ 23 ]  <Error> executeQuery: Code: 395, e.displayText() = DB::Exception: Value passed to 'throwIf' 
28.893086 [ 23 ]  <Debug> MemoryTracker: Peak memory usage (for query): 4.02 MiB.

Threads 209, 211 did insert before Exception

19.13.7.57

15.756235 [ 8174 ] <Debug> executeQuery: (from [::1]:53622) INSERT INTO testX SELECT number FROM numbers(10)
15.756628 [ 8174 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
15.756696 [ 8174 ] <Debug> executeQuery: Query pipeline:
15.757001 [ 30 ] <Trace> dw.testX: Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
15.757196 [ 120 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
15.757196 [ 50 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
15.757314 [ 81 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
17.757825 [ 8174 ] <Error> executeQuery: Code: 395, e.displayText() = DB::Exception: Value passed to 'throwIf' 
17.757901 [ 8174 ] <Debug> MemoryTracker: Peak memory usage (for query): 2.30 KiB.
17.757961 [ 8174 ] <Debug> MemoryTracker: Peak memory usage (total): 2.30 KiB.
17.757976 [ 8174 ] <Information> TCPHandler: Processed in 2.002 sec.

Threads 120, 81 never inserted

We suspect it impacts performance because INSERTS start after all SELECTS (for 1 block ?) finished.
@den-crane den-crane added bug Confirmed user-visible misbehaviour in official release performance and removed bug Confirmed user-visible misbehaviour in official release labels Apr 13, 2020
@den-crane
Copy link
Contributor Author

The performance impact is visible with a high number of MVs.

drop table if exists testX;
drop table if exists testXA;
drop table if exists testXB;
drop table if exists testXC;
drop table if exists testXD;
drop table if exists testXE;
drop table if exists testXF;

create table testX ( A Int64) engine=MergeTree order by tuple();
create MATERIALIZED view testXA engine=MergeTree order by tuple() as select * from testX;
create MATERIALIZED view testXB engine=MergeTree order by tuple() as select * from testX;
create MATERIALIZED view testXC engine=MergeTree order by tuple() as select * from testX;
create MATERIALIZED view testXD engine=MergeTree order by tuple() as select * from testX;
create MATERIALIZED view testXE engine=MergeTree order by tuple() as select * from testX;
create MATERIALIZED view testXF engine=MergeTree order by tuple() as select * from testX;
insert into testX select number from numbers(100000) settings max_block_size=1000000;

18.14.18 Elapsed: 0.005 sec. Processed 100.00 thousand rows

16.473089 [ 23 ] <Debug> executeQuery: (from [::1]:37306) insert into testX select number from numbers(100000) settings max_block_size=1000000
16.473328 [ 23 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
16.473386 [ 23 ] <Debug> executeQuery: Query pipeline:
16.474951 [ 224 ] <Trace> dw.testX (Data): Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
16.475310 [ 227 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
16.475319 [ 226 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
16.475327 [ 225 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
16.475349 [ 229 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
16.475358 [ 228 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
16.475364 [ 230 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
16.476860 [ 226 ] <Trace> dw..inner.testXB (Data): Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
16.476925 [ 227 ] <Trace> dw..inner.testXE (Data): Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
16.476999 [ 225 ] <Trace> dw..inner.testXA (Data): Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
16.477016 [ 229 ] <Trace> dw..inner.testXC (Data): Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
16.477453 [ 230 ] <Trace> dw..inner.testXD (Data): Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
16.477453 [ 228 ] <Trace> dw..inner.testXF (Data): Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
16.477524 [ 229 ] <Trace> ThreadStatus: Thread 229 exited
16.477526 [ 227 ] <Trace> ThreadStatus: Thread 227 exited
16.477531 [ 228 ] <Trace> ThreadStatus: Thread 228 exited
16.477533 [ 225 ] <Trace> ThreadStatus: Thread 225 exited
16.477528 [ 226 ] <Trace> ThreadStatus: Thread 226 exited
16.477533 [ 230 ] <Trace> ThreadStatus: Thread 230 exited
16.477651 [ 224 ] <Trace> ThreadStatus: Thread 224 exited
16.477696 [ 23 ] <Information> executeQuery: Read 100000 rows, 781.25 KiB in 0.005 sec., 21904293 rows/sec., 167.12 MiB/sec.
16.477703 [ 23 ] <Debug> MemoryTracker: Peak memory usage (for query): 19.81 MiB.
16.477738 [ 23 ] <Information> TCPHandler: Processed in 0.005 sec.

19.13.7.57 Elapsed: 0.011 sec. Processed 100.00 thousand rows,


30.642405 [ 8238 ] <Debug> executeQuery: (from [::1]:37958) INSERT INTO testX SELECT number FROM numbers(100000) SETTINGS max_block_size = 1000000
30.642916 [ 8238 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
30.642994 [ 8238 ] <Debug> executeQuery: Query pipeline:
30.644472 [ 68 ] <Trace> dw.testX: Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
30.644640 [ 110 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
30.644643 [ 95 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
30.644654 [ 86 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
30.644654 [ 71 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
30.644713 [ 75 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
30.644713 [ 92 ] <Trace> InterpreterSelectQuery: FetchColumns -> Complete
30.646644 [ 68 ] <Trace> dw..inner.testXA: Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
30.647871 [ 68 ] <Trace> dw..inner.testXB: Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
30.649033 [ 68 ] <Trace> dw..inner.testXC: Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
30.650233 [ 68 ] <Trace> dw..inner.testXD: Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
30.651459 [ 68 ] <Trace> dw..inner.testXE: Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
30.652714 [ 68 ] <Trace> dw..inner.testXF: Renaming temporary part tmp_insert_all_1_1_0 to all_1_1_0.
30.652812 [ 8238 ] <Information> executeQuery: Read 100000 rows, 781.25 KiB in 0.010 sec., 9649717 rows/sec., 73.62 MiB/sec.
30.652824 [ 8238 ] <Debug> MemoryTracker: Peak memory usage (for query): 6.00 MiB.
30.652873 [ 8238 ] <Debug> MemoryTracker: Peak memory usage (total): 6.00 MiB.
30.652880 [ 8238 ] <Information> TCPHandler: Processed in 0.011 sec.

All inserts are executed by the same thread [ 68 ]

@SaltTan
Copy link
Contributor

SaltTan commented Apr 13, 2020

The change happened in September 2019
19.11.11.57 -> 19.11.12.69
19.13.4.32 -> 19.13.5.44

@nvartolomei
Copy link
Contributor

#7195

@nvartolomei
Copy link
Contributor

Broken in #3796 if I'm not mistaken.

@KochetovNicolai KochetovNicolai mentioned this issue May 8, 2020
Merged
@SaltTan
Copy link
Contributor

SaltTan commented May 26, 2020

This is not fixed.
I've checked 20.4.4.18, all inserts into MVs are done by the same thread consecutively.

@den-crane den-crane reopened this May 26, 2020
@den-crane
Copy link
Contributor Author

den-crane commented May 26, 2020 •
edited

yes, no parallelism during MV inserts (one thread [ 202101 ] for all MV)

20.5.1.3496

insert into testX select number from numbers(100000) settings max_block_size=1000000;

parallel_view_processing=0 Elapsed: 0.010 sec.

parallel_view_processing=1 Elapsed: 0.010 sec. / EXPECTED 0.005 sec.

49.839500 [ 202161 ]  executeQuery: (from [::1]:58112) INSERT INTO testX SELECT number FROM numbers(100000) SETTINGS max_block_size = 1000000
49.839558 [ 202161 ]  ContextAccess (default): Access granted: INSERT(A) ON dw.testX
49.839589 [ 202161 ]  ContextAccess (default): Access granted: CREATE TEMPORARY TABLE ON *.*
49.839694 [ 202161 ]  InterpreterSelectQuery: FetchColumns -> Complete
49.839763 [ 202161 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.839777 [ 202161 ]  ContextAccess (default): Access granted: INSERT(A) ON dw.`.inner.testXA`
49.839816 [ 202161 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.839826 [ 202161 ]  ContextAccess (default): Access granted: INSERT(A) ON dw.`.inner.testXB`
49.839863 [ 202161 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.839873 [ 202161 ]  ContextAccess (default): Access granted: INSERT(A) ON dw.`.inner.testXC`
49.839909 [ 202161 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.839919 [ 202161 ]  ContextAccess (default): Access granted: INSERT(A) ON dw.`.inner.testXD`
49.839954 [ 202161 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.839976 [ 202161 ]  ContextAccess (default): Access granted: INSERT(A) ON dw.`.inner.testXE`
49.840014 [ 202161 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.840024 [ 202161 ]  ContextAccess (default): Access granted: INSERT(A) ON dw.`.inner.testXF`
49.840079 [ 202161 ]  executeQuery: Query pipeline:
49.840317 [ 202101 ]  DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 588.93 GiB.
49.841459 [ 202101 ]  dw.testX: Renaming temporary part tmp_insert_all_4_4_0 to all_4_4_0.
49.841604 [ 202124 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.841632 [ 202143 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.841632 [ 202146 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.841638 [ 202124 ]  InterpreterSelectQuery: FetchColumns -> Complete
49.841641 [ 202157 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.841658 [ 202146 ]  InterpreterSelectQuery: FetchColumns -> Complete
49.841660 [ 202143 ]  InterpreterSelectQuery: FetchColumns -> Complete
49.841669 [ 202157 ]  InterpreterSelectQuery: FetchColumns -> Complete
49.841719 [ 202126 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.841719 [ 202154 ]  ContextAccess (default): Access granted: SELECT(A) ON dw.testX
49.841764 [ 202154 ]  InterpreterSelectQuery: FetchColumns -> Complete
49.841764 [ 202126 ]  InterpreterSelectQuery: FetchColumns -> Complete
49.841846 [ 202101 ]  DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 588.93 GiB.
49.842991 [ 202101 ]  dw.`.inner.testXA`: Renaming temporary part tmp_insert_all_4_4_0 to all_4_4_0.
49.843024 [ 202101 ]  DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 588.93 GiB.
49.844130 [ 202101 ]  dw.`.inner.testXB`: Renaming temporary part tmp_insert_all_4_4_0 to all_4_4_0.
49.844157 [ 202101 ]  DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 588.93 GiB.
49.845262 [ 202101 ]  dw.`.inner.testXC`: Renaming temporary part tmp_insert_all_4_4_0 to all_4_4_0.
49.845287 [ 202101 ]  DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 588.93 GiB.
49.846409 [ 202101 ]  dw.`.inner.testXD`: Renaming temporary part tmp_insert_all_4_4_0 to all_4_4_0.
49.846436 [ 202101 ]  DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 588.93 GiB.
49.847540 [ 202101 ]  dw.`.inner.testXE`: Renaming temporary part tmp_insert_all_4_4_0 to all_4_4_0.
49.847565 [ 202101 ]  DiskLocal: Reserving 1.00 MiB on disk `default`, having unreserved 588.93 GiB.
49.848670 [ 202101 ]  dw.`.inner.testXF`: Renaming temporary part tmp_insert_all_4_4_0 to all_4_4_0.
49.848767 [ 202161 ]  <Information> executeQuery: Read 100000 rows, 781.25 KiB in 0.009 sec., 10835079 rows/sec., 82.67 MiB/sec.
49.848782 [ 202161 ]  MemoryTracker: Peak memory usage (for query): 14.99 KiB.

@KochetovNicolai KochetovNicolai mentioned this issue Jun 1, 2020
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@KochetovNicolai KochetovNicolai

Labels
performance
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix parallel MV ClickHouse/ClickHouse
More parallel MV processing. ClickHouse/ClickHouse
5 participants
@nvartolomei @filimonov @KochetovNicolai @den-crane @SaltTan