← Back to branch summary

~ubuntu-branches/ubuntu/precise/mysql-5.1/precise

« back to all changes in this revision

Viewing changes to mysql-test/suite/rpl/t/rpl_slow_query_log.test

  • Committer: Bazaar Package Importer
  • Author(s): Norbert Tretkowski
  • Date: 2010-03-17 14:56:02 UTC
  • Revision ID: james.westby@ubuntu.com-20100317145602-x7e30l1b2sb5s6w6
Tags: upstream-5.1.45
Import upstream version 5.1.45

Show diffs side-by-side

added added

removed removed

Lines of Context:
mysql-test/suite/rpl/t/rpl_slow_query_log.test
 
1
#
 
2
# BUG#23300: Slow query log on slave does not log slow replicated statements
 
3
#
 
4
# Description:
 
5
#   The slave should log slow queries replicated from master when
 
6
#   --log-slow-slave-statements is used.
 
7
#
 
8
#   Test is implemented as follows:
 
9
#      i) stop slave
 
10
#     ii) On slave, set long_query_time to a small value.
 
11
#     ii) start slave so that long_query_time variable is picked by sql thread
 
12
#    iii) On master, do one short time query and one long time query, on slave
 
13
#         and check that slow query is logged to slow query log but fast query 
 
14
#         is not.
 
15
#     iv) On slave, check that slow queries go into the slow log and fast dont,
 
16
#         when issued through a regular client connection
 
17
#      v) On slave, check that slow queries go into the slow log and fast dont
 
18
#         when we use SET TIMESTAMP= 1 on a regular client connection.
 
19
#     vi) check that when setting slow_query_log= OFF in a connection 'extra2'
 
20
#         prevents logging slow queries in a connection 'extra'
 
21
#
 
22
# OBS: 
 
23
#   This test only runs for statement binlogging format because on row format
 
24
#   slow queries do not get slow query logged. 
 
25
#   Note that due to the sleep() command the insert is written to the binary
 
26
#   log in row format.
 
27
 
 
28
source include/master-slave.inc;
 
29
source include/have_binlog_format_statement.inc;
 
30
 
 
31
CALL mtr.add_suppression("Unsafe statement binlogged in statement format since BINLOG_FORMAT = STATEMENT");
 
32
 
 
33
 
 
34
# Prepare slave for different long_query_time we need to stop the slave 
 
35
# and restart it as long_query_time variable is dynamic and, after 
 
36
# setting it, it only takes effect on new connections. 
 
37
#
 
38
# Reference: 
 
39
#   http://dev.mysql.com/doc/refman/6.0/en/set-option.html
 
40
connection slave;
 
41
 
 
42
source include/stop_slave.inc;
 
43
 
 
44
SET @old_log_output= @@log_output;
 
45
SET GLOBAL log_output= 'TABLE';
 
46
SET @old_long_query_time= @@long_query_time;
 
47
SET GLOBAL long_query_time= 2;
 
48
TRUNCATE mysql.slow_log;
 
49
 
 
50
source include/start_slave.inc;
 
51
 
 
52
connection master;
 
53
CREATE TABLE t1 (a int, b int); 
 
54
 
 
55
# test:
 
56
#   check that slave logs the slow query to the slow log, but not the fast one.
 
57
 
 
58
let $slow_query= INSERT INTO t1 values(1, sleep(3));
 
59
let $fast_query= INSERT INTO t1 values(1, 1);
 
60
 
 
61
eval $fast_query;
 
62
--disable_warnings
 
63
eval $slow_query;
 
64
--enable_warnings
 
65
sync_slave_with_master;
 
66
 
 
67
let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`;
 
68
let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
 
69
 
 
70
if ($found_fast_query)
 
71
{
 
72
  SELECT * FROM mysql.slow_log;
 
73
  die "Assertion failed! Fast query FOUND in slow query log. Bailing out!";
 
74
}
 
75
 
 
76
if (!$found_slow_query)
 
77
{
 
78
  SELECT * FROM mysql.slow_log;
 
79
  die "Assertion failed! Slow query NOT FOUND in slow query log. Bailing out!";
 
80
}
 
81
TRUNCATE mysql.slow_log;
 
82
 
 
83
# regular checks for slow query log (using a new connection - 'extra' - to slave)
 
84
 
 
85
# test: 
 
86
#   when using direct connections to the slave, check that slow query is logged 
 
87
#   but not the fast one.
 
88
 
 
89
connect(extra,127.0.0.1,root,,test,$SLAVE_MYPORT);
 
90
connection extra;
 
91
 
 
92
let $fast_query= SELECT 1;
 
93
let $slow_query= SELECT 1, sleep(3);
 
94
 
 
95
eval $slow_query;
 
96
eval $fast_query;
 
97
 
 
98
let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`;
 
99
let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
 
100
 
 
101
if ($found_fast_query)
 
102
{
 
103
  SELECT * FROM mysql.slow_log;
 
104
  die "Assertion failed! Fast query FOUND in slow query log. Bailing out!";
 
105
}
 
106
 
 
107
if (!$found_slow_query)
 
108
{
 
109
  SELECT * FROM mysql.slow_log;
 
110
  die "Assertion failed! Slow query NOT FOUND in slow query log. Bailing out!";
 
111
}
 
112
TRUNCATE mysql.slow_log;
 
113
 
 
114
# test:
 
115
#   when using direct connections to the slave, check that when setting timestamp to 1 the 
 
116
#   slow query is logged but the fast one is not.
 
117
 
 
118
let $fast_query= SELECT 2;
 
119
let $slow_query= SELECT 2, sleep(3);
 
120
 
 
121
SET TIMESTAMP= 1;
 
122
eval $slow_query;
 
123
eval $fast_query;
 
124
 
 
125
let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`;
 
126
let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
 
127
 
 
128
if ($found_fast_query)
 
129
{
 
130
  SELECT * FROM mysql.slow_log;
 
131
  die "Assertion failed! Fast query FOUND in slow query log. Bailing out!";
 
132
}
 
133
 
 
134
if (!$found_slow_query)
 
135
{
 
136
  SELECT * FROM mysql.slow_log;
 
137
  die "Assertion failed! Slow query NOT FOUND in slow query log. Bailing out!";
 
138
}
 
139
TRUNCATE mysql.slow_log;
 
140
 
 
141
# test: 
 
142
#   check that when setting the slow_query_log= OFF on connection 'extra2'
 
143
#   prevents connection 'extra' from logging to slow query log.
 
144
 
 
145
let $fast_query= SELECT 3;
 
146
let $slow_query= SELECT 3, sleep(3);
 
147
 
 
148
connect(extra2,127.0.0.1,root,,test,$SLAVE_MYPORT);
 
149
connection extra2;
 
150
 
 
151
SET @old_slow_query_log= @@slow_query_log;
 
152
SET GLOBAL slow_query_log= 'OFF';
 
153
 
 
154
connection extra;
 
155
 
 
156
eval $slow_query;
 
157
eval $fast_query;
 
158
 
 
159
let $found_fast_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$fast_query'`;
 
160
let $found_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
 
161
 
 
162
if ($found_fast_query)
 
163
{
 
164
  SELECT * FROM mysql.slow_log;
 
165
  die "Assertion failed! Fast query FOUND in slow query log when slow_query_log= OFF. Bailing out!";
 
166
}
 
167
 
 
168
if ($found_slow_query)
 
169
{
 
170
  SELECT * FROM mysql.slow_log;
 
171
  die "Assertion failed! Slow query FOUND in slow query log when slow_query_log= OFF. Bailing out!";
 
172
}
 
173
TRUNCATE mysql.slow_log;
 
174
 
 
175
# clean up: drop tables, reset the variables back to the previous value,
 
176
#           disconnect extra connections
 
177
connection extra2;
 
178
SET GLOBAL slow_query_log= @old_slow_query_log;
 
179
 
 
180
connection master;
 
181
DROP TABLE t1;
 
182
sync_slave_with_master;
 
183
 
 
184
source include/stop_slave.inc;
 
185
 
 
186
SET GLOBAL long_query_time= @old_long_query_time;
 
187
SET GLOBAL log_output= @old_log_output;
 
188
 
 
189
source include/start_slave.inc;
 
190
 
 
191
disconnect extra;
 
192
disconnect extra2;
 
193
 
 
194
#
 
195
# BUG#50620: Adding an index to a table prevents slave from logging into slow log
 
196
#
 
197
 
 
198
-- source include/master-slave-reset.inc
 
199
 
 
200
-- connection master
 
201
SET @old_log_output= @@log_output;
 
202
SET GLOBAL log_output= 'TABLE';
 
203
SET GLOBAL long_query_time= 2;
 
204
SET @old_long_query_time= @@long_query_time;
 
205
SET SESSION long_query_time= 2;
 
206
TRUNCATE mysql.slow_log;
 
207
-- connection slave
 
208
 
 
209
-- source include/stop_slave.inc
 
210
SET @old_log_output= @@log_output;
 
211
SET GLOBAL log_output= 'TABLE';
 
212
SET @old_long_query_time= @@long_query_time;
 
213
SET GLOBAL long_query_time= 2;
 
214
TRUNCATE mysql.slow_log;
 
215
-- source include/start_slave.inc
 
216
 
 
217
let $slow_query= INSERT INTO t1 values(1, sleep(3));
 
218
 
 
219
-- connection master
 
220
CREATE TABLE t1 (a int, b int); 
 
221
 
 
222
-- echo ********************************************************************
 
223
-- echo **** INSERT one row that exceeds long_query_time
 
224
-- echo **** Outcome: query ends up in both master and slave slow log
 
225
-- echo ********************************************************************
 
226
 
 
227
-- disable_warnings
 
228
-- eval $slow_query
 
229
-- enable_warnings
 
230
 
 
231
let $master_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
 
232
-- sync_slave_with_master
 
233
let $slave_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
 
234
 
 
235
if (`SELECT $master_slow_query != $slave_slow_query`)
 
236
{
 
237
  -- connection master
 
238
  -- echo ***********************************************
 
239
  -- echo ** DUMPING MASTER SLOW LOG CONTENTS 
 
240
  -- echo ***********************************************
 
241
  SELECT * FROM mysql.slow_log;
 
242
 
 
243
  -- connection slave
 
244
  -- echo ***********************************************
 
245
  -- echo ** DUMPING SLAVE SLOW LOG CONTENTS 
 
246
  -- echo ***********************************************
 
247
  SELECT * FROM mysql.slow_log;
 
248
 
 
249
  -- die "Assertion failed! Master and slave slow log contents differ. Bailing out!"
 
250
}
 
251
 
 
252
if (`SELECT $master_slow_query = $slave_slow_query`)
 
253
{
 
254
  -- echo ### Assertion is good. Both Master and Slave exhibit the 
 
255
  -- echo ### same number of queries in slow log: $master_slow_query
 
256
}
 
257
 
 
258
TRUNCATE mysql.slow_log;
 
259
-- connection master
 
260
TRUNCATE mysql.slow_log;
 
261
 
 
262
-- echo ********************************************************************
 
263
-- echo **** Now do inserts again, but first add an index to the table.
 
264
-- echo **** Outcome: Note that the slave contains the same one entry (as 
 
265
-- echo ****          the master does)  whereas before the patch it did not.
 
266
-- echo ********************************************************************
 
267
 
 
268
ALTER TABLE t1 ADD INDEX id1(a);
 
269
 
 
270
-- disable_warnings
 
271
-- eval $slow_query
 
272
-- enable_warnings
 
273
 
 
274
let $master_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
 
275
-- sync_slave_with_master
 
276
let $slave_slow_query= `SELECT count(*) = 1 FROM mysql.slow_log WHERE sql_text like '$slow_query'`;
 
277
 
 
278
if (`SELECT $master_slow_query != $slave_slow_query`)
 
279
{
 
280
  -- connection master
 
281
  -- echo ***********************************************
 
282
  -- echo ** DUMPING MASTER SLOW LOG CONTENTS 
 
283
  -- echo ***********************************************
 
284
  SELECT * FROM mysql.slow_log;
 
285
 
 
286
  -- connection slave
 
287
  -- echo ***********************************************
 
288
  -- echo ** DUMPING SLAVE SLOW LOG CONTENTS 
 
289
  -- echo ***********************************************
 
290
  SELECT * FROM mysql.slow_log;
 
291
 
 
292
  -- die "Assertion failed! Master and slave slow log contents differ. Bailing out!"
 
293
}
 
294
 
 
295
if (`SELECT $master_slow_query = $slave_slow_query`)
 
296
{
 
297
  -- echo ### Assertion is good. Both Master and Slave exhibit the 
 
298
  -- echo ### same number of queries in slow log: $master_slow_query
 
299
}
 
300
 
 
301
-- connection master
 
302
SET @@global.log_output= @old_log_output;
 
303
SET @@global.long_query_time= @old_long_query_time;
 
304
DROP TABLE t1;
 
305
 
 
306
-- sync_slave_with_master
 
307
SET @@global.log_output= @old_log_output;
 
308
SET @@global.long_query_time= @old_long_query_time;