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

Merge lp:~gl-az/percona-server/bug1287650-5.6 into lp:percona-server/5.6

  1. bug1287650-5.6
  2. Merge into 5.6
Proposed by George Ormond Lorch III
Status: Merged
Approved by: Alexey Kopytov
Approved revision: no longer in the source branch.
Merged at revision: 579
Proposed branch: lp:~gl-az/percona-server/bug1287650-5.6
Merge into: lp:percona-server/5.6
Diff against target: 255 lines (+74/-6)
12 files modified
mysql-test/r/percona_slow_query_log_always_write.result (+3/-0)
mysql-test/r/percona_slow_query_log_rate.result (+3/-0)
mysql-test/r/percona_slow_query_log_rate_limit_write.result (+3/-0)
mysql-test/suite/sys_vars/r/log_slow_rate_limit_basic.result (+27/-3)
mysql-test/suite/sys_vars/t/log_slow_rate_limit_basic.test (+11/-1)
mysql-test/t/percona_slow_query_log_always_write.test (+5/-0)
mysql-test/t/percona_slow_query_log_rate.test (+10/-0)
mysql-test/t/percona_slow_query_log_rate_limit_write.test (+5/-0)
sql/sql_class.cc (+3/-0)
sql/sql_class.h (+2/-0)
sql/sql_parse.cc (+1/-1)
sql/sys_vars.cc (+1/-1)
To merge this branch: bzr merge lp:~gl-az/percona-server/bug1287650-5.6
Reviewer Review Type Date Requested Status
Alexey Kopytov (community) Approve
Laurynas Biveinis Pending
Review via email: mp+209548@code.launchpad.net

Description of the change

bug 1290714 - Maximum allowed value for log_slow_rate_limit is unreasonably high

As suggested by Alexey, set the upper bound of the log_slow_rate_limit to
1000.

Modified sys_vars/log_slow_rate_limit.test to test for invalid rates.

bug 1287650 - Change log_slow_rate_type=query log_slow_rate_limit to be random

A simple change was made to allow selection of query to be logged to be random rather than exactly every nth query. This is achieved by addind a new
rand_struct to 'class THD'. This has some ramifications for mtr cases in that the actual queries logged and number of queries logged will be pseudo random and only deterministic as long as the random sequence remains constant. To address this, a DBUG_EXECUTE_IF was added to the THD initialization to seed the new rand_struct with some constants rather than environmental/random-ish values. This new debug state will only be utilized during a connection start up so care must be observed in writing mtr cases that need this. They must set the debug state then either reconnect or create a new connection to perform any testing that requires deterministic results from the slow log rate limit. Over time, the rate limit specified will be respected but at any given moment the rate will likely be slightly over or under shot.

To post a comment you must log in.
Revision history for this message
George Ormond Lorch III (gl-az) wrote :

MAde fixes ad new jenkins: http://jenkins.percona.com/view/PS%205.6/job/percona-server-5.6-param/541/

Revision history for this message
Alexey Kopytov (akopytov) :
review: Needs Fixing
Revision history for this message
George Ormond Lorch III (gl-az) wrote :

New jenkins: http://jenkins.percona.com/view/PS%205.6/job/percona-server-5.6-param/542/

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

George, you can avoid the mutex by using per-connection RNG state, see THD::rand, for example. You can even reuse that state I guess without creating another one.

That state is initialized on THD creation from another random number. To get deterministic test results you could have a DBUG_EXECUTE_IF() seeding it with a constant number instead.

Also, multiplying the value by SLOG_SLOW_RATE_LIMIT_MAX and then comparing the result modulo log_slow_rate_limit to 0 is incorrect. You can multiply my_rnd() by log_slow_rate_limit and compare that number to zero (or any other number < log_slow_rate_limit). Or, compare the my_rnd() result directly with 1 / (double) log_slow_rate_limit.

review: Needs Fixing
Revision history for this message
George Ormond Lorch III (gl-az) wrote :

jenkins http://jenkins.percona.com/view/PS%205.6/job/percona-server-5.6-param/590/

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/r/percona_slow_query_log_always_write.result'
2--- mysql-test/r/percona_slow_query_log_always_write.result 2013-08-28 21:14:46 +0000
3+++ mysql-test/r/percona_slow_query_log_always_write.result 2014-04-18 19:16:06 +0000
4@@ -2,6 +2,8 @@
5 SET @old_log_slow_rate_type=@@global.log_slow_rate_type;
6 SET @old_log_slow_rate_limit=@@global.log_slow_rate_limit;
7 SET @old_slow_query_log_always_write_time=@@global.slow_query_log_always_write_time;
8+SET @old_debug=@@global.debug;
9+SET GLOBAL debug="+d,seed_slow_log_random";
10 SET GLOBAL log_slow_rate_type='session';
11 SET GLOBAL long_query_time=10.0;
12 SET GLOBAL log_slow_rate_limit=999;
13@@ -35,6 +37,7 @@
14 [log_grep.inc] lines: 1
15 [log_grep.inc] file: percona.slow_extended.log_slow_always_write_time_2 pattern: this-should-not-be-logged
16 [log_grep.inc] lines: 0
17+SET GLOBAL debug=$old_debug;
18 SET GLOBAL long_query_time=@old_long_query_time;
19 SET GLOBAL log_slow_rate_type=@old_log_slow_rate_type;
20 SET GLOBAL log_slow_rate_limit=@old_log_slow_rate_limit;
21
22=== modified file 'mysql-test/r/percona_slow_query_log_rate.result'
23--- mysql-test/r/percona_slow_query_log_rate.result 2013-08-28 21:14:46 +0000
24+++ mysql-test/r/percona_slow_query_log_rate.result 2014-04-18 19:16:06 +0000
25@@ -1,3 +1,5 @@
26+SET @old_debug=@@global.debug;
27+SET GLOBAL debug="+d,seed_slow_log_random";
28 SET GLOBAL long_query_time=0;
29 SET GLOBAL log_slow_rate_type='session';
30 SET GLOBAL log_slow_rate_limit=3;
31@@ -24,6 +26,7 @@
32 [log_grep.inc] file: percona.slow_extended.log_slow_rate_limit_1 pattern:
33 [log_grep.inc] sum: 2
34 [log_grep.inc] zero: 2
35+SET GLOBAL debug="+d,seed_slow_log_random";
36 SET GLOBAL log_slow_rate_type='query';
37 SET GLOBAL log_slow_rate_limit=2;
38 [log_start.inc] percona.slow_extended.log_slow_rate_limit_2
39
40=== modified file 'mysql-test/r/percona_slow_query_log_rate_limit_write.result'
41--- mysql-test/r/percona_slow_query_log_rate_limit_write.result 2013-08-28 21:14:46 +0000
42+++ mysql-test/r/percona_slow_query_log_rate_limit_write.result 2014-04-18 19:16:06 +0000
43@@ -2,6 +2,8 @@
44 SET @old_long_query_time=@@global.long_query_time;
45 SET @old_log_slow_rate_limit=@@global.log_slow_rate_limit;
46 SET @old_slow_query_log_always_write_time=@@global.slow_query_log_always_write_time;
47+SET @old_debug=@@global.debug;
48+SET GLOBAL debug="+d,seed_slow_log_random";
49 SET GLOBAL log_slow_rate_type='session';
50 SET GLOBAL long_query_time=10.0;
51 SET GLOBAL log_slow_rate_limit=999;
52@@ -32,6 +34,7 @@
53 [log_grep.inc] file: percona.slow_extended.percona_slow_query_log_rate_limit_write_2 pattern: ^# Log_slow_rate_type:
54 [log_grep.inc] lines: 1
55 SET GLOBAL long_query_time=0;
56+SET GLOBAL debug=$old_debug;
57 SET GLOBAL log_slow_rate_type=@old_log_slow_rate_type;
58 SET GLOBAL log_slow_rate_limit=@old_log_slow_rate_limit;
59 SET GLOBAL slow_query_log_always_write_time=@old_slow_query_log_always_write_time;
60
61=== modified file 'mysql-test/suite/sys_vars/r/log_slow_rate_limit_basic.result'
62--- mysql-test/suite/sys_vars/r/log_slow_rate_limit_basic.result 2012-04-18 23:25:38 +0000
63+++ mysql-test/suite/sys_vars/r/log_slow_rate_limit_basic.result 2014-04-18 19:16:06 +0000
64@@ -1,3 +1,27 @@
65-SELECT @@global.log_slow_rate_limit;
66-@@global.log_slow_rate_limit
67-1
68+SET @@global.log_slow_rate_limit = -1;
69+Warnings:
70+Warning 1292 Truncated incorrect log_slow_rate_limit value: '-1'
71+SELECT @@global.log_slow_rate_limit;
72+@@global.log_slow_rate_limit
73+1
74+SET @@global.log_slow_rate_limit = 0;
75+Warnings:
76+Warning 1292 Truncated incorrect log_slow_rate_limit value: '0'
77+SELECT @@global.log_slow_rate_limit;
78+@@global.log_slow_rate_limit
79+1
80+SET @@global.log_slow_rate_limit = 1;
81+SELECT @@global.log_slow_rate_limit;
82+@@global.log_slow_rate_limit
83+1
84+SET @@global.log_slow_rate_limit = 1000;
85+SELECT @@global.log_slow_rate_limit;
86+@@global.log_slow_rate_limit
87+1000
88+SET @@global.log_slow_rate_limit = 1001;
89+Warnings:
90+Warning 1292 Truncated incorrect log_slow_rate_limit value: '1001'
91+SELECT @@global.log_slow_rate_limit;
92+@@global.log_slow_rate_limit
93+1000
94+SET @@global.log_slow_rate_limit = default;
95
96=== modified file 'mysql-test/suite/sys_vars/t/log_slow_rate_limit_basic.test'
97--- mysql-test/suite/sys_vars/t/log_slow_rate_limit_basic.test 2012-04-18 23:25:38 +0000
98+++ mysql-test/suite/sys_vars/t/log_slow_rate_limit_basic.test 2014-04-18 19:16:06 +0000
99@@ -1,1 +1,11 @@
100-SELECT @@global.log_slow_rate_limit;
101+SET @@global.log_slow_rate_limit = -1;
102+SELECT @@global.log_slow_rate_limit;
103+SET @@global.log_slow_rate_limit = 0;
104+SELECT @@global.log_slow_rate_limit;
105+SET @@global.log_slow_rate_limit = 1;
106+SELECT @@global.log_slow_rate_limit;
107+SET @@global.log_slow_rate_limit = 1000;
108+SELECT @@global.log_slow_rate_limit;
109+SET @@global.log_slow_rate_limit = 1001;
110+SELECT @@global.log_slow_rate_limit;
111+SET @@global.log_slow_rate_limit = default;
112
113=== modified file 'mysql-test/t/percona_slow_query_log_always_write.test'
114--- mysql-test/t/percona_slow_query_log_always_write.test 2013-08-28 21:14:46 +0000
115+++ mysql-test/t/percona_slow_query_log_always_write.test 2014-04-18 19:16:06 +0000
116@@ -12,6 +12,10 @@
117 SET @old_log_slow_rate_limit=@@global.log_slow_rate_limit;
118 SET @old_slow_query_log_always_write_time=@@global.slow_query_log_always_write_time;
119
120+# Force deterministic random pattern of slow log filter for new connections
121+SET @old_debug=@@global.debug;
122+SET GLOBAL debug="+d,seed_slow_log_random";
123+
124 SET GLOBAL log_slow_rate_type='session';
125 SET GLOBAL long_query_time=10.0;
126 SET GLOBAL log_slow_rate_limit=999;
127@@ -69,6 +73,7 @@
128 --source include/log_grep.inc
129
130 # off the rate limit
131+SET GLOBAL debug=$old_debug;
132 SET GLOBAL long_query_time=@old_long_query_time;
133 SET GLOBAL log_slow_rate_type=@old_log_slow_rate_type;
134 SET GLOBAL log_slow_rate_limit=@old_log_slow_rate_limit;
135
136=== modified file 'mysql-test/t/percona_slow_query_log_rate.test'
137--- mysql-test/t/percona_slow_query_log_rate.test 2013-08-28 21:14:46 +0000
138+++ mysql-test/t/percona_slow_query_log_rate.test 2014-04-18 19:16:06 +0000
139@@ -1,3 +1,5 @@
140+--source include/have_debug.inc
141+
142 # Force deterministic session and query ids
143 --source include/restart_mysqld.inc
144
145@@ -6,6 +8,10 @@
146 let $old_log_slow_rate_limit=`SELECT @@global.log_slow_rate_limit`;
147 let $old_slow_query_log_always_write_time=`SELECT @@global.slow_query_log_always_write_time`;
148
149+# Force deterministic random pattern of slow log filter for new connections
150+SET @old_debug=@@global.debug;
151+SET GLOBAL debug="+d,seed_slow_log_random";
152+
153 SET GLOBAL long_query_time=0;
154
155 SET GLOBAL log_slow_rate_type='session';
156@@ -17,12 +23,16 @@
157 # disconnect checks at the end of the previous test
158 --source include/restart_mysqld.inc
159
160+# Force deterministic random pattern of slow log filter for new connections again
161+SET GLOBAL debug="+d,seed_slow_log_random";
162+
163 SET GLOBAL log_slow_rate_type='query';
164 SET GLOBAL log_slow_rate_limit=2;
165 --let log_file=percona.slow_extended.log_slow_rate_limit_2
166 --source include/percona_slow_query_log_rate.inc
167
168 --disable_query_log
169+SET GLOBAL debug=$old_debug;
170 eval SET GLOBAL long_query_time=$old_long_query_time;
171 eval SET GLOBAL log_slow_rate_type=$old_log_slow_rate_type;
172 eval SET GLOBAL log_slow_rate_limit=$old_log_slow_rate_limit;
173
174=== modified file 'mysql-test/t/percona_slow_query_log_rate_limit_write.test'
175--- mysql-test/t/percona_slow_query_log_rate_limit_write.test 2013-08-28 21:14:46 +0000
176+++ mysql-test/t/percona_slow_query_log_rate_limit_write.test 2014-04-18 19:16:06 +0000
177@@ -11,6 +11,10 @@
178 SET @old_log_slow_rate_limit=@@global.log_slow_rate_limit;
179 SET @old_slow_query_log_always_write_time=@@global.slow_query_log_always_write_time;
180
181+# Force deterministic random pattern of slow log filter for new connections
182+SET @old_debug=@@global.debug;
183+SET GLOBAL debug="+d,seed_slow_log_random";
184+
185 SET GLOBAL log_slow_rate_type='session';
186 SET GLOBAL long_query_time=10.0;
187 SET GLOBAL log_slow_rate_limit=999;
188@@ -63,6 +67,7 @@
189 # off the rate limit
190 SET GLOBAL long_query_time=0;
191
192+SET GLOBAL debug=$old_debug;
193 SET GLOBAL log_slow_rate_type=@old_log_slow_rate_type;
194 SET GLOBAL log_slow_rate_limit=@old_log_slow_rate_limit;
195 SET GLOBAL slow_query_log_always_write_time=@old_slow_query_log_always_write_time;
196
197=== modified file 'sql/sql_class.cc'
198--- sql/sql_class.cc 2014-03-17 10:59:40 +0000
199+++ sql/sql_class.cc 2014-04-18 19:16:06 +0000
200@@ -1117,6 +1117,9 @@
201 tablespace_op=FALSE;
202 tmp= sql_rnd_with_mutex();
203 randominit(&rand, tmp + (ulong) &rand, tmp + (ulong) ::global_query_id);
204+ randominit(&slog_rand, tmp + (ulong) &slog_rand, tmp + (ulong) ::global_query_id);
205+ DBUG_EXECUTE_IF("seed_slow_log_random",
206+ randominit(&slog_rand, 0x11111111, 0x77777777););
207 substitute_null_with_insert_id = FALSE;
208 thr_lock_info_init(&lock_info); /* safety: will be reset after start */
209
210
211=== modified file 'sql/sql_class.h'
212--- sql/sql_class.h 2014-03-26 10:11:16 +0000
213+++ sql/sql_class.h 2014-04-18 19:16:06 +0000
214@@ -122,6 +122,7 @@
215 SLOG_F_TMP_TABLE, SLOG_F_TMP_DISK, SLOG_F_FILESORT,
216 SLOG_F_FILESORT_DISK
217 };
218+#define SLOG_SLOW_RATE_LIMIT_MAX 1000
219 enum enum_log_warnings_suppress { log_warnings_suppress_1592 };
220 enum enum_slave_exec_mode { SLAVE_EXEC_MODE_STRICT,
221 SLAVE_EXEC_MODE_IDEMPOTENT,
222@@ -2263,6 +2264,7 @@
223 String packet; // dynamic buffer for network I/O
224 String convert_buffer; // buffer for charset conversions
225 struct rand_struct rand; // used for authentication
226+ struct rand_struct slog_rand; // used for random slow log filtering
227 struct system_variables variables; // Changeable local variables
228 struct system_status_var status_var; // Per thread statistic vars
229 struct system_status_var *initial_status_var; /* used by show status */
230
231=== modified file 'sql/sql_parse.cc'
232--- sql/sql_parse.cc 2014-03-26 10:11:16 +0000
233+++ sql/sql_parse.cc 2014-04-18 19:16:06 +0000
234@@ -2031,7 +2031,7 @@
235
236 if (opt_slow_query_log_rate_type == SLOG_RT_QUERY
237 && thd->variables.log_slow_rate_limit
238- && thd->query_id % thd->variables.log_slow_rate_limit
239+ && my_rnd(&thd->slog_rand) * ((double)thd->variables.log_slow_rate_limit) > 1.0
240 && query_exec_time < slow_query_log_always_write_time
241 && (thd->variables.long_query_time >= 1000000
242 || (ulong) query_exec_time < 1000000)) {
243
244=== modified file 'sql/sys_vars.cc'
245--- sql/sys_vars.cc 2014-03-19 06:42:26 +0000
246+++ sql/sys_vars.cc 2014-04-18 19:16:06 +0000
247@@ -4072,7 +4072,7 @@
248 static Sys_var_ulong sys_log_slow_rate_limit(
249 "log_slow_rate_limit","Rate limit statement writes to slow log to only those from every (1/log_slow_rate_limit) session.",
250 SESSION_VAR(log_slow_rate_limit), CMD_LINE(REQUIRED_ARG),
251- VALID_RANGE(1, ULONG_MAX), DEFAULT(1), BLOCK_SIZE(1));
252+ VALID_RANGE(1, SLOG_SLOW_RATE_LIMIT_MAX), DEFAULT(1), BLOCK_SIZE(1));
253
254 static double opt_slow_query_log_always_write_time;
255 static bool update_slow_query_log_always_write_time(sys_var *self, THD *thd,

Subscribers

People subscribed via source and target branches