Merge lp:~dingqi-lxb/percona-server/5.5_log_queries_in_memory into lp:percona-server/5.5

Proposed by 林晓斌
Status: Work in progress
Proposed branch: lp:~dingqi-lxb/percona-server/5.5_log_queries_in_memory
Merge into: lp:percona-server/5.5
Diff against target: 896 lines (+879/-0)
3 files modified
doc/source/diagnostics/slow_log_in_memory.rst (+74/-0)
patches/series (+1/-0)
patches/slowlog_in_memory.patch (+804/-0)
To merge this branch: bzr merge lp:~dingqi-lxb/percona-server/5.5_log_queries_in_memory
Reviewer Review Type Date Requested Status
Oleg Tsarev (community) Needs Fixing
Review via email: mp+87244@code.launchpad.net

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

Description of the change

http://jenkins.percona.com/view/Percona%20Server%205.5/job/percona-server-5.5-param/258/

patch for https://blueprints.launchpad.net/percona-server/+spec/log-queries-in-memory.

add a variable 'slowlog_in_memory_audit_max_memory' and global status 'slow_log_current_memory'

If the current_memory grows larger than max_memory, the eldest ones will be wash out.
Same action happens when max_mamory are set to a new value that is less than current_memory.

To post a comment you must log in.
Revision history for this message
Oleg Tsarev (tsarev) wrote : Posted in a previous version of this proposal

1. Please add patch name to the "patches/series" file
2. About innodb_trx_id. Please look to two following cases:
 * log_slow_verbosity doesn't set "innodb"
 * query doesn't use the InnoDB
In first case slow query log will has no information about InnoDB
In second case slow query will have line "# No InnoDB statistics available for this query\n"
In this two cases innodb_trx_id will be incorrect, and you can't use and setup it.

Please handle variable innodb_was_used correctly (at least for innodb_trx_id)

3. Following is very, very bad:
+ if (general_query)
+ {
....
+ }
+ else
+ {
+ this->general_query= "NULL";
+ this->general_query_len= 5;
+ }
You are break SQL semantic. For example query:
SELECT * FROM INSFORMATION_SCHEMA.I_S_SLOW_LOG WHERE QUERY IS NULL
or any join will not work correctly.
You are break SQL language semantic by string "NULL" instead of NULL

Same for Schema.

4. I_S_SLOW_LOG not very good name. Why SLOW_LOG bad?

5. Please add documentation to the doc/

6. Sleep in the test file - bad idea. Please replace this by debug variable query_exec_time.

7. Please add tests to sys_vars suite for the all added variables.

Please fix this, and I will review again.

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

8.
+ ulonglong utime_of_query= thd->current_utime() - thd->utime_after_lock;
+ if (utime_of_query <= thd->variables.long_query_time)
+ return;

Please look into the slow_extended.patch:

static inline ulonglong get_query_exec_time(THD *thd, ulonglong cur_utime)
...
thd->server_status|= SERVER_QUERY_WAS_SLOW;

Please better use this status variable, instead of calculate query execution time directly.

Revision history for this message
林晓斌 (dingqi-lxb) wrote : Posted in a previous version of this proposal

Thank you. Oleg, I have some items to discuss.

2. About innodb_trx_id. Please look to two following cases
   In these two cases, the variable thd->innodb_trx_id is set to 0. It seems that I have to show it in the result table as 0, is there other result even use innodb_was_used ?

8.About calculating query execution time directly, it is because that I have to get the query_time, the status is not enough.

* Why plugin doesn't uninstall in test?
  You mean that it shows " Plugin is busy and will be uninstalled on shutdown" in result-file? It is the same with the demo for audit plugin "null_audit", the strategy decided by mysqld

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

On Mon, Dec 12, 2011 at 12:05 PM, 林晓斌 <email address hidden> wrote:
> Thank you. Oleg, I have some items to discuss.
>
> 2. About innodb_trx_id. Please look to two following cases
>   In these two cases, the variable thd->innodb_trx_id is set to 0.  It seems that I have to show it in the result table as 0, is there other result even use innodb_was_used ?

I think right decision is "NULL" value instead of 0.
>
> 8.About calculating query execution time directly, it is because that I have to get the query_time, the status is not enough.
>
> * Why plugin doesn't uninstall in test?
>  You mean that it shows " Plugin is busy and will be uninstalled on shutdown" in result-file? It is the same with the demo for audit plugin "null_audit", the strategy decided by mysqld

Ok

> --
> https://code.launchpad.net/~dingqi-lxb/percona-server/5.5_log_queries_in_memory/+merge/85251
> You are reviewing the proposed merge of lp:~dingqi-lxb/percona-server/5.5_log_queries_in_memory into lp:percona-server.

--
Oleg Tsarev, Software Engineer, Percona Inc.

Revision history for this message
林晓斌 (dingqi-lxb) wrote : Posted in a previous version of this proposal

2. About innodb_trx_id. Generally, when the thd->innodb_trx_id is 0, the value of "INNODB_TRX_ID" should show NULL, so the thd->innodb_was_used will not be imported here.

7. Please add tests to sys_vars suite for the all added variables.
   The variable add in this plugin will not be seen in other test-case, it can only be seen the plugin is installed. So, is test-case in sys_vars suits necessary?

Revision history for this message
Stewart Smith (stewart) wrote : Posted in a previous version of this proposal

On Wed, 21 Dec 2011 02:50:35 -0000, 林晓斌 <email address hidden> wrote:
> +There are two plugins in the feature. They can be installed by
> command ``"install plugin SLOWLOG_IN_MEMORY_AUDIT soname
> 'slowlog_in_memory.so'"`` and ``"install plugin SLOW_LOG soname
> 'slowlog_in_memory.so'"``, they work by keeping one list in memory.

I think we should be consistent in naming. SLOW_LOG instead of SLOWLOG
and slow_log instead of slowlog.
--
Stewart Smith

Revision history for this message
Baron Schwartz (baron-xaprb) wrote : Posted in a previous version of this proposal

I'm sorry that I haven't noticed this discussion before, but I believe that it would be best to avoid a query time in milliseconds:

1. It should have microsecond resolution. Milliseconds is not enough.
2. It should be named EXEC_TIME and should be a floating-point value in seconds so the user does not have to convert the value to seconds.

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

About documentation:

1) Please link to page page "Slow Log In Memory" to the index of documentation (to "Diagnostic" article)

2) "MS_QUERY_TIME – The query_exec_time of the query, in second."
But looks like time in the milliseconds

About the patch:

3) You avoid the "quiltrc" config file from the root of branch. As result your patch has incorrect format.
Please, use "quilt --quiltrc=quiltrc ..." while you touch the patches

About the feature:
4) I think, we should add at least following:
  * User
  * Query_time (microseconds)

About the tests:

5) Here is little example of incorrect work (JUST EXAMPLE):
http://bazaar.launchpad.net/~tsarev/percona-server/5.5_log_queries_in_memory/revision/202
So, your implementation avoid all variables related to slow query log, except long_query_time.
  * How to right test: modify all tests provided by slow_extended.patch. Right now their check a slow query log by "log_grep.inc". You should add similar checks of plugin to every test.

About the implementation:

6) Incorrect works with query exec time:
 ulonglong utime_of_query= thd->current_utime() - thd->utime_after_lock;
 * Possible scenario: query doesn't pass to slow query log, but pass to INFORMATION_SCHEMA.SLOW_LOG memory. Or opposite.
 * How to fix: you shoud use thd->server_status variable for detect insert or don't insert event to SLOW_LOG table. This allows to support all related options from PS.
 * What requires the modify: slow_extended.patch. thd->server_status variable (SERVER_QUERY_WAS_SLOW flag) should setup status of every query (and also should be used both in PS and plugin)

7) Separatelly about this:

+ ulonglong utime_of_query= thd->current_utime() - thd->utime_after_lock;
+
+#ifndef DBUG_OFF
+ if (thd->variables.query_exec_time != 0)
+ utime_of_query= thd->lex->sql_command != SQLCOM_SET_OPTION ? thd->variables.query_exec_time : 0;
+#endif
+
+ if (utime_of_query <= thd->variables.long_query_time)
+ return;

Copy-paste - not a very good idea.

8) Class slow_log_list. Some methods lock/unlock mutexes, some not (pop_front). It think this is a bad contract-to-interface .

9) Event Id can be missordered (different from order of events in the list)

10) Order of event can be missordered (different from slow query log)

11) Class slow_log_list. Why "first" and "last" are public members?

12) Please also note: subunit has a #bug 911237 - according to 5.5 testing not a work right now. Please merge fix then it will be merged to lp:percona-server

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

To 12) - fix already in lp:percona-server, just need a merge before future tests

Revision history for this message
林晓斌 (dingqi-lxb) wrote :

4)There is Query_time already, will be shown as 1.1234, in senconds, what does this Query_time mean?

6) ok, before recored it, I will check thd->server_status before. But the result of utime_of_query has to be re-calculated here all the same.

7) what does this mean?

9) Yes, the procedure of assigning event_id and putting into the list is not locked as a whole, for performance consideration. Ok, I will lock them as a whole.

10) This can not be confirmed. Because the procedre of logging into slow log and loging into memory are different plugins. Is there any proposal?

11) Because the "first" and "last" needs to be accessed at i_s_fill_table_slow_log

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

4) This is Ok. Also please ask Baron about Lock_time
6) Not a "before", but "instead". You should not use direct utime_of_query calculation. Please replace any calculation by check of flag thd->server_status
7) This is mean you should not use copy-paste. Never.
9) Any perfomance consideration should not break the correct work
10) You can modify the slow_extended.patch and create event id on server-side. But this is requires consideration
11) Why you didn't add public interface for iteration instead of access to members?

Revision history for this message
林晓斌 (dingqi-lxb) wrote :

6) Check can use thd->server_status, but I need to calculate the utime_of_query if the thd->server_status & SERVER_QUERY_WAS_SLOW != 0, because I need to recored it, right?

10) It will make the plugin depart from the concept that it can be used in both Percona-server and Oracle-mysql directly. I propose that it remains the current strategy, if the misorder between memory and slow log can be tolerant.

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

6) right
10) ok

Unmerged revisions

200. By 林晓斌

add slowlog_in_memory.patch

199. By 林晓斌

merge from trunk

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== added file 'doc/source/diagnostics/slow_log_in_memory.rst'
2--- doc/source/diagnostics/slow_log_in_memory.rst 1970-01-01 00:00:00 +0000
3+++ doc/source/diagnostics/slow_log_in_memory.rst 2012-01-02 12:24:34 +0000
4@@ -0,0 +1,74 @@
5+.. _slow_log_in_memory:
6+
7+=================
8+ Slow Log In Memory
9+=================
10+
11+The feature is used to save slow queries in memory. This feature adds an ``INFORMATION_SCHEMA.SLOW_LOG`` table to show the latest queries, a variable to limit the max memory used, and status to show the status of memory used.
12+
13+There are two plugins in the feature. They can be installed by command ``"install plugin SLOWLOG_IN_MEMORY_AUDIT soname 'slowlog_in_memory.so'"`` and ``"install plugin SLOW_LOG soname 'slowlog_in_memory.so'"``, they work by keeping one list in memory.
14+
15+
16+Other Information
17+=================
18+
19+ * Author/Origin:
20+ *Percona*; *Percona* added an ``INFORMATION_SCHEMA`` table and the :variable:`slowlog_in_memory_audit_max_memory` and the :status:`slow_log_current_memory`.
21+
22+System Variables
23+================
24+
25+.. variable:: slowlog_in_memory_audit_max_memory
26+
27+ :cli: Yes
28+ :conf: Yes
29+ :scope: Global
30+ :dyn: Yes
31+ :vartype: ULONG
32+ :default: 1M
33+ :range: 0 - 1G
34+
35+The variable is used to limit the max-memory used for slow log. If a new slow query will make the `current_memory` bigger than this value, the most eldest items will be discarded, until there is enough memory for new item. When the value is decrease dynamically, it behaves the same.
36+
37+Status Variables
38+================
39+
40+One new status variable was introduced by this feature.
41+
42+.. variable:: slow_log_current_memory
43+
44+ :vartype: ULONG
45+ :scope: Global
46+
47+The variable showes the current memory used for the slow queries. It can never be bigger than the `slowlog_in_memory_audit_max_memory` variable.
48+
49+
50+INFORMATION_SCHEMA Tables
51+=========================
52+
53+.. table:: INFORMATION_SCHEMA.SLOW_LOG
54+
55+ :column EVENT_ID: A global increment id for every record in the table, can be used to identify every one.
56+ :column TIMESTAMP: The timestamp when the query stop.
57+ :column THREAD_ID: The thread_id of the query.
58+ :column DB: The current database() of the query, may be NULL.
59+ :column INNODB_TRX_ID: The Innodb_trx_id if InnoDB is used, may be NULL.
60+ :column ERROR: The errno of the query, 0 means no error.
61+ :column MS_QUERY_TIME: The query_exec_time of the query, in second.
62+ :column QUERY: The query statement.
63+
64+This table holds the lastest slow queries.
65+
66+Example: ::
67+
68+ mysql> select * from information_schema.slow_log \G
69+ *************************** 1. row ***************************
70+ EVENT_ID: 1
71+ TIMESTAMP: 1323753896
72+ THREAD_ID: 2
73+ DB: test
74+ INNODB_TRX_ID: NULL
75+ ERRNO: 0
76+ MS_QUERY_TIME: 3001
77+ QUERY: select sleep(3)
78+
79
80=== modified file 'patches/series'
81--- patches/series 2011-12-16 09:37:26 +0000
82+++ patches/series 2012-01-02 12:24:34 +0000
83@@ -62,3 +62,4 @@
84 bug45702.patch
85 group_commit.patch
86 warning_fixes.patch
87+slowlog_in_memory.patch
88
89=== added file 'patches/slowlog_in_memory.patch'
90--- patches/slowlog_in_memory.patch 1970-01-01 00:00:00 +0000
91+++ patches/slowlog_in_memory.patch 2012-01-02 12:24:34 +0000
92@@ -0,0 +1,804 @@
93+--- a/plugin/slowlog_in_memory/CMakeLists.txt 1970-01-01 08:00:00.000000000 +0800
94++++ b/plugin/slowlog_in_memory/CMakeLists.txt 2011-12-22 21:08:28.000000000 +0800
95+@@ -0,0 +1,17 @@
96++# Copyright (c) 2006, 2010, Oracle and/or its affiliates. All rights reserved.
97++#
98++# This program is free software; you can redistribute it and/or modify
99++# it under the terms of the GNU General Public License as published by
100++# the Free Software Foundation; version 2 of the License.
101++#
102++# This program is distributed in the hope that it will be useful,
103++# but WITHOUT ANY WARRANTY; without even the implied warranty of
104++# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
105++# GNU General Public License for more details.
106++#
107++# You should have received a copy of the GNU General Public License
108++# along with this program; if not, write to the Free Software
109++# Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA
110++
111++MYSQL_ADD_PLUGIN(slowlog_in_memory slowlog_in_memory.cc
112++ MODULE_ONLY MODULE_OUTPUT_NAME "slowlog_in_memory")
113+--- a/plugin/slowlog_in_memory/slowlog_in_memory.cc 1970-01-01 08:00:00.000000000 +0800
114++++ b/plugin/slowlog_in_memory/slowlog_in_memory.cc 2011-12-22 21:09:34.000000000 +0800
115+@@ -0,0 +1,295 @@
116++/* Copyright (c) 2006, 2011, Oracle and/or its affiliates. All rights reserved.
117++
118++ This program is free software; you can redistribute it and/or
119++ modify it under the terms of the GNU General Public License
120++ as published by the Free Software Foundation; version 2 of
121++ the License.
122++
123++ This program is distributed in the hope that it will be useful,
124++ but WITHOUT ANY WARRANTY; without even the implied warranty of
125++ MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
126++ GNU General Public License for more details.
127++
128++ You should have received a copy of the GNU General Public License
129++ along with this program; if not, write to the Free Software
130++ Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA */
131++
132++#include "ut_slow_log_list.h"
133++
134++#if !defined(__attribute__) && (defined(__cplusplus) || !defined(__GNUC__) || __GNUC__ == 2 && __GNUC_MINOR__ < 8)
135++#define __attribute__(A)
136++#endif
137++typedef struct st_mysql_sys_var SYS_VAR;
138++uint max_memory_for_slow_log;
139++
140++/* lock management */
141++
142++slow_log_list *global_slow_log_list= NULL;
143++
144++/*
145++ Initialize the plugin at server start or plugin installation.
146++
147++ SYNOPSIS
148++ slow_log_in_memory_plugin_init()
149++
150++ DESCRIPTION
151++ Does nothing.
152++
153++ RETURN VALUE
154++ 0 success
155++ 1 failure (cannot happen)
156++*/
157++
158++static int slow_log_in_memory_plugin_init(void *arg __attribute__((unused)))
159++{
160++#ifdef HAVE_PSI_INTERFACE
161++ init_semisync_psi_keys();
162++#endif
163++
164++ mysql_mutex_init(key_ss_mutex_LOCK_slow_event_id_,
165++ &LOCK_slow_event_id_, MY_MUTEX_INIT_FAST);
166++ global_slow_log_list= new slow_log_list(max_memory_for_slow_log);
167++
168++ return 0;
169++}
170++
171++
172++/*
173++ Terminate the plugin at server shutdown or plugin deinstallation.
174++
175++ SYNOPSIS
176++ slow_log_in_memory_plugin_deinit()
177++ Does nothing.
178++
179++ RETURN VALUE
180++ 0 success
181++ 1 failure (cannot happen)
182++*/
183++
184++static int slow_log_in_memory_plugin_deinit(void *arg __attribute__((unused)))
185++{
186++ if (global_slow_log_list)
187++ {
188++ delete global_slow_log_list;
189++ global_slow_log_list= NULL;
190++ }
191++
192++ mysql_mutex_destroy(&LOCK_slow_event_id_);
193++ return 0;
194++}
195++
196++/*
197++ Foo
198++
199++ SYNOPSIS
200++ slow_log_in_memory_notify()
201++ thd connection context
202++
203++ DESCRIPTION
204++*/
205++
206++static void slow_log_in_memory_notify(MYSQL_THD thd __attribute__((unused)),
207++ unsigned int event_class,
208++ const void *event)
209++{
210++ if (max_memory_for_slow_log == 0) return;
211++
212++ if (event_class == MYSQL_AUDIT_GENERAL_CLASS)
213++ {
214++ const struct mysql_event_general *event_general=
215++ (const struct mysql_event_general *) event;
216++ if (event_general->event_subclass != MYSQL_AUDIT_GENERAL_STATUS)
217++ return;
218++
219++ ulonglong utime_of_query= thd->current_utime() - thd->utime_after_lock;
220++
221++#ifndef DBUG_OFF
222++ if (thd->variables.query_exec_time != 0)
223++ utime_of_query= thd->lex->sql_command != SQLCOM_SET_OPTION ? thd->variables.query_exec_time : 0;
224++#endif
225++
226++ if (utime_of_query <= thd->variables.long_query_time)
227++ return;
228++
229++ slow_log_t *tmp= new slow_log_t(event_general->general_time, event_general->general_thread_id, thd->db, thd->innodb_trx_id, event_general->general_error_code, (double)utime_of_query/1000000, event_general->general_query);
230++ global_slow_log_list->push_back(tmp);
231++ }
232++}
233++
234++
235++/*
236++ Plugin type-specific descriptor
237++*/
238++
239++static struct st_mysql_audit slow_log_in_memory_descriptor=
240++{
241++ MYSQL_AUDIT_INTERFACE_VERSION, /* interface version */
242++ NULL, /* release_thd function */
243++ slow_log_in_memory_notify, /* notify function */
244++ { (unsigned long) MYSQL_AUDIT_GENERAL_CLASSMASK } /* class mask */
245++};
246++
247++static void change_max_memory_for_slow_log(MYSQL_THD thd,
248++ SYS_VAR *var,
249++ void *ptr,
250++ const void *val)
251++{
252++ uint new_len= *(uint *)val;
253++ *(uint *)ptr= new_len;
254++
255++ global_slow_log_list->change_max_memory(new_len);
256++ return;
257++}
258++
259++static MYSQL_SYSVAR_UINT(max_memory, max_memory_for_slow_log,
260++ PLUGIN_VAR_OPCMDARG,
261++ "The max memory that can be allocated for slow log.",
262++ NULL, // check
263++ &change_max_memory_for_slow_log, // update
264++ 1024*1024, 0, 1024*1024*1024, 1);
265++
266++static SYS_VAR* slow_log_in_memory_system_vars[]= {
267++ MYSQL_SYSVAR(max_memory),
268++ NULL,
269++};
270++
271++static uint slow_log_current_memory(MYSQL_THD thd, SHOW_VAR *var, char *buff)
272++{
273++ var->type= SHOW_INT;
274++ var->value= (char*)&global_slow_log_list->current_memory;
275++ return 0;
276++}
277++
278++/* plugin status variables */
279++static SHOW_VAR slow_log_in_memory_status_vars[]= {
280++ {"slow_log_current_memory",
281++ (char*) &slow_log_current_memory,
282++ SHOW_FUNC},
283++ {NULL, NULL, SHOW_LONG},
284++};
285++
286++
287++/*
288++ I_S_SLOW_LOG
289++*/
290++static struct st_mysql_information_schema i_s_slow_log=
291++{
292++ MYSQL_INFORMATION_SCHEMA_INTERFACE_VERSION
293++};
294++
295++static ST_FIELD_INFO i_s_slow_log_fields[] =
296++{
297++ {"EVENT_ID", 11, MYSQL_TYPE_LONGLONG, 0, 0, 0, SKIP_OPEN_TABLE},
298++ {"TIMESTAMP", 11, MYSQL_TYPE_LONGLONG, 0, 0, 0, SKIP_OPEN_TABLE},
299++ {"THREAD_ID", 11, MYSQL_TYPE_LONG, 0, 0, 0, SKIP_OPEN_TABLE},
300++ {"DB", NAME_CHAR_LEN, MYSQL_TYPE_STRING, 0, 1, 0, SKIP_OPEN_TABLE},
301++ {"INNODB_TRX_ID", 11, MYSQL_TYPE_LONGLONG, 0, 1, 0, SKIP_OPEN_TABLE},
302++ {"ERRNO", 11, MYSQL_TYPE_LONG, 0, 0, 0, SKIP_OPEN_TABLE},
303++ {"MS_QUERY_TIME", 11, MYSQL_TYPE_FLOAT, 0, 0, 0, SKIP_OPEN_TABLE},
304++
305++ {"QUERY", 255, MYSQL_TYPE_STRING, 0, 1, 0, SKIP_OPEN_TABLE},
306++ {0, 0, MYSQL_TYPE_STRING, 0, 0, 0, SKIP_OPEN_TABLE}
307++};
308++
309++
310++int i_s_fill_table_slow_log(THD* thd, TABLE_LIST* tables, COND* cond)
311++{
312++ if (!global_slow_log_list) return 0;
313++
314++ TABLE *table= tables->table;
315++
316++ mysql_mutex_lock(&global_slow_log_list->LOCK_slow_log_);
317++
318++ slow_log_t *item= global_slow_log_list->first;
319++ while (item)
320++ {
321++ restore_record(table, s->default_values);
322++
323++ table->field[0]->store(item->event_id, TRUE);
324++ table->field[1]->store(item->timestamp, TRUE);
325++ table->field[2]->store(item->thread_id, TRUE);
326++
327++ if (item->schema)
328++ {
329++ table->field[3]->store(item->schema, item->schema_len-1, system_charset_info);
330++ table->field[3]->set_notnull();
331++ }
332++
333++ if (item->innodb_trx_id)
334++ {
335++ table->field[4]->store(item->innodb_trx_id, TRUE);
336++ table->field[4]->set_notnull();
337++ }
338++
339++ table->field[5]->store(item->cmd_errno, TRUE);
340++ table->field[6]->store(item->time_of_query);
341++
342++ if (item->general_query)
343++ {
344++ table->field[7]->store(item->general_query, item->general_query_len-1, system_charset_info);
345++ table->field[7]->set_notnull();
346++ }
347++
348++ schema_table_store_record(thd, table);
349++ item= item->next;
350++ }
351++
352++ mysql_mutex_unlock(&global_slow_log_list->LOCK_slow_log_);
353++ return 0;
354++}
355++
356++
357++static int i_s_slow_log_plugin_init(void *arg __attribute__((unused)))
358++{
359++ ST_SCHEMA_TABLE* schema;
360++
361++ schema = (ST_SCHEMA_TABLE*) arg;
362++
363++ schema->fields_info = i_s_slow_log_fields;
364++ schema->fill_table = i_s_fill_table_slow_log;
365++ return 0;
366++}
367++
368++
369++static int i_s_slow_log_plugin_deinit(void *arg __attribute__((unused)))
370++{
371++ return(0);
372++}
373++
374++/*
375++ Plugin library descriptor
376++*/
377++
378++mysql_declare_plugin(slow_log_in_memory)
379++{
380++ MYSQL_AUDIT_PLUGIN, /* type */
381++ &slow_log_in_memory_descriptor, /* descriptor */
382++ "SLOW_LOG_IN_MEMORY_AUDIT", /* name */
383++ "Percona", /* author */
384++ "Error code histogram Audit", /* description */
385++ PLUGIN_LICENSE_GPL,
386++ slow_log_in_memory_plugin_init, /* init function (when loaded) */
387++ slow_log_in_memory_plugin_deinit, /* deinit function (when unloaded) */
388++ 0x0001, /* version */
389++ slow_log_in_memory_status_vars, /* status variables */
390++ slow_log_in_memory_system_vars, /* system variables */
391++ NULL,
392++ 0,
393++},
394++{
395++ MYSQL_INFORMATION_SCHEMA_PLUGIN, /* type */
396++ &i_s_slow_log, /* descriptor */
397++ "SLOW_LOG", /* name */
398++ "Percona", /* author */
399++ "latest slow log in memory", /* description */
400++ PLUGIN_LICENSE_GPL,
401++ i_s_slow_log_plugin_init, /* init function (when loaded) */
402++ i_s_slow_log_plugin_deinit, /* deinit function (when unloaded) */
403++ 0x0001, /* version */
404++ NULL, /* status variables */
405++ NULL, /* system variables */
406++ NULL,
407++ 0,
408++}
409++mysql_declare_plugin_end;
410++
411+--- a/plugin/slowlog_in_memory/ut_slow_log_list.h 1970-01-01 08:00:00.000000000 +0800
412++++ b/plugin/slowlog_in_memory/ut_slow_log_list.h 2011-12-22 21:09:34.000000000 +0800
413+@@ -0,0 +1,230 @@
414++#ifndef UT_SLOW_LOG_LIST_H
415++#define UT_SLOW_LOG_LIST_H
416++
417++#define MYSQL_SERVER
418++#include <mysql/plugin_audit.h>
419++#include "unireg.h"
420++#include "sql_show.h"
421++#include "sql_class.h"
422++
423++mysql_mutex_t LOCK_slow_event_id_;
424++
425++#ifdef HAVE_PSI_INTERFACE
426++PSI_mutex_key key_ss_mutex_LOCK_slow_log_;
427++PSI_mutex_key key_ss_mutex_LOCK_slow_event_id_;
428++
429++static PSI_mutex_info all_semisync_mutexes[]=
430++{
431++ {&key_ss_mutex_LOCK_slow_log_, "LOCK_slow_log_", 0},
432++ {&key_ss_mutex_LOCK_slow_event_id_, "LOCK_slow_event_id_", 0}
433++};
434++
435++static void init_semisync_psi_keys(void)
436++{
437++ const char* category= "semisync";
438++ int count;
439++
440++ if (PSI_server == NULL)
441++ return;
442++
443++ count= array_elements(all_semisync_mutexes);
444++ PSI_server->register_mutex(category, all_semisync_mutexes, count);
445++
446++}
447++#endif /* HAVE_PSI_INTERFACE */
448++
449++/* unique event id for each slow query */
450++ulonglong global_event_id= 0;
451++
452++const uint MAX_QUERY_LEN= 255;
453++
454++class slow_log_t
455++{
456++public:
457++ ulonglong event_id;
458++ ulonglong timestamp;
459++ ulong thread_id;
460++ char *schema;
461++ ulonglong innodb_trx_id;
462++ int cmd_errno;
463++ double time_of_query;
464++ char *general_query;
465++
466++ uint schema_len;
467++ uint general_query_len;
468++
469++ slow_log_t *next;
470++
471++ slow_log_t(ulonglong timestamp, ulong thread_id, const char *schema,
472++ ulonglong innodb_trx_id, int cmd_errno, double time_of_query, const char *general_query):next(NULL)
473++ {
474++ this->timestamp= timestamp;
475++ this->thread_id= thread_id;
476++
477++ if (schema)
478++ {
479++ this->schema_len= strlen(schema) + 1;
480++ this->schema= strndup(schema, this->schema_len);
481++ }
482++ else
483++ {
484++ this->schema= NULL;
485++ this->schema_len= 0;
486++ }
487++
488++ this->innodb_trx_id= innodb_trx_id;
489++ this->cmd_errno= cmd_errno;
490++ this->time_of_query= time_of_query;
491++
492++ if (general_query)
493++ {
494++ this->general_query_len= strlen(general_query) + 1;
495++
496++ if (this->general_query_len > MAX_QUERY_LEN)
497++ {
498++ this->general_query_len= MAX_QUERY_LEN;
499++ }
500++
501++ this->general_query= strndup(general_query, this->general_query_len);
502++ this->general_query[this->general_query_len-1]= '\0';
503++ }
504++ else
505++ {
506++ this->general_query= NULL;
507++ this->general_query_len= 0;
508++ }
509++
510++ this->real_size= sizeof(slow_log_t) + this->schema_len + this->general_query_len;
511++
512++ mysql_mutex_lock(&LOCK_slow_event_id_);
513++ this->event_id= ++global_event_id;
514++ mysql_mutex_unlock(&LOCK_slow_event_id_);
515++ }
516++
517++ ~slow_log_t()
518++ {
519++ if (schema)
520++ {
521++ free(schema);
522++ schema= NULL;
523++ }
524++
525++ if (general_query)
526++ {
527++ free(general_query);
528++ general_query= NULL;
529++ }
530++ }
531++
532++ uint size_of_instance()
533++ {
534++ return real_size;
535++ }
536++
537++ uint real_size;
538++};
539++
540++class slow_log_list
541++{
542++public:
543++ slow_log_t *first, *last;
544++ mysql_mutex_t LOCK_slow_log_;
545++
546++ uint current_memory;
547++
548++ void change_max_memory(uint new_len)
549++ {
550++ mysql_mutex_lock(&LOCK_slow_log_);
551++
552++ max_memory= new_len;
553++
554++ /* if the size is larger than current size, just change the value*/
555++ if (max_memory >= current_memory)
556++ {
557++ mysql_mutex_unlock(&LOCK_slow_log_);
558++ return;
559++ }
560++
561++ while (current_memory > max_memory)
562++ {
563++ pop_front();
564++ }
565++
566++ mysql_mutex_unlock(&LOCK_slow_log_);
567++ }
568++
569++ slow_log_list(uint max_memory)
570++ {
571++ first= NULL;
572++ last= NULL;
573++ current_memory= 0;
574++ this->max_memory= max_memory;
575++
576++ mysql_mutex_init(key_ss_mutex_LOCK_slow_log_,
577++ &LOCK_slow_log_, MY_MUTEX_INIT_FAST);
578++ }
579++
580++ ~slow_log_list()
581++ {
582++ mysql_mutex_lock(&LOCK_slow_log_);
583++ while (first)
584++ {
585++ pop_front();
586++ }
587++ mysql_mutex_unlock(&LOCK_slow_log_);
588++
589++ mysql_mutex_destroy(&LOCK_slow_log_);
590++ }
591++
592++ void push_back(slow_log_t * item)
593++ {
594++ mysql_mutex_lock(&LOCK_slow_log_);
595++
596++ uint size= item->size_of_instance();
597++
598++ if (size > max_memory)
599++ {
600++ sql_print_warning("the insert item size %u > %u discarded", size, max_memory);
601++ mysql_mutex_unlock(&LOCK_slow_log_);
602++ return;
603++ }
604++
605++ while (current_memory + size > max_memory)
606++ {
607++ pop_front();
608++ }
609++
610++ if (!first)
611++ {
612++ first= item;
613++ last= item;
614++ }
615++ else
616++ {
617++ last->next= item;
618++ last= item;
619++ }
620++
621++ current_memory+= size;
622++ mysql_mutex_unlock(&LOCK_slow_log_);
623++ }
624++
625++ /*functions call pop_front should have hold LOCK_slow_log_*/
626++ void pop_front()
627++ {
628++ if (!first) return;
629++
630++ slow_log_t *item= first;
631++ first= first->next;
632++
633++ if (!first) last= NULL;
634++
635++ current_memory-= item->size_of_instance();
636++ delete item;
637++ }
638++
639++private:
640++ uint max_memory;
641++};
642++#endif
643++
644+--- a/mysql-test/include/have_slog_log_in_memory_audit_plugin.inc 1970-01-01 08:00:00.000000000 +0800
645++++ b/mysql-test/include/have_slog_log_in_memory_audit_plugin.inc 2011-12-22 21:08:28.000000000 +0800
646+@@ -0,0 +1,21 @@
647++#
648++# Check if server has support for loading plugins
649++#
650++if (`SELECT @@have_dynamic_loading != 'YES'`) {
651++ --skip Requires dynamic loading
652++}
653++
654++#
655++# Check if the variable SLOW_LOG_IN_MEMORY_AUDIT is set
656++#
657++if (!$SLOW_LOG_IN_MEMORY_AUDIT)
658++{
659++ skip Need slow_log_in_memory plugins;
660++}
661++
662++#
663++# Check if --plugin-dir was setup for slow_log_in_memory
664++#
665++if (`SELECT CONCAT('--plugin-dir=', @@plugin_dir) != '$SLOW_LOG_IN_MEMORY_AUDIT_OPT'`) {
666++ --skip SLOW_LOG plugin requires that --plugin-dir is set to the slow_log_in_memory plugin dir (either the .opt file does not contain \$SLOW_LOG_IN_MEMORY_AUDIT_OPT or another plugin is in use)
667++}
668+--- a/mysql-test/include/plugin.defs 2011-12-19 14:44:49.000000000 +0800
669++++ b/mysql-test/include/plugin.defs 2011-12-22 21:08:28.000000000 +0800
670+@@ -40,3 +40,5 @@
671+ ha_federated storage/federated FEDERATED_PLUGIN
672+ mypluglib plugin/fulltext SIMPLE_PARSER
673+ libdaemon_example plugin/daemon_example DAEMONEXAMPLE
674++slowlog_in_memory plugin/slowlog_in_memory SLOW_LOG
675++slowlog_in_memory plugin/slowlog_in_memory SLOW_LOG_IN_MEMORY_AUDIT
676+--- a/mysql-test/r/slow_log_in_memory.result 1970-01-01 08:00:00.000000000 +0800
677++++ b/mysql-test/r/slow_log_in_memory.result 2011-12-22 21:10:53.000000000 +0800
678+@@ -0,0 +1,69 @@
679++#
680++# feature: slow log show in information_schema.slow_log
681++#
682++install plugin SLOW_LOG_IN_MEMORY_AUDIT soname 'slowlog_in_memory.so';
683++install plugin SLOW_LOG soname 'slowlog_in_memory.so';
684++show variables like 'slow_log_in_memory_audit_max_memory';
685++Variable_name Value
686++slow_log_in_memory_audit_max_memory 1048576
687++SET long_query_time=2;
688++SET query_exec_time=2.123456;
689++select 1;
690++1
691++1
692++SET query_exec_time=0;
693++SET long_query_time=2;
694++SET query_exec_time=2.1;
695++select 1;
696++1
697++1
698++SET query_exec_time=0;
699++SET long_query_time=2;
700++SET query_exec_time=2.1;
701++select 1;
702++1
703++1
704++SET query_exec_time=0;
705++show global status like 'slow_log_current_memory';
706++Variable_name Value
707++slow_log_current_memory XX
708++select * from information_schema.slow_log;
709++EVENT_ID TIMESTAMP THREAD_ID DB INNODB_TRX_ID ERRNO MS_QUERY_TIME QUERY
710++1 XX XX test XX 0 2.123456 select 1
711++2 XX XX test XX 0 2.1 select 1
712++3 XX XX test XX 0 2.1 select 1
713++# decrease max_memory and wash eldest
714++set global slow_log_in_memory_audit_max_memory=240;
715++use information_schema;
716++SET long_query_time=2;
717++SET query_exec_time=2.1;
718++select 1;
719++1
720++1
721++SET query_exec_time=0;
722++show global status like 'slow_log_current_memory';
723++Variable_name Value
724++slow_log_current_memory XX
725++select * from information_schema.slow_log;
726++EVENT_ID TIMESTAMP THREAD_ID DB INNODB_TRX_ID ERRNO MS_QUERY_TIME QUERY
727++3 XX XX test XX 0 2.1 select 1
728++4 XX XX information_schema XX 0 2.1 select 1
729++# set to zero to disable audit
730++set global slow_log_in_memory_audit_max_memory=0;
731++SET long_query_time=2;
732++SET query_exec_time=2.1;
733++select 1;
734++1
735++1
736++SET query_exec_time=0;
737++show global status like 'slow_log_current_memory';
738++Variable_name Value
739++slow_log_current_memory 0
740++select * from information_schema.slow_log;
741++EVENT_ID TIMESTAMP THREAD_ID DB INNODB_TRX_ID ERRNO MS_QUERY_TIME QUERY
742++uninstall plugin SLOW_LOG;
743++uninstall plugin SLOW_LOG_IN_MEMORY_AUDIT;
744++Warnings:
745++Warning 1620 Plugin is busy and will be uninstalled on shutdown
746++SET SESSION query_exec_time=default;
747++SET long_query_time=default;
748+--- a/mysql-test/suite/sys_vars/r/slow_log_in_memory_audit.result 1970-01-01 08:00:00.000000000 +0800
749++++ b/mysql-test/suite/sys_vars/r/slow_log_in_memory_audit.result 2011-12-22 21:08:28.000000000 +0800
750+@@ -0,0 +1,31 @@
751++install plugin SLOW_LOG_IN_MEMORY_AUDIT soname 'slowlog_in_memory.so';
752++install plugin SLOW_LOG soname 'slowlog_in_memory.so';
753++select @@global.slow_log_in_memory_audit_max_memory;
754++@@global.slow_log_in_memory_audit_max_memory
755++1048576
756++show global variables like 'slow_log_in_memory_audit_max_memory';
757++Variable_name Value
758++slow_log_in_memory_audit_max_memory 1048576
759++select * from information_schema.global_variables where variable_name='slow_log_in_memory_audit_max_memory';
760++VARIABLE_NAME VARIABLE_VALUE
761++SLOW_LOG_IN_MEMORY_AUDIT_MAX_MEMORY 1048576
762++set global slow_log_in_memory_audit_max_memory=2097152;
763++select @@global.slow_log_in_memory_audit_max_memory;
764++@@global.slow_log_in_memory_audit_max_memory
765++2097152
766++show global variables like 'slow_log_in_memory_audit_max_memory';
767++Variable_name Value
768++slow_log_in_memory_audit_max_memory 2097152
769++set global slow_log_in_memory_audit_max_memory=1.1;
770++ERROR 42000: Incorrect argument type to variable 'slow_log_in_memory_audit_max_memory'
771++set global slow_log_in_memory_audit_max_memory=1e1;
772++ERROR 42000: Incorrect argument type to variable 'slow_log_in_memory_audit_max_memory'
773++set global slow_log_in_memory_audit_max_memory="some text";
774++ERROR 42000: Incorrect argument type to variable 'slow_log_in_memory_audit_max_memory'
775++select @@global.slow_log_in_memory_audit_max_memory;
776++@@global.slow_log_in_memory_audit_max_memory
777++2097152
778++UNINSTALL PLUGIN SLOW_LOG;
779++UNINSTALL PLUGIN SLOW_LOG_IN_MEMORY_AUDIT;
780++Warnings:
781++Warning 1620 Plugin is busy and will be uninstalled on shutdown
782+--- a/mysql-test/suite/sys_vars/t/slow_log_in_memory_audit-master.opt 1970-01-01 08:00:00.000000000 +0800
783++++ b/mysql-test/suite/sys_vars/t/slow_log_in_memory_audit-master.opt 2011-12-22 21:08:28.000000000 +0800
784+@@ -0,0 +1 @@
785++$SLOW_LOG_IN_MEMORY_AUDIT_OPT
786+--- a/mysql-test/suite/sys_vars/t/slow_log_in_memory_audit.test 1970-01-01 08:00:00.000000000 +0800
787++++ b/mysql-test/suite/sys_vars/t/slow_log_in_memory_audit.test 2011-12-22 21:08:28.000000000 +0800
788+@@ -0,0 +1,40 @@
789++
790++#
791++# exists as a global only
792++#
793++source include/not_embedded.inc;
794++source include/have_slog_log_in_memory_audit_plugin.inc;
795++# The following is to prevent a mis-match on windows that has the name of of the lib ending with 'dll'
796++--replace_regex /\.dll/.so/
797++install plugin SLOW_LOG_IN_MEMORY_AUDIT soname 'slowlog_in_memory.so';
798++install plugin SLOW_LOG soname 'slowlog_in_memory.so';
799++select @@global.slow_log_in_memory_audit_max_memory;
800++
801++show global variables like 'slow_log_in_memory_audit_max_memory';
802++select * from information_schema.global_variables where variable_name='slow_log_in_memory_audit_max_memory';
803++
804++#
805++# show that it's writable
806++#
807++set global slow_log_in_memory_audit_max_memory=2097152;
808++select @@global.slow_log_in_memory_audit_max_memory;
809++show global variables like 'slow_log_in_memory_audit_max_memory';
810++
811++#
812++# incorrect types
813++#
814++--error ER_WRONG_TYPE_FOR_VAR
815++set global slow_log_in_memory_audit_max_memory=1.1;
816++--error ER_WRONG_TYPE_FOR_VAR
817++set global slow_log_in_memory_audit_max_memory=1e1;
818++--error ER_WRONG_TYPE_FOR_VAR
819++set global slow_log_in_memory_audit_max_memory="some text";
820++
821++
822++#
823++# Cleanup
824++#
825++select @@global.slow_log_in_memory_audit_max_memory;
826++UNINSTALL PLUGIN SLOW_LOG;
827++UNINSTALL PLUGIN SLOW_LOG_IN_MEMORY_AUDIT;
828++
829+--- a/mysql-test/t/slow_log_in_memory-master.opt 1970-01-01 08:00:00.000000000 +0800
830++++ b/mysql-test/t/slow_log_in_memory-master.opt 2011-12-22 21:08:28.000000000 +0800
831+@@ -0,0 +1 @@
832++$SLOW_LOG_IN_MEMORY_AUDIT_OPT
833+--- a/mysql-test/t/slow_log_in_memory.test 1970-01-01 08:00:00.000000000 +0800
834++++ b/mysql-test/t/slow_log_in_memory.test 2011-12-22 21:10:45.000000000 +0800
835+@@ -0,0 +1,61 @@
836++--source include/have_debug.inc
837++--source include/have_slog_log_in_memory_audit_plugin.inc
838++
839++--echo #
840++--echo # feature: slow log show in information_schema.slow_log
841++--echo #
842++
843++install plugin SLOW_LOG_IN_MEMORY_AUDIT soname 'slowlog_in_memory.so';
844++install plugin SLOW_LOG soname 'slowlog_in_memory.so';
845++show variables like 'slow_log_in_memory_audit_max_memory';
846++
847++SET long_query_time=2;
848++SET query_exec_time=2.123456;
849++select 1;
850++SET query_exec_time=0;
851++
852++connect (con1,localhost,root,,);
853++
854++SET long_query_time=2;
855++SET query_exec_time=2.1;
856++select 1;
857++SET query_exec_time=0;
858++
859++connect (con2,localhost,root,,);
860++
861++SET long_query_time=2;
862++SET query_exec_time=2.1;
863++select 1;
864++SET query_exec_time=0;
865++--replace_column 2 XX
866++show global status like 'slow_log_current_memory';
867++--replace_column 2 XX 3 XX 5 XX
868++select * from information_schema.slow_log;
869++
870++--echo # decrease max_memory and wash eldest
871++set global slow_log_in_memory_audit_max_memory=240;
872++connection con1;
873++use information_schema;
874++SET long_query_time=2;
875++SET query_exec_time=2.1;
876++select 1;
877++SET query_exec_time=0;
878++--replace_column 2 XX
879++show global status like 'slow_log_current_memory';
880++--replace_column 2 XX 3 XX 5 XX
881++select * from information_schema.slow_log;
882++
883++--echo # set to zero to disable audit
884++connection con1;
885++set global slow_log_in_memory_audit_max_memory=0;
886++SET long_query_time=2;
887++SET query_exec_time=2.1;
888++select 1;
889++SET query_exec_time=0;
890++show global status like 'slow_log_current_memory';
891++select * from information_schema.slow_log;
892++
893++uninstall plugin SLOW_LOG;
894++uninstall plugin SLOW_LOG_IN_MEMORY_AUDIT;
895++SET SESSION query_exec_time=default;
896++SET long_query_time=default;

Subscribers

People subscribed via source and target branches