Percona Server moved to https://jira.percona.com/projects/PS

Merge lp:~tsarev/percona-server/12952 into lp:percona-server/5.1

  1. 12952
  2. Merge into 5.1
Proposed by Oleg Tsarev
Status: Merged
Merged at revision: 283
Proposed branch: lp:~tsarev/percona-server/12952
Merge into: lp:percona-server/5.1
Diff against target: 364 lines (+250/-68)
1 file modified
patches/show_slave_status_nolock.patch (+250/-68)
To merge this branch: bzr merge lp:~tsarev/percona-server/12952
Reviewer Review Type Date Requested Status
Alexey Kopytov (community) Approve
Oleg Tsarev Pending
Review via email: mp+75708@code.launchpad.net

This proposal supersedes a proposal from 2011-09-16.

Description of the change

Add test-case for bug #851011: SHOW SLAVE STATUS NOLOCK acquire lock on
  sql/slave.cc: 1650
    pthread_mutex_lock(&mi->run_lock);
Fix: wrap mutex lock/unlock by check to \"UNLOCK\" statement
Issue number: #12952.

To post a comment you must log in.
Revision history for this message
Alexey Kopytov (akopytov) wrote : Posted in a previous version of this proposal

I don't see a point in reviewing a test case separately from the fix. For example, is the .result file from the test with the bug fixed or not?

And I still don't see a detailed description of the problem we are trying to fix, which complicates reviewing the test case even further. No, the reported bug does not help much either. "SHOW SLAVE STATUS NOLOCK acquire lock on some mutex" sounds like the problem is not quite clear.

review: Disapprove
Revision history for this message
Oleg Tsarev (tsarev) wrote : Posted in a previous version of this proposal

This test-case check feature "SHOW SLAVE STATUS NOLOCK" workability.
Test-case according to issue number 12952 (customer-case).
Result file contain correct result of run, if feature works fine.
Right now this test fails.

> "SHOW SLAVE STATUS NOLOCK acquire lock on some mutex" sounds like the problem is not quite clear.
Fix will ve in another MP, this is just a test-case.

Please note:
What exactly you don't understand or don't like in this MP?

review: Needs Resubmitting
Revision history for this message
Alexey Kopytov (akopytov) wrote : Posted in a previous version of this proposal

Please submit a MP for the full bugfix including the test case and update the bug report so that it's clear which specific mutex is holding SHOW SLAVE STATUS NOLOCK under what circumstances.

Revision history for this message
Oleg Tsarev (tsarev) wrote :

For detalise circumstances need additional investigation.
If you think investigation are required - I can complete it.

Revision history for this message
Oleg Tsarev (tsarev) wrote :

Additional information about circumstances.

1) SHOW SLAVE STATUS [NOLOCK] passed following mutexes:
query: SHOW SLAVE STATUS
| | mutex: 'LOCK_active_mi' lock FILE: sql_parse.cc LINE: 2597
| | | mutex: 'Master_info::run_lock' lock FILE: slave.cc LINE: 1650
| | | mutex: 'Master_info::run_lock' unlock FILE: slave.cc LINE: 1652
| | | mutex: 'Master_info::data_lock' lock FILE: slave.cc LINE: 1654
| | | mutex: 'Relay_log_info::data_lock' lock FILE: slave.cc LINE: 1655
| | | mutex: 'Relay_log_info::data_lock' unlock FILE: slave.cc LINE: 1759
| | | mutex: 'Master_info::data_lock' unlock FILE: slave.cc LINE: 1760
| | mutex: 'LOCK_active_mi' unlock FILE: sql_parse.cc LINE: 2608

2) SLAVE SQL THREAD while applying events passed following mutexes:
<apply_event_and_update_pos
mutex: 'Relay_log_info::data_lock' lock FILE: slave.cc LINE: 2268
>apply_event_and_update_pos
| mutex: 'Relay_log_info::data_lock' unlock FILE: slave.cc LINE: 2162
| | mutex: 'Relay_log_info::data_lock' lock FILE: log_event.cc LINE: 5101
| | mutex: 'Relay_log_info::data_lock' unlock FILE: log_event.cc LINE: 5113

3) STOP SLAVE command passing following mutexes:
query: STOP SLAVE
| | mutex: 'LOCK_active_mi' lock FILE: sql_parse.cc LINE: 3007
| | | | mutex: 'Master_info::run_lock' lock FILE: slave.cc LINE: 198
| | | | mutex: 'Relay_log_info::run_lock' lock FILE: slave.cc LINE: 199
| | | | | mutex: 'Relay_log_info::run_lock' cond_timedwait: start FILE: slave.cc LINE: 535

# !!! HERE WE WAIT UNTIL COMPLETE QUERY FROM SQL_SLAVE_THREAD !!! #

| | | | | mutex: 'Relay_log_info::run_lock' cond_timedwait: complete FILE: slave.cc LINE: 535
| | | | | mutex: 'Master_info::run_lock' cond_timedwait: start FILE: slave.cc LINE: 535
| | | | | mutex: 'Master_info::run_lock' cond_timedwait: complete FILE: slave.cc LINE: 535
| | | | mutex: 'Relay_log_info::run_lock' unlock FILE: slave.cc LINE: 213
| | | | mutex: 'Master_info::run_lock' unlock FILE: slave.cc LINE: 214
| | mutex: 'LOCK_active_mi' unlock FILE: sql_parse.cc LINE: 3009

As we can see, STOP SLAVE lock following mutexes:
1) 'LOCK_active_mi' FILE: sql_parse.cc LINE: 3007
2) 'Master_info::run_lock' FILE: slave.cc LINE: 198
mutex 'Relay_log_info::run_lock' free by cond_timed_wait

As result, SHOW SLAVE STATUS NOLOCK should not lock this two mutexes (wrapped by check in the my fix).

I hope, this information enough for your understanding of circumstances.
If you need any additional information - I can provide it for you (just highligh what you want know).

Revision history for this message
Alexey Kopytov (akopytov) wrote :

Approved if passes Jenkins. Please also port to 5.5.

review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'patches/show_slave_status_nolock.patch'
2--- patches/show_slave_status_nolock.patch 2011-09-06 08:23:51 +0000
3+++ patches/show_slave_status_nolock.patch 2011-09-16 10:56:26 +0000
4@@ -56,7 +56,7 @@
5 sql_command_flags[SQLCOM_SHOW_CREATE_PROC]= CF_STATUS_COMMAND;
6 sql_command_flags[SQLCOM_SHOW_CREATE_FUNC]= CF_STATUS_COMMAND;
7 sql_command_flags[SQLCOM_SHOW_CREATE_TRIGGER]= CF_STATUS_COMMAND;
8-@@ -2589,12 +2590,16 @@
9+@@ -2591,12 +2592,17 @@
10 pthread_mutex_unlock(&LOCK_active_mi);
11 break;
12 }
13@@ -67,22 +67,32 @@
14 if (check_global_access(thd, SUPER_ACL | REPL_CLIENT_ACL))
15 goto error;
16 - pthread_mutex_lock(&LOCK_active_mi);
17-+ if(SQLCOM_SHOW_SLAVE_NOLOCK_STAT != lex->sql_command)
18++ bool do_lock=SQLCOM_SHOW_SLAVE_NOLOCK_STAT != lex->sql_command;
19++ if(do_lock)
20 + {
21 + pthread_mutex_lock(&LOCK_active_mi);
22 + }
23 if (active_mi != NULL)
24 {
25 res = show_master_info(thd, active_mi);
26-@@ -2605,7 +2610,10 @@
27+@@ -2607,7 +2613,19 @@
28 WARN_NO_MASTER_INFO, ER(WARN_NO_MASTER_INFO));
29 my_ok(thd);
30 }
31 - pthread_mutex_unlock(&LOCK_active_mi);
32-+ if(SQLCOM_SHOW_SLAVE_NOLOCK_STAT != lex->sql_command)
33++ if(do_lock)
34 + {
35 + pthread_mutex_unlock(&LOCK_active_mi);
36 + }
37++ DBUG_EXECUTE_IF("after_show_slave_status",
38++ {
39++ const char act[]=
40++ "now "
41++ "signal signal.after_show_slave_status";
42++ DBUG_ASSERT(opt_debug_sync_timeout > 0);
43++ DBUG_ASSERT(!debug_sync_set_action(current_thd,
44++ STRING_WITH_LEN(act)));
45++ };);
46 break;
47 }
48 case SQLCOM_SHOW_MASTER_STAT:
49@@ -109,79 +119,251 @@
50 {
51 LEX *lex= Lex;
52 --- /dev/null
53++++ b/mysql-test/t/percona_show_slave_status_nolock.test
54+@@ -0,0 +1,88 @@
55++--source include/master-slave.inc
56++--source include/have_debug_sync.inc
57++--source include/have_binlog_format_statement.inc
58++
59++--let $rpl_connection_name=slave_lock
60++--let $rpl_server_number=2
61++--source include/rpl_connect.inc
62++
63++--let $rpl_connection_name=slave_nolock
64++--let $rpl_server_number=2
65++--source include/rpl_connect.inc
66++
67++--let $show_statement= SHOW PROCESSLIST
68++--let $field= Info
69++
70++connection master;
71++--echo [master]
72++--disable_warnings
73++DROP TABLE IF EXISTS t;
74++--enable_warnings
75++CREATE TABLE t(id INT);
76++sync_slave_with_master;
77++
78++connection slave;
79++--echo [slave]
80++SET DEBUG_SYNC='RESET';
81++SET GLOBAL DEBUG="+d,after_mysql_insert";
82++SET GLOBAL DEBUG="+d,after_show_slave_status";
83++
84++connection master;
85++--echo [master]
86++INSERT INTO t VALUES(0);
87++
88++connection slave;
89++--echo [slave]
90++--let $condition= 'INSERT INTO t VALUES(0)'
91++--source include/wait_show_condition.inc
92++
93++--echo check 'SHOW SLAVE STATUS' and 'SHOW SLAVE STATUS NOLOCK' - both should work fine
94++--source include/percona_show_slave_status_nolock.inc
95++
96++connection master;
97++--echo [master]
98++INSERT INTO t VALUES(1);
99++
100++connection slave;
101++--echo [slave]
102++--let $condition= 'INSERT INTO t VALUES(1)'
103++--source include/wait_show_condition.inc
104++
105++--let $rpl_connection_name=slave_stop
106++--let $rpl_server_number=2
107++--source include/rpl_connect.inc
108++
109++connection slave_stop;
110++--echo [slave_stop]
111++send STOP SLAVE;
112++
113++connection slave;
114++--echo [slave]
115++--let $condition= 'STOP SLAVE'
116++--source include/wait_show_condition.inc
117++
118++--echo check 'SHOW SLAVE STATUS' and 'SHOW SLAVE STATUS NOLOCK' - just NOLOCK version should works fine
119++--source include/percona_show_slave_status_nolock.inc
120++
121++
122++connection slave_stop;
123++--echo [slave_stop]
124++reap;
125++--source include/wait_for_slave_to_stop.inc
126++START SLAVE;
127++--source include/wait_for_slave_to_start.inc
128++
129++connection master;
130++--echo [master]
131++SET DEBUG_SYNC='RESET';
132++
133++connection slave;
134++--echo [slave]
135++SET GLOBAL DEBUG='';
136++SET DEBUG_SYNC='RESET';
137++
138++connection master;
139++DROP TABLE t;
140++sync_slave_with_master;
141++
142++--source include/rpl_end.inc
143+--- /dev/null
144 +++ b/mysql-test/r/percona_show_slave_status_nolock.result
145-@@ -0,0 +1,21 @@
146+@@ -0,0 +1,68 @@
147 +include/master-slave.inc
148 +[connection master]
149++include/rpl_connect.inc [creating slave_lock]
150++include/rpl_connect.inc [creating slave_nolock]
151++[master]
152 +DROP TABLE IF EXISTS t;
153 +CREATE TABLE t(id INT);
154-+INSERT INTO t SELECT SLEEP(10);
155++[slave]
156++SET DEBUG_SYNC='RESET';
157++SET GLOBAL DEBUG="+d,after_mysql_insert";
158++SET GLOBAL DEBUG="+d,after_show_slave_status";
159++[master]
160++INSERT INTO t VALUES(0);
161++[slave]
162++check 'SHOW SLAVE STATUS' and 'SHOW SLAVE STATUS NOLOCK' - both should work fine
163++
164++[slave_lock]
165++SHOW SLAVE STATUS;
166++SET DEBUG_SYNC='now WAIT_FOR signal.after_show_slave_status TIMEOUT 1';
167++SIGNAL after SHOW SLAVE STATUS is 'signal.after_show_slave_status'
168++[slave]
169++SET DEBUG_SYNC='now SIGNAL signal.empty';
170++[slave_nolock]
171++SHOW SLAVE STATUS NOLOCK;
172++SET DEBUG_SYNC='now WAIT_FOR signal.after_show_slave_status TIMEOUT 1';
173++# should be 'signal.after_show_slave_status'
174++SIGNAL after SHOW SLAVE STATUS NOLOCK is 'signal.after_show_slave_status'
175++[slave]
176++SET DEBUG_SYNC='now SIGNAL signal.continue';
177++[slave]
178++SET DEBUG_SYNC='now SIGNAL signal.empty';
179++
180++[master]
181++INSERT INTO t VALUES(1);
182++[slave]
183++include/rpl_connect.inc [creating slave_stop]
184++[slave_stop]
185 +STOP SLAVE;
186-+Warnings:
187-+Note 1592 Statement may not be safe to log in statement format.
188-+master count(*)
189-+master 1
190-+slave count(*)
191-+slave 0
192++[slave]
193++check 'SHOW SLAVE STATUS' and 'SHOW SLAVE STATUS NOLOCK' - just NOLOCK version should works fine
194++
195++[slave_lock]
196++SHOW SLAVE STATUS;
197++SET DEBUG_SYNC='now WAIT_FOR signal.after_show_slave_status TIMEOUT 1';
198++SIGNAL after SHOW SLAVE STATUS is 'signal.empty'
199++[slave]
200++SET DEBUG_SYNC='now SIGNAL signal.empty';
201++[slave_nolock]
202 +SHOW SLAVE STATUS NOLOCK;
203++SET DEBUG_SYNC='now WAIT_FOR signal.after_show_slave_status TIMEOUT 1';
204++# should be 'signal.after_show_slave_status'
205++SIGNAL after SHOW SLAVE STATUS NOLOCK is 'signal.after_show_slave_status'
206++[slave]
207++SET DEBUG_SYNC='now SIGNAL signal.continue';
208++[slave]
209++SET DEBUG_SYNC='now SIGNAL signal.empty';
210++
211++[slave_stop]
212 +include/wait_for_slave_to_stop.inc
213 +START SLAVE;
214 +include/wait_for_slave_to_start.inc
215-+slave count(*)
216-+slave 1
217++[master]
218++SET DEBUG_SYNC='RESET';
219++[slave]
220++SET GLOBAL DEBUG='';
221++SET DEBUG_SYNC='RESET';
222 +DROP TABLE t;
223-+STOP SLAVE;
224-+include/wait_for_slave_to_stop.inc
225++include/rpl_end.inc
226 --- /dev/null
227-+++ b/mysql-test/t/percona_show_slave_status_nolock.test
228-@@ -0,0 +1,50 @@
229-+--source include/master-slave.inc
230-+--source include/have_binlog_format_statement.inc
231-+
232-+connection master;
233-+ --disable_warnings
234-+ DROP TABLE IF EXISTS t;
235-+ --enable_warnings
236-+ CREATE TABLE t(id INT);
237-+ sync_slave_with_master;
238-+
239-+connection master;
240-+ send INSERT INTO t SELECT SLEEP(10);
241-+
242-+connection slave;
243-+ sleep 15;
244-+ send STOP SLAVE;
245-+
246-+connection master;
247-+ reap;
248-+
249-+ --disable_query_log
250-+ select "master",count(*) from t;
251-+ --enable_query_log
252-+
253-+connection slave1;
254-+ --disable_query_log
255-+ select "slave",count(*) from t;
256-+ --enable_query_log
257-+
258-+ --disable_result_log
259-+ SHOW SLAVE STATUS NOLOCK;
260-+ --enable_result_log
261-+
262-+connection slave;
263-+ reap;
264-+
265-+ --source include/wait_for_slave_to_stop.inc
266-+ START SLAVE;
267-+ --source include/wait_for_slave_to_start.inc
268-+
269-+ --disable_query_log
270-+ select "slave",count(*) from t;
271-+ --enable_query_log
272-+
273-+connection master;
274-+ DROP TABLE t;
275-+sync_slave_with_master;
276-+
277-+STOP SLAVE;
278-+--source include/wait_for_slave_to_stop.inc
279++++ b/mysql-test/include/percona_show_slave_status_nolock.inc
280+@@ -0,0 +1,56 @@
281++--echo
282++--disable_result_log
283++connection slave_lock;
284++--echo [slave_lock]
285++send SHOW SLAVE STATUS;
286++
287++connection slave;
288++--let $condition= 'SHOW SLAVE STATUS'
289++--source include/wait_show_condition.inc
290++
291++--disable_warnings
292++SET DEBUG_SYNC='now WAIT_FOR signal.after_show_slave_status TIMEOUT 1';
293++--enable_warnings
294++
295++--let current=`SELECT SUBSTR(Variable_value FROM 22) FROM INFORMATION_SCHEMA.SESSION_VARIABLES WHERE Variable_name = 'DEBUG_SYNC'`
296++--echo SIGNAL after SHOW SLAVE STATUS is $current
297++
298++connection slave;
299++--echo [slave]
300++SET DEBUG_SYNC='now SIGNAL signal.empty';
301++
302++connection slave_nolock;
303++--echo [slave_nolock]
304++send SHOW SLAVE STATUS NOLOCK;
305++
306++connection slave;
307++--let $condition= 'SHOW SLAVE STATUS NOLOCK'
308++--source include/wait_show_condition.inc
309++
310++--disable_warnings
311++SET DEBUG_SYNC='now WAIT_FOR signal.after_show_slave_status TIMEOUT 1';
312++--enable_warnings
313++
314++--echo # should be 'signal.after_show_slave_status'
315++--let current=`SELECT SUBSTR(Variable_value FROM 22) FROM INFORMATION_SCHEMA.SESSION_VARIABLES WHERE Variable_name = 'DEBUG_SYNC'`
316++--echo SIGNAL after SHOW SLAVE STATUS NOLOCK is $current
317++
318++connection slave;
319++--echo [slave]
320++SET DEBUG_SYNC='now SIGNAL signal.continue';
321++
322++connection slave_lock;
323++--disable_result_log
324++reap;
325++--enable_result_log
326++
327++connection slave_nolock;
328++--disable_result_log
329++reap;
330++--enable_result_log
331++
332++connection slave;
333++--echo [slave]
334++SET DEBUG_SYNC='now SIGNAL signal.empty';
335++--enable_result_log
336++--echo
337+--- a/sql/slave.cc
338++++ b/sql/slave.cc
339+@@ -1639,6 +1639,7 @@
340+
341+ if (mi->host[0])
342+ {
343++ bool do_lock=SQLCOM_SHOW_SLAVE_NOLOCK_STAT != thd->lex->sql_command;
344+ DBUG_PRINT("info",("host is set: '%s'", mi->host));
345+ String *packet= &thd->packet;
346+ protocol->prepare_for_resend();
347+@@ -1647,9 +1648,15 @@
348+ slave_running can be accessed without run_lock but not other
349+ non-volotile members like mi->io_thd, which is guarded by the mutex.
350+ */
351+- pthread_mutex_lock(&mi->run_lock);
352++ if (do_lock)
353++ {
354++ pthread_mutex_lock(&mi->run_lock);
355++ }
356+ protocol->store(mi->io_thd ? mi->io_thd->proc_info : "", &my_charset_bin);
357+- pthread_mutex_unlock(&mi->run_lock);
358++ if (do_lock)
359++ {
360++ pthread_mutex_unlock(&mi->run_lock);
361++ }
362+
363+ pthread_mutex_lock(&mi->data_lock);
364+ pthread_mutex_lock(&mi->rli.data_lock);

Subscribers

People subscribed via source and target branches