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

Merge lp:~percona-dev/percona-server/release-5.1.53-bug693818-fix-bug695373 into lp:~percona-dev/percona-server/release-5.1.53

  1. release-5.1.53-bug693818-fix-bug695373
  2. Merge into release-5.1.53
Proposed by Oleg Tsarev
Status: Merged
Approved by: Alexey Kopytov
Approved revision: no longer in the source branch.
Merged at revision: 178
Proposed branch: lp:~percona-dev/percona-server/release-5.1.53-bug693818-fix-bug695373
Merge into: lp:~percona-dev/percona-server/release-5.1.53
Prerequisite: lp:~percona-dev/percona-server/release-5.1.53-bug693818
Diff against target: 270 lines (+33/-4)
20 files modified
mysql-test/slow_extended.patch/percona_slow_extended-control_global_slow.result (+1/-0)
mysql-test/slow_extended.patch/percona_slow_extended-control_global_slow.test (+1/-1)
mysql-test/slow_extended.patch/percona_slow_extended-log_slow_filter.result (+1/-0)
mysql-test/slow_extended.patch/percona_slow_extended-log_slow_filter.test (+1/-1)
mysql-test/slow_extended.patch/percona_slow_extended-log_slow_verbosity.result (+1/-0)
mysql-test/slow_extended.patch/percona_slow_extended-log_slow_verbosity.test (+1/-1)
mysql-test/slow_extended.patch/percona_slow_extended-long_query_time.result (+1/-0)
mysql-test/slow_extended.patch/percona_slow_extended-long_query_time.test (+1/-0)
mysql-test/slow_extended.patch/percona_slow_extended-microseconds_in_slow_extended.result (+1/-0)
mysql-test/slow_extended.patch/percona_slow_extended-microseconds_in_slow_extended.test (+1/-0)
mysql-test/slow_extended.patch/percona_slow_extended-min_examined_row_limit.result (+1/-0)
mysql-test/slow_extended.patch/percona_slow_extended-min_examined_row_limit.test (+1/-1)
mysql-test/slow_extended.patch/percona_slow_extended-slave_innodb_stats.result (+1/-0)
mysql-test/slow_extended.patch/percona_slow_extended-slave_innodb_stats.test (+2/-0)
mysql-test/slow_extended.patch/percona_slow_extended-slave_statements-and-use_global_long_query_time.result (+2/-0)
mysql-test/slow_extended.patch/percona_slow_extended-slave_statements-and-use_global_long_query_time.test (+6/-0)
mysql-test/slow_extended.patch/percona_slow_extended-slave_statements.result (+2/-0)
mysql-test/slow_extended.patch/percona_slow_extended-slave_statements.test (+6/-0)
mysql-test/slow_extended.patch/percona_slow_extended-use_global_long_query_time.result (+1/-0)
mysql-test/slow_extended.patch/percona_slow_extended-use_global_long_query_time.test (+1/-0)
To merge this branch: bzr merge lp:~percona-dev/percona-server/release-5.1.53-bug693818-fix-bug695373
Reviewer Review Type Date Requested Status
Alexey Kopytov (community) Approve
Review via email: mp+44857@code.launchpad.net

This proposal supersedes a proposal from 2010-12-29.

Description of the change

Sometime test percona_slow_extended-log_slow_verbosity are failed.
This test run long query(SELECT sleep(2)), and than analyze slow query log (search string "No InnoDB statistics available for this query").
You can see bug #695373 - first run of test doesn't string "No InnoDB... " instead of one, but retry run found two string instead of one.
I think reason of that - script searchs string in slow query log BEFORE this string was wrote to log by mysql.

I add FLUSH LOGS, and now test work fine.

Similar changes for tests:
  percona_slow_extended-control_global_slow
  percona_slow_extended-log_slow_filter
  percona_slow_extended-log_slow_verbosity
  percona_slow_extended-long_query_time
  percona_slow_extended-microseconds_in_slow_extended
  percona_slow_extended-min_examined_row_limit
  percona_slow_extended-slave_innodb_stats
  percona_slow_extended-slave_statements-and-use_global_long_query_time
  percona_slow_extended-slave_statements
  percona_slow_extended-use_global_long_query_time

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

Just FLUSH LOGS should be enough. There is no need to restart the server.

By the way, it is clear that the problem applies to all slow_extended tests, not just log_slow_verbosity. The reason is that logging to slow query log is performed after the OK packet has been to the client. Since the client then runs a shell or Perl process asynchronously with respect to the current thread (and therefore, to the current MySQL connection), there is an obvious race condition in those tests.

review: Needs Fixing
Revision history for this message
Alexey Kopytov (akopytov) :
review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-control_global_slow.result'
2--- mysql-test/slow_extended.patch/percona_slow_extended-control_global_slow.result 2010-12-06 03:50:48 +0000
3+++ mysql-test/slow_extended.patch/percona_slow_extended-control_global_slow.result 2010-12-29 18:12:32 +0000
4@@ -8,4 +8,5 @@
5 0
6 set global use_global_log_slow_control=none;
7 set global log_slow_verbosity=microtime;
8+FLUSH LOGS;
9 1
10
11=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-control_global_slow.test'
12--- mysql-test/slow_extended.patch/percona_slow_extended-control_global_slow.test 2010-12-29 18:12:32 +0000
13+++ mysql-test/slow_extended.patch/percona_slow_extended-control_global_slow.test 2010-12-29 18:12:32 +0000
14@@ -6,7 +6,7 @@
15 set global use_global_log_slow_control=none;
16 set global log_slow_verbosity=microtime;
17
18+FLUSH LOGS;
19 --let grep_file = $MYSQLTEST_VARDIR/mysqld.1/data/percona_slow_query_log-control_global_slow.log
20 --let grep_pattern = No InnoDB statistics available for this query
21-
22 --source include/grep.inc
23
24=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-log_slow_filter.result'
25--- mysql-test/slow_extended.patch/percona_slow_extended-log_slow_filter.result 2010-12-06 03:50:48 +0000
26+++ mysql-test/slow_extended.patch/percona_slow_extended-log_slow_filter.result 2010-12-29 18:12:32 +0000
27@@ -21,4 +21,5 @@
28 sleep(2)
29 0
30 drop table if exists t;
31+FLUSH LOGS;
32 2
33
34=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-log_slow_filter.test'
35--- mysql-test/slow_extended.patch/percona_slow_extended-log_slow_filter.test 2010-12-29 18:12:32 +0000
36+++ mysql-test/slow_extended.patch/percona_slow_extended-log_slow_filter.test 2010-12-29 18:12:32 +0000
37@@ -26,7 +26,7 @@
38 drop table if exists t;
39 --enable_warnings
40
41+FLUSH LOGS;
42 --let grep_file = $MYSQLTEST_VARDIR/mysqld.1/data/percona_slow_query_log-log_slow_filter.log
43 --let grep_pattern = Query_time
44-
45 --source include/grep.inc
46
47=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-log_slow_verbosity.result'
48--- mysql-test/slow_extended.patch/percona_slow_extended-log_slow_verbosity.result 2010-12-06 03:50:48 +0000
49+++ mysql-test/slow_extended.patch/percona_slow_extended-log_slow_verbosity.result 2010-12-29 18:12:32 +0000
50@@ -5,4 +5,5 @@
51 SELECT sleep(2);
52 sleep(2)
53 0
54+FLUSH LOGS;
55 1
56
57=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-log_slow_verbosity.test'
58--- mysql-test/slow_extended.patch/percona_slow_extended-log_slow_verbosity.test 2010-12-29 18:12:32 +0000
59+++ mysql-test/slow_extended.patch/percona_slow_extended-log_slow_verbosity.test 2010-12-29 18:12:32 +0000
60@@ -6,7 +6,7 @@
61
62 SELECT sleep(2);
63
64+FLUSH LOGS;
65 --let grep_file = $MYSQLTEST_VARDIR/mysqld.1/data/percona_slow_query_log-log_slow_verbosity.log
66 --let grep_pattern = No InnoDB statistics available for this query
67-
68 --source include/grep.inc
69
70=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-long_query_time.result'
71--- mysql-test/slow_extended.patch/percona_slow_extended-long_query_time.result 2010-12-06 03:50:48 +0000
72+++ mysql-test/slow_extended.patch/percona_slow_extended-long_query_time.result 2010-12-29 18:12:32 +0000
73@@ -18,4 +18,5 @@
74 sleep(5)
75 0
76 set long_query_time=2;
77+FLUSH LOGS;
78 3
79
80=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-long_query_time.test'
81--- mysql-test/slow_extended.patch/percona_slow_extended-long_query_time.test 2010-12-29 18:12:32 +0000
82+++ mysql-test/slow_extended.patch/percona_slow_extended-long_query_time.test 2010-12-29 18:12:32 +0000
83@@ -12,6 +12,7 @@
84
85 set long_query_time=2;
86
87+FLUSH LOGS;
88 --let grep_file = $MYSQLTEST_VARDIR/mysqld.1/data/percona_slow_query_log-long_query_time.log
89 --let grep_pattern = Query_time
90 --source include/grep.inc
91
92=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-microseconds_in_slow_extended.result'
93--- mysql-test/slow_extended.patch/percona_slow_extended-microseconds_in_slow_extended.result 2010-12-06 03:50:48 +0000
94+++ mysql-test/slow_extended.patch/percona_slow_extended-microseconds_in_slow_extended.result 2010-12-29 18:12:32 +0000
95@@ -6,5 +6,6 @@
96 sleep(2)
97 0
98 set global slow_query_log_microseconds_timestamp=OFF;
99+FLUSH LOGS;
100 1
101 2
102
103=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-microseconds_in_slow_extended.test'
104--- mysql-test/slow_extended.patch/percona_slow_extended-microseconds_in_slow_extended.test 2010-12-29 18:12:32 +0000
105+++ mysql-test/slow_extended.patch/percona_slow_extended-microseconds_in_slow_extended.test 2010-12-29 18:12:32 +0000
106@@ -8,6 +8,7 @@
107
108 set global slow_query_log_microseconds_timestamp=OFF;
109
110+FLUSH LOGS;
111 --let grep_file = $MYSQLTEST_VARDIR/mysqld.1/data/percona_slow_query_log-microseconds_in_slow_query_log.log
112 --let grep_pattern = # Time: [0-9]+[ ]+[0-9]+:[0-9]+:[0-9]+.[0-9]+
113 --source include/grep.inc
114
115=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-min_examined_row_limit.result'
116--- mysql-test/slow_extended.patch/percona_slow_extended-min_examined_row_limit.result 2010-12-06 03:50:48 +0000
117+++ mysql-test/slow_extended.patch/percona_slow_extended-min_examined_row_limit.result 2010-12-29 18:12:32 +0000
118@@ -21,4 +21,5 @@
119 sleep(2)
120 0
121 drop table if exists t;
122+FLUSH LOGS;
123 2
124
125=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-min_examined_row_limit.test'
126--- mysql-test/slow_extended.patch/percona_slow_extended-min_examined_row_limit.test 2010-12-29 18:12:32 +0000
127+++ mysql-test/slow_extended.patch/percona_slow_extended-min_examined_row_limit.test 2010-12-29 18:12:32 +0000
128@@ -26,7 +26,7 @@
129 drop table if exists t;
130 --enable_warnings
131
132+FLUSH LOGS;
133 --let grep_file = $MYSQLTEST_VARDIR/mysqld.1/data/percona_slow_query_log-min_examined_row_limit.log
134 --let grep_pattern = Query_time
135 --source include/grep.inc
136-
137
138=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-slave_innodb_stats.result'
139--- mysql-test/slow_extended.patch/percona_slow_extended-slave_innodb_stats.result 2010-11-18 12:38:25 +0000
140+++ mysql-test/slow_extended.patch/percona_slow_extended-slave_innodb_stats.result 2010-12-29 18:12:32 +0000
141@@ -18,4 +18,5 @@
142 START SLAVE;
143 INSERT INTO t SELECT t.id,t.data from t;
144 DROP TABLE IF EXISTS t;
145+FLUSH LOGS;
146 4
147
148=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-slave_innodb_stats.test'
149--- mysql-test/slow_extended.patch/percona_slow_extended-slave_innodb_stats.test 2010-12-29 18:12:32 +0000
150+++ mysql-test/slow_extended.patch/percona_slow_extended-slave_innodb_stats.test 2010-12-29 18:12:32 +0000
151@@ -41,6 +41,8 @@
152 DROP TABLE IF EXISTS t;
153 sync_slave_with_master;
154
155+connection slave;
156+FLUSH LOGS;
157 --let grep_file = $MYSQLTEST_VARDIR/mysqld.2/mysqld-slow.log
158 --let grep_pattern = InnoDB_IO_r_ops
159 --source include/grep.inc
160
161=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-slave_statements-and-use_global_long_query_time.result'
162--- mysql-test/slow_extended.patch/percona_slow_extended-slave_statements-and-use_global_long_query_time.result 2010-11-18 11:36:02 +0000
163+++ mysql-test/slow_extended.patch/percona_slow_extended-slave_statements-and-use_global_long_query_time.result 2010-12-29 18:12:32 +0000
164@@ -75,12 +75,14 @@
165 use_global_long_query_time ON
166 set global long_query_time=1;
167 set global use_global_long_query_time=0;
168+FLUSH LOGS;
169 # Analyse master slow_query_log
170 0
171 0
172 0
173 0
174 0
175+FLUSH LOGS;
176 # Analyse slave slow_query_log
177 0
178 0
179
180=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-slave_statements-and-use_global_long_query_time.test'
181--- mysql-test/slow_extended.patch/percona_slow_extended-slave_statements-and-use_global_long_query_time.test 2010-12-29 18:12:32 +0000
182+++ mysql-test/slow_extended.patch/percona_slow_extended-slave_statements-and-use_global_long_query_time.test 2010-12-29 18:12:32 +0000
183@@ -75,6 +75,9 @@
184 set global long_query_time=1;
185 set global use_global_long_query_time=0;
186
187+connection master;
188+FLUSH LOGS;
189+
190 -- echo # Analyse master slow_query_log
191 let $i=5;
192 let $k=1;
193@@ -87,6 +90,9 @@
194 inc $k;
195 }
196
197+connection slave;
198+FLUSH LOGS;
199+
200 -- echo # Analyse slave slow_query_log
201 let $i=5;
202 let $k=1;
203
204=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-slave_statements.result'
205--- mysql-test/slow_extended.patch/percona_slow_extended-slave_statements.result 2010-11-05 11:47:33 +0000
206+++ mysql-test/slow_extended.patch/percona_slow_extended-slave_statements.result 2010-12-29 18:12:32 +0000
207@@ -64,6 +64,7 @@
208 INSERT INTO t VALUES (7);
209 # Read information about master binlog
210 # Sync slave(7) thread
211+FLUSH LOGS;
212 # Analyse master slow_query_log
213 1
214 1
215@@ -72,6 +73,7 @@
216 1
217 1
218 1
219+FLUSH LOGS;
220 # Analyse slave slow_query_log
221 0
222 0
223
224=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-slave_statements.test'
225--- mysql-test/slow_extended.patch/percona_slow_extended-slave_statements.test 2010-12-29 18:12:32 +0000
226+++ mysql-test/slow_extended.patch/percona_slow_extended-slave_statements.test 2010-12-29 18:12:32 +0000
227@@ -122,6 +122,9 @@
228 connection slave;
229 let $sync_result = `SELECT MASTER_POS_WAIT('$binlog_file',$binlog_position)`;
230
231+connection master;
232+FLUSH LOGS;
233+
234 -- echo # Analyse master slow_query_log
235 let $i=7;
236 let $k=1;
237@@ -134,6 +137,9 @@
238 inc $k;
239 }
240
241+connection slave;
242+FLUSH LOGS;
243+
244 -- echo # Analyse slave slow_query_log
245 let $i=7;
246 let $k=1;
247
248=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-use_global_long_query_time.result'
249--- mysql-test/slow_extended.patch/percona_slow_extended-use_global_long_query_time.result 2010-12-06 03:50:48 +0000
250+++ mysql-test/slow_extended.patch/percona_slow_extended-use_global_long_query_time.result 2010-12-29 18:12:32 +0000
251@@ -20,6 +20,7 @@
252 0
253 set global long_query_time=2;
254 set global use_global_long_query_time=0;
255+FLUSH LOGS;
256 3
257 show global variables like 'use_global_log_slow_control';
258 Variable_name Value
259
260=== modified file 'mysql-test/slow_extended.patch/percona_slow_extended-use_global_long_query_time.test'
261--- mysql-test/slow_extended.patch/percona_slow_extended-use_global_long_query_time.test 2010-12-29 18:12:32 +0000
262+++ mysql-test/slow_extended.patch/percona_slow_extended-use_global_long_query_time.test 2010-12-29 18:12:32 +0000
263@@ -14,6 +14,7 @@
264 set global long_query_time=2;
265 set global use_global_long_query_time=0;
266
267+FLUSH LOGS;
268 --let grep_file = $MYSQLTEST_VARDIR/mysqld.1/data/percona_slow_query_log-use_global_long_query_time.log
269 --let grep_pattern = Query_time
270 --source include/grep.inc

Subscribers

People subscribed via source and target branches

to all changes: