Skip to content

Commit b5bbc1b

Browse files
author
Sven Sandberg
committed
BUG#21127308: REPLICATION THREAD STATUSES NOT SHOWN IN PERFORMANCE_SCHEMA
Some thread statuses related to replication were not included in the all_server_stages[] array. That resulted in performance_schema.threads showing NULL in the PROCESSLIST_STATUS column (but SHOW PROCESSLIST showed the correct status). Fixed by including these thread statuses in the array. Additionally: - Changed "Waiting for slave workers to finish." to "Waiting for slave workers to process their queues". - Changed "Waiting for GTID to be written to the binary log" to "Waiting for GTID to be committed" - Changed "Waiting for its turn to commit." to "Waiting for preceding transaction to commit" - Changed "Waiting for dependent transaction to commit." to "Waiting for dependent transaction to commit" Tests: - mysql-test/suite/rpl/t/rpl_mts_logical_clock_crash.test failed becuase it was waiting for stage_slave_waiting_for_workers_to_finish. Fixed the test. Also noticed that despite there was a timeout in wait_condition.inc, it just printed a message and continued running the test; it did not source show_rpl_debug_info.inc and did not execute 'die'. Added call to show_rpl_debug_info.inc if $show_rpl_debug_info is set (also in some other include/wait_*.inc files), and made rpl_init.inc set $show_rpl_debug_info.
1 parent b9b03fa commit b5bbc1b

13 files changed

+223
-32
lines changed

‎mysql-test/include/rpl_init.inc

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -396,6 +396,10 @@ if ($rpl_inited)
396396
}
397397
--let $rpl_inited= 1
398398

399+
# Set $show_rpl_debug_info to make subsequent failures in
400+
# e.g. wait_condition.inc print replication debug output.
401+
--let $show_rpl_debug_info= 1
402+
399403

400404
# Indicate that the server is in a dirty state and needs to be restarted
401405
# if the test is skipped. If the test is not skipped, it will continue

‎mysql-test/include/wait_condition.inc

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -53,4 +53,9 @@ while ($wait_counter)
5353
if (!$success)
5454
{
5555
echo Timeout in wait_condition.inc for $wait_condition;
56+
if ($show_rpl_debug_info)
57+
{
58+
--source include/show_rpl_debug_info.inc
59+
--die Timeout in wait_condition.inc for $wait_condition
60+
}
5661
}

‎mysql-test/include/wait_for_query_to_fail.inc

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,10 @@ while (!$mysql_errno)
1717

1818
if (!$counter)
1919
{
20+
if ($show_rpl_debug_info)
21+
{
22+
--source include/show_rpl_debug_info.inc
23+
}
2024
--die "Waited too long for query to fail";
2125
}
2226
}

‎mysql-test/include/wait_show_condition.inc

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -127,10 +127,18 @@ if ($wait_for_all == 1)
127127

128128
if (!$found)
129129
{
130+
if ($show_rpl_debug_info)
131+
{
132+
--source include/show_rpl_debug_info.inc
133+
}
130134
echo # Timeout in include/wait_show_condition.inc for $condition;
131135
echo # show_statement : $show_statement;
132136
echo # field : $field;
133137
echo # condition : $condition;
134138
echo # max_run_time : $max_run_time;
139+
if ($show_rpl_debug_info)
140+
{
141+
--die Timeout in wait_show_condition.inc for $condition
142+
}
135143
}
136144

‎mysql-test/include/wait_until_disconnected.inc

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,11 @@ while (!$mysql_errno)
1717
dec $counter;
1818
if (!$counter)
1919
{
20+
if ($show_rpl_debug_info)
21+
{
22+
--source include/show_rpl_debug_info.inc
23+
--echo current_connectio= $CURRENT_CONNECTION
24+
}
2025
--die Server failed to dissapear
2126
}
2227
--sleep 0.1

‎mysql-test/suite/rpl/r/rpl_perfschema_threads_processlist_status.result

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,17 @@
1+
include/master-slave.inc
2+
Warnings:
3+
Note #### Sending passwords in plain text without SSL/TLS is extremely insecure.
4+
Note #### Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
5+
[connection master]
6+
==== Initialize ====
7+
SET GLOBAL SLAVE_TRANSACTION_RETRIES= 0;
8+
SET GLOBAL SLAVE_PARALLEL_WORKERS= 1;
9+
include/start_slave.inc
10+
==== Test ====
11+
include/assert.inc [The worker status should be set in P_S.threads]
12+
==== Look for more mistakes in mysqld.cc ====
13+
==== Clean up ====
14+
include/stop_slave.inc
15+
SET GLOBAL SLAVE_PARALLEL_WORKERS= OLD_VALUE;
16+
SET GLOBAL SLAVE_TRANSACTION_RETRIES= OLD_VALUE;
17+
include/rpl_end.inc

‎mysql-test/suite/rpl/t/rpl_mts_logical_clock_crash.test

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -72,7 +72,7 @@ LOCK TABLE t1 WRITE;
7272
# Wait unti coordinator enters the wait status.
7373
--let $show_statement= SHOW PROCESSLIST
7474
--let $field= State
75-
--let $condition= = 'Waiting for slave workers to finish.'
75+
--let $condition= = 'Waiting for slave workers to process their queues'
7676
--source include/wait_show_condition.inc
7777

7878
# Release metadata lock on t1, so workers can go ahead.

‎mysql-test/suite/rpl/t/rpl_mts_slave_preserve_commit_order_deadlock.test

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -70,7 +70,7 @@ INSERT INTO t1 VALUES(11, 11);
7070

7171
# It guarantees the DELETE statement is waiting for
7272
# the transaction before it to commit
73-
--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE STATE = "Waiting for its turn to commit."
73+
--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE STATE = "Waiting for preceding transaction to commit"
7474
--source include/wait_condition.inc
7575

7676
# Resume the INSERT statement and trigger the deadlock
@@ -177,7 +177,7 @@ INSERT INTO t1 VALUES(33, 33);
177177
--source include/start_slave_sql.inc
178178

179179
# It guarantees 'DELETE' statement is waiting for the transactions before it.
180-
--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE STATE = "Waiting for its turn to commit."
180+
--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE STATE = "Waiting for preceding transaction to commit"
181181
--source include/wait_condition.inc
182182

183183
# Trigger one deadlock
@@ -189,7 +189,7 @@ ROLLBACK;
189189
--source include/wait_condition.inc
190190

191191
# It guarantees 'DELETE' statement is waiting for the transactions before it.
192-
--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE STATE = "Waiting for its turn to commit."
192+
--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE STATE = "Waiting for preceding transaction to commit"
193193
--source include/wait_condition.inc
194194

195195
# Trigger another deadlock
@@ -223,7 +223,7 @@ INSERT INTO t2 SELECT * FROM mysql.innodb_table_stats;
223223
--source include/start_slave_sql.inc
224224

225225
# It guarantees 'INSERT' statement is waiting for the transactions before it.
226-
--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE STATE = "Waiting for its turn to commit."
226+
--let $wait_condition= SELECT count(*) = 1 FROM information_schema.processlist WHERE STATE = "Waiting for preceding transaction to commit"
227227
--source include/wait_condition.inc
228228

229229
UNLOCK TABLES;

‎mysql-test/suite/rpl/t/rpl_perfschema_threads_processlist_status.test

Lines changed: 139 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,139 @@
1+
# ==== Purpose ====
2+
#
3+
# Verify that performance_schema.threads shows the correct
4+
# PROCESSLIST_INFO for all thread stages.
5+
#
6+
# This is to verify that BUG#21127308 has been fixed. In the bug, the
7+
# status of a replication worker thread waiting for more work (and
8+
# several others) was not included in the array all_server_stages[],
9+
# which caused PROCESSLIST_INFO in performance_schema.threads to be
10+
# NULL for such threads.
11+
#
12+
# ==== Implementation ====
13+
#
14+
# It's hard to simulate all possible thread stages, as each case needs
15+
# to be simulated in its own ad-hoc way, likely using debug sync
16+
# points.
17+
#
18+
# Instead, we verify the bug just for one of the stages that was
19+
# missing in the bug. Then, we parse mysqld.cc to find if there are
20+
# any stages declared which are not listed in the array.
21+
#
22+
# This works currently, but the parsing depends on the current
23+
# formatting in mysqld. So this test will fail if e.g. the
24+
# declarations are moved to another file, or the datatype
25+
# PSI_stage_info is renamed, etc. If that happens, please update this
26+
# script accordingly.
27+
#
28+
# ==== Related bugs ====
29+
#
30+
# BUG#21127308: REPLICATION THREAD STATUSES NOT SHOWN IN PERFORMANCE_SCHEMA
31+
# - Test was added in this bug.
32+
33+
# Test is binlog_format-agnostic
34+
--source include/have_binlog_format_row.inc
35+
--let $rpl_skip_start_slave= 1
36+
--source include/master-slave.inc
37+
38+
--echo ==== Initialize ====
39+
40+
--connection slave
41+
--let $old_slave_parallel_workers= `SELECT @@GLOBAL.SLAVE_PARALLEL_WORKERS`
42+
--let $old_slave_transaction_retries= `SELECT @@GLOBAL.SLAVE_TRANSACTION_RETRIES`
43+
SET GLOBAL SLAVE_TRANSACTION_RETRIES= 0;
44+
SET GLOBAL SLAVE_PARALLEL_WORKERS= 1;
45+
--source include/start_slave.inc
46+
47+
--echo ==== Test ====
48+
49+
--let $show_statement= SHOW PROCESSLIST
50+
--let $field= State
51+
--let $condition= = 'Waiting for an event from Coordinator'
52+
--source include/wait_show_condition.inc
53+
54+
--let $assert_cond= COUNT(*) = 1 FROM performance_schema.threads WHERE PROCESSLIST_STATE = "Waiting for an event from Coordinator"
55+
--let $assert_text= The worker status should be set in P_S.threads
56+
--source include/assert.inc
57+
58+
--echo ==== Look for more mistakes in mysqld.cc ====
59+
60+
perl;
61+
# Find the location of mysqld.cc, if available.
62+
my $mysqld;
63+
for my $location ('../sql', '../../sql', '../../../sql')
64+
{
65+
if (-f "$location/mysqld.cc") {
66+
$mysqld= "$location/mysqld.cc";
67+
last;
68+
}
69+
}
70+
71+
# Tests may be installed in a completely different directory, in
72+
# which case the source is not reachable. In that case, just skip
73+
# this part of the test.
74+
if ($mysqld)
75+
{
76+
# List of all stages declared in mysqld.cc
77+
my %declared_stages= ();
78+
# Hash of all stages included in the all_server_stages array.
79+
my @listed_stages= ();
80+
81+
# This flag is set to true while processing lines from the array
82+
# initialization.
83+
my $in_server_stage_list= 0;
84+
85+
# Process mysqld.cc
86+
open MYSQLD_CC, $mysqld or die "Error $? opening $mysqld: $!";
87+
while (<MYSQLD_CC>)
88+
{
89+
# Read declaration.
90+
if (/PSI_stage_info\s+([A-Za-z_0-9]+)\s*=/)
91+
{
92+
$declared_stages{$1} = 1;
93+
}
94+
# Figure out when we enter and leave the array initialization.
95+
elsif (/PSI_stage_info\s*\*\s*all_server_stages\s*\[/)
96+
{
97+
$in_server_stage_list= 1;
98+
}
99+
elsif (/\};/) {
100+
$in_server_stage_list= 0;
101+
}
102+
# Read element from list.
103+
elsif ($in_server_stage_list &&
104+
/\&\s*([A-Za-z_0-9]+)\s*,?/)
105+
{
106+
push(@listed_stages, $1);
107+
}
108+
}
109+
close MYSQLD_CC or die "Error $? closing $mysqld: $!";
110+
111+
# Sanity check, so that change in the format or naming doesn't make
112+
# this test useless.
113+
if (scalar(keys(%declared_stages)) < 10)
114+
{
115+
die "No declared stages found. Probably the format of stage declarations has changed; please update the regular expressions in this test to match the new format.";
116+
}
117+
118+
# Check that every declared stage was found in the array.
119+
for my $stage (@listed_stages)
120+
{
121+
delete($declared_stages{$stage});
122+
}
123+
if (scalar(%declared_stages))
124+
{
125+
die "Error: the following stages were declared in mysqld.cc but not listed in all_server_stages: " . join(", ", sort(keys(%declared_stages))) . ". This will make the PROCESSLIST_STATE column of performance_schema.threads show NULL when a thread is in this stage.";
126+
}
127+
}
128+
EOF
129+
130+
--echo ==== Clean up ====
131+
132+
--source include/stop_slave.inc
133+
--replace_result $old_slave_parallel_workers OLD_VALUE
134+
eval SET GLOBAL SLAVE_PARALLEL_WORKERS= $old_slave_parallel_workers;
135+
--replace_result $old_slave_transaction_retries OLD_VALUE
136+
eval SET GLOBAL SLAVE_TRANSACTION_RETRIES= $old_slave_transaction_retries;
137+
138+
--let $rpl_only_running_threads= 1
139+
--source include/rpl_end.inc

‎sql/mysqld.cc

Lines changed: 22 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -8665,6 +8665,7 @@ PSI_stage_info stage_checking_privileges_on_cached_query= { 0, "checking privile
86658665
PSI_stage_info stage_checking_query_cache_for_query= { 0, "checking query cache for query", 0};
86668666
PSI_stage_info stage_cleaning_up= { 0, "cleaning up", 0};
86678667
PSI_stage_info stage_closing_tables= { 0, "closing tables", 0};
8668+
PSI_stage_info stage_compressing_gtid_table= { 0, "Compressing gtid_executed table", 0};
86688669
PSI_stage_info stage_connecting_to_master= { 0, "Connecting to master", 0};
86698670
PSI_stage_info stage_converting_heap_to_ondisk= { 0, "converting HEAP to ondisk", 0};
86708671
PSI_stage_info stage_copying_to_group_table= { 0, "Copying to group table", 0};
@@ -8717,6 +8718,12 @@ PSI_stage_info stage_sending_cached_result_to_client= { 0, "sending cached resul
87178718
PSI_stage_info stage_sending_data= { 0, "Sending data", 0};
87188719
PSI_stage_info stage_setup= { 0, "setup", 0};
87198720
PSI_stage_info stage_slave_has_read_all_relay_log= { 0, "Slave has read all relay log; waiting for more updates", 0};
8721+
PSI_stage_info stage_slave_waiting_event_from_coordinator= { 0, "Waiting for an event from Coordinator", 0};
8722+
PSI_stage_info stage_slave_waiting_for_workers_to_process_queue= { 0, "Waiting for slave workers to process their queues", 0};
8723+
PSI_stage_info stage_slave_waiting_worker_queue= { 0, "Waiting for Slave Worker queue", 0};
8724+
PSI_stage_info stage_slave_waiting_worker_to_free_events= { 0, "Waiting for Slave Workers to free pending events", 0};
8725+
PSI_stage_info stage_slave_waiting_worker_to_release_partition= { 0, "Waiting for Slave Worker to release partition", 0};
8726+
PSI_stage_info stage_slave_waiting_workers_to_exit= { 0, "Waiting for workers to exit", 0};
87208727
PSI_stage_info stage_sorting_for_group= { 0, "Sorting for group", 0};
87218728
PSI_stage_info stage_sorting_for_order= { 0, "Sorting for order", 0};
87228729
PSI_stage_info stage_sorting_result= { 0, "Sorting result", 0};
@@ -8732,7 +8739,7 @@ PSI_stage_info stage_updating_reference_tables= { 0, "updating reference tables"
87328739
PSI_stage_info stage_upgrading_lock= { 0, "upgrading lock", 0};
87338740
PSI_stage_info stage_user_sleep= { 0, "User sleep", 0};
87348741
PSI_stage_info stage_verifying_table= { 0, "verifying table", 0};
8735-
PSI_stage_info stage_waiting_for_gtid_to_be_written_to_binary_log= { 0, "waiting for GTID to be written to binary log", 0};
8742+
PSI_stage_info stage_waiting_for_gtid_to_be_committed= { 0, "Waiting for GTID to be committed", 0};
87368743
PSI_stage_info stage_waiting_for_handler_insert= { 0, "waiting for handler insert", 0};
87378744
PSI_stage_info stage_waiting_for_handler_lock= { 0, "waiting for handler lock", 0};
87388745
PSI_stage_info stage_waiting_for_handler_open= { 0, "waiting for handler open", 0};
@@ -8747,19 +8754,11 @@ PSI_stage_info stage_waiting_for_query_cache_lock= { 0, "Waiting for query cache
87478754
PSI_stage_info stage_waiting_for_the_next_event_in_relay_log= { 0, "Waiting for the next event in relay log", 0};
87488755
PSI_stage_info stage_waiting_for_the_slave_thread_to_advance_position= { 0, "Waiting for the slave SQL thread to advance position", 0};
87498756
PSI_stage_info stage_waiting_to_finalize_termination= { 0, "Waiting to finalize termination", 0};
8750-
PSI_stage_info stage_slave_waiting_workers_to_exit= { 0, "Waiting for workers to exit", 0};
8751-
PSI_stage_info stage_slave_waiting_worker_to_release_partition= { 0, "Waiting for Slave Worker to release partition", 0};
8752-
PSI_stage_info stage_slave_waiting_worker_to_free_events= { 0, "Waiting for Slave Workers to free pending events", 0};
8753-
PSI_stage_info stage_slave_waiting_worker_queue= { 0, "Waiting for Slave Worker queue", 0};
8754-
PSI_stage_info stage_slave_waiting_event_from_coordinator= { 0, "Waiting for an event from Coordinator", 0};
8755-
PSI_stage_info stage_slave_waiting_for_workers_to_finish= { 0, "Waiting for slave workers to finish.", 0};
8756-
PSI_stage_info stage_compressing_gtid_table= { 0, "Compressing gtid_executed table", 0};
8757+
PSI_stage_info stage_worker_waiting_for_its_turn_to_commit= { 0, "Waiting for preceding transaction to commit", 0};
8758+
PSI_stage_info stage_worker_waiting_for_commit_parent= { 0, "Waiting for dependent transaction to commit", 0};
87578759
PSI_stage_info stage_suspending= { 0, "Suspending", 0};
8758-
#ifdef HAVE_REPLICATION
8759-
PSI_stage_info stage_worker_waiting_for_its_turn_to_commit= { 0, "Waiting for its turn to commit.", 0};
8760-
PSI_stage_info stage_worker_waiting_for_commit_parent= { 0, "Waiting for dependent transaction to commit.", 0};
8761-
#endif
87628760
PSI_stage_info stage_starting= { 0, "starting", 0};
8761+
87638762
#ifdef HAVE_PSI_INTERFACE
87648763

87658764
PSI_stage_info *all_server_stages[]=
@@ -8776,6 +8775,7 @@ PSI_stage_info *all_server_stages[]=
87768775
& stage_checking_query_cache_for_query,
87778776
& stage_cleaning_up,
87788777
& stage_closing_tables,
8778+
& stage_compressing_gtid_table,
87798779
& stage_connecting_to_master,
87808780
& stage_converting_heap_to_ondisk,
87818781
& stage_copying_to_group_table,
@@ -8828,6 +8828,12 @@ PSI_stage_info *all_server_stages[]=
88288828
& stage_sending_data,
88298829
& stage_setup,
88308830
& stage_slave_has_read_all_relay_log,
8831+
& stage_slave_waiting_event_from_coordinator,
8832+
& stage_slave_waiting_for_workers_to_process_queue,
8833+
& stage_slave_waiting_worker_queue,
8834+
& stage_slave_waiting_worker_to_free_events,
8835+
& stage_slave_waiting_worker_to_release_partition,
8836+
& stage_slave_waiting_workers_to_exit,
88318837
& stage_sorting_for_group,
88328838
& stage_sorting_for_order,
88338839
& stage_sorting_result,
@@ -8843,20 +8849,23 @@ PSI_stage_info *all_server_stages[]=
88438849
& stage_upgrading_lock,
88448850
& stage_user_sleep,
88458851
& stage_verifying_table,
8852+
& stage_waiting_for_gtid_to_be_committed,
88468853
& stage_waiting_for_handler_insert,
88478854
& stage_waiting_for_handler_lock,
88488855
& stage_waiting_for_handler_open,
88498856
& stage_waiting_for_insert,
88508857
& stage_waiting_for_master_to_send_event,
88518858
& stage_waiting_for_master_update,
8859+
& stage_waiting_for_relay_log_space,
88528860
& stage_waiting_for_slave_mutex_on_exit,
88538861
& stage_waiting_for_slave_thread_to_start,
88548862
& stage_waiting_for_table_flush,
88558863
& stage_waiting_for_query_cache_lock,
88568864
& stage_waiting_for_the_next_event_in_relay_log,
88578865
& stage_waiting_for_the_slave_thread_to_advance_position,
88588866
& stage_waiting_to_finalize_termination,
8859-
& stage_compressing_gtid_table,
8867+
& stage_worker_waiting_for_its_turn_to_commit,
8868+
& stage_worker_waiting_for_commit_parent,
88608869
& stage_suspending,
88618870
& stage_starting
88628871
};

0 commit comments

Comments
 (0)