Skip to content

[refactor](log) Add some log for table and db transaction manager's lock #40746

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
Merged
lide-reed merged 2 commits into from
Sep 20, 2024
Merged

[refactor](log) Add some log for table and db transaction manager's lock #40746

lide-reed merged 2 commits into from
Sep 20, 2024

Conversation

@liutang123
Copy link
Contributor

@liutang123 liutang123 commented Sep 12, 2024 •
edited
Loading

Proposed changes

Use the fe config like #39015, print table lock usage duration.
In 2.0.6, I found replayer thread is blocked for a long time.

2024-09-12 11:00:58,797 INFO (replayer|89) [DatabaseTransactionMgr.replayUpsertTransactionState():1977] replay a visible transaction TransactionState. transaction id: 471728922, label: flink_connector_20240912_103150_269f8d635ffb455bb4043eecd1a8406b, db id: 475180, table id list: 14473765, callback id: -1, coordinator: BE: 10.217.0.100, transaction status: VISIBLE, error replicas num: 0, replica ids: , prepare time: 1726108310505, commit time: 1726108310579, finish time: 1726108310604, reason: 
2024-09-12 11:00:58,798 WARN (replayer|89) [Env.replayJournal():2575] entityCost:940256 loadJournalCost:940256 logId:1392353661 replayedJournalId:1392353661 code:100 size:562

And, there are many table lock fail log:

2024-09-12 10:56:53,167 WARN (mysql-nio-pool-32036|412611) [Table.tryReadLock():155] Failed to try table atdpersonpaycode's read lock. timeout 1 MINUTES. Current owner: null

But, I don't kown what thread hold the table lock.
So, add some logs to print lock holding info.

Issue Number: close #xxx

@doris-robot
Copy link

doris-robot commented Sep 12, 2024

Thank you for your contribution to Apache Doris.
Don't know what should be done next? See How to process your PR

Since 2024-03-18, the Document has been moved to doris-website.
See Doris Document.

@liutang123
Copy link
Contributor Author

liutang123 commented Sep 12, 2024

run buildall

@doris-robot
Copy link

doris-robot commented Sep 12, 2024

TPC-H: Total hot run time: 50429 ms 
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpch-tools
Tpch sf100 test result on commit c8b9a6a05e4a2bb962317a48ed6bf38301a226c3, data reload: false

------ Round 1 ----------------------------------
q1	17535	4398	4364	4364
q2	2066	158	147	147
q3	10260	1937	1933	1933
q4	10106	1265	1354	1265
q5	8432	3940	3980	3940
q6	246	127	124	124
q7	2025	1611	1634	1611
q8	9304	2783	2763	2763
q9	10649	10653	10662	10653
q10	8628	3598	3561	3561
q11	416	246	242	242
q12	476	293	301	293
q13	18343	3986	4077	3986
q14	350	330	331	330
q15	522	465	472	465
q16	542	458	450	450
q17	1166	982	986	982
q18	7392	6963	7056	6963
q19	1684	1551	1556	1551
q20	523	303	308	303
q21	4508	4126	4135	4126
q22	500	400	377	377
Total cold run time: 115673 ms
Total hot run time: 50429 ms

----- Round 2, with runtime_filter_mode=off -----
q1	4378	4313	4332	4313
q2	323	224	221	221
q3	4175	4213	4151	4151
q4	2773	2768	2756	2756
q5	7234	7139	7174	7139
q6	244	119	118	118
q7	3240	2863	2929	2863
q8	4376	4478	4509	4478
q9	14243	14045	13946	13946
q10	4274	4298	4280	4280
q11	763	682	691	682
q12	1032	872	857	857
q13	6688	3776	3753	3753
q14	462	422	432	422
q15	499	469	457	457
q16	641	613	603	603
q17	3858	3872	3820	3820
q18	8876	8782	8867	8782
q19	1736	1680	1715	1680
q20	2378	2112	2139	2112
q21	8540	8500	8541	8500
q22	1095	921	981	921
Total cold run time: 81828 ms
Total hot run time: 76854 ms

@doris-robot
Copy link

doris-robot commented Sep 12, 2024

TPC-DS: Total hot run time: 213695 ms 
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/tpcds-tools
TPC-DS sf100 test result on commit c8b9a6a05e4a2bb962317a48ed6bf38301a226c3, data reload: false

query1	916	420	376	376
query2	6536	2309	2212	2212
query3	6924	219	208	208
query4	23362	21645	21504	21504
query5	19737	6528	6540	6528
query6	282	220	245	220
query7	4331	302	308	302
query8	267	250	231	231
query9	3016	2631	2556	2556
query10	467	309	316	309
query11	15804	15058	15472	15058
query12	118	79	78	78
query13	1035	440	440	440
query14	17236	13737	13660	13660
query15	371	224	233	224
query16	6373	275	262	262
query17	1767	908	915	908
query18	891	317	320	317
query19	214	155	147	147
query20	79	77	83	77
query21	192	106	96	96
query22	5327	5282	5217	5217
query23	34413	33439	33467	33439
query24	7836	6356	6335	6335
query25	521	444	434	434
query26	1278	163	161	161
query27	2432	298	293	293
query28	6058	2243	2217	2217
query29	2918	2939	2863	2863
query30	243	174	165	165
query31	973	736	743	736
query32	73	63	56	56
query33	461	270	254	254
query34	859	462	471	462
query35	1167	929	981	929
query36	1459	1212	1148	1148
query37	166	59	61	59
query38	3045	2973	2919	2919
query39	1386	1330	1339	1330
query40	303	94	95	94
query41	40	39	37	37
query42	82	89	87	87
query43	640	624	673	624
query44	1198	714	717	714
query45	247	234	233	233
query46	1241	977	985	977
query47	1887	1659	1722	1659
query48	501	410	405	405
query49	641	375	376	375
query50	859	614	611	611
query51	4780	4656	4676	4656
query52	95	76	87	76
query53	236	185	185	185
query54	2706	2476	2520	2476
query55	89	91	84	84
query56	221	209	216	209
query57	1188	1038	1202	1038
query58	226	215	218	215
query59	3549	3305	3483	3305
query60	222	202	206	202
query61	98	94	94	94
query62	782	494	466	466
query63	198	177	170	170
query64	3578	1601	1507	1507
query65	3638	3574	3559	3559
query66	768	392	419	392
query67	15869	15466	15209	15209
query68	9130	667	658	658
query69	494	266	275	266
query70	1650	1430	1447	1430
query71	389	305	314	305
query72	6733	4758	4836	4758
query73	763	327	324	324
query74	6369	5854	5876	5854
query75	4587	3681	3722	3681
query76	4796	1141	1204	1141
query77	683	256	268	256
query78	12735	11814	11976	11814
query79	6149	642	636	636
query80	1790	375	387	375
query81	489	240	248	240
query82	1624	97	96	96
query83	173	132	135	132
query84	263	70	70	70
query85	1011	328	319	319
query86	347	293	291	291
query87	3243	3020	3013	3013
query88	4818	2373	2370	2370
query89	420	298	310	298
query90	1880	219	214	214
query91	159	126	127	126
query92	60	50	50	50
query93	5141	534	563	534
query94	780	211	210	210
query95	2098	1979	2016	1979
query96	649	335	336	335
query97	6540	6393	6494	6393
query98	227	209	213	209
query99	2804	952	929	929
Total cold run time: 315409 ms
Total hot run time: 213695 ms

@doris-robot
Copy link

doris-robot commented Sep 12, 2024

ClickBench: Total hot run time: 31.41 s 
machine: 'aliyun_ecs.c7a.8xlarge_32C64G'
scripts: https://github.com/apache/doris/tree/master/tools/clickbench-tools
ClickBench test result on commit c8b9a6a05e4a2bb962317a48ed6bf38301a226c3, data reload: false

query1	0.02	0.02	0.02
query2	0.08	0.02	0.02
query3	0.25	0.05	0.06
query4	1.78	0.07	0.06
query5	0.54	0.53	0.52
query6	1.26	0.61	0.61
query7	0.01	0.01	0.01
query8	0.03	0.02	0.02
query9	0.53	0.49	0.48
query10	0.54	0.54	0.54
query11	0.12	0.08	0.08
query12	0.12	0.08	0.09
query13	0.62	0.62	0.61
query14	0.77	0.79	0.79
query15	0.77	0.77	0.76
query16	0.37	0.39	0.39
query17	1.03	0.97	1.02
query18	0.20	0.28	0.23
query19	1.94	1.89	1.85
query20	0.02	0.01	0.01
query21	15.46	0.55	0.55
query22	2.20	2.36	1.42
query23	16.63	1.10	0.97
query24	4.74	1.68	1.75
query25	0.37	0.07	0.04
query26	0.64	0.16	0.17
query27	0.04	0.04	0.04
query28	7.66	0.71	0.71
query29	12.71	2.37	2.33
query30	0.58	0.52	0.53
query31	2.82	0.41	0.38
query32	3.46	0.51	0.50
query33	3.09	3.06	3.05
query34	15.27	4.83	4.85
query35	4.90	4.86	4.86
query36	1.05	1.01	1.02
query37	0.06	0.05	0.04
query38	0.03	0.03	0.03
query39	0.02	0.01	0.02
query40	0.15	0.15	0.14
query41	0.07	0.02	0.01
query42	0.02	0.01	0.02
query43	0.02	0.02	0.02
Total cold run time: 102.99 s
Total hot run time: 31.41 s

@doris-robot
Copy link

doris-robot commented Sep 12, 2024

Load test result on machine: 'aliyun_ecs.c7a.8xlarge_32C64G'

Load test result on commit c8b9a6a05e4a2bb962317a48ed6bf38301a226c3 with default session variables
Stream load json:         20 seconds loaded 2358488459 Bytes, about 112 MB/s
Stream load orc:          58 seconds loaded 1101869774 Bytes, about 18 MB/s
Stream load parquet:      31 seconds loaded 861443392 Bytes, about 26 MB/s
Insert into select:       21.0 seconds inserted 10000000 Rows, about 476K ops/s

lide-reed
lide-reed approved these changes Sep 12, 2024
View reviewed changes
Copy link
Contributor

@lide-reed lide-reed left a comment

Choose a reason for hiding this comment

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

LGTM

@github-actions github-actions bot added the approved Indicates a PR has been approved by one committer. label Sep 12, 2024
@github-actions
Copy link
Contributor

github-actions bot commented Sep 12, 2024

PR approved by at least one committer and no changes requested.

@github-actions
Copy link
Contributor

github-actions bot commented Sep 12, 2024

PR approved by anyone and no changes requested.

xy720
xy720 reviewed Sep 12, 2024
View reviewed changes
@liutang123
Copy link
Contributor Author

liutang123 commented Sep 20, 2024

run buildall

@lide-reed lide-reed merged commit abefe26 into apache:branch-2.0 Sep 20, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@lide-reed lide-reed lide-reed approved these changes

@cambyzju cambyzju cambyzju approved these changes

@xy720 xy720 xy720 approved these changes

Assignees

No one assigned

Labels

approved Indicates a PR has been approved by one committer. reviewed

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

5 participants

@liutang123 @doris-robot @lide-reed @cambyzju @xy720