MDEV-4568 - Port Percona response time distribution as audit plugin

sql/sp_head.cc:
  Trigger MYSQL_AUDIT_GENERAL_STATUS event for each statement in stored
  procedures. Not strictly needed for query_response_time plugin, but
  makes it behave more like Percona patch.

mysql-test/mysql-test-run.pl

@@ -377,7 +377,7 @@ sub main {
   # directly before it executes them, like "make test-force-pl" in RPM builds.
   mtr_report("Logging: $0 ", join(" ", @ARGV));
 
-  $DEFAULT_SUITES.=",sequence,sql_discovery" if $source_dist;
+  $DEFAULT_SUITES.=",sequence,sql_discovery,query_response_time" if $source_dist;
 
   command_line_setup();
 

plugin/query_response_time/CMakeLists.txt

+ADD_DEFINITIONS(-DHAVE_RESPONSE_TIME_DISTRIBUTION)
+MYSQL_ADD_PLUGIN(QUERY_RESPONSE_TIME query_response_time.cc query_response_time.h plugin.cc)

plugin/query_response_time/mysql-test/query_response_time/basic.result

+SHOW VARIABLES WHERE VARIABLE_NAME LIKE 'query_response_time%' AND VARIABLE_NAME!='query_response_time_exec_time_debug';
+Variable_name	Value
+query_response_time_flush	OFF
+query_response_time_range_base	10
+query_response_time_stats	OFF
+SHOW CREATE TABLE INFORMATION_SCHEMA.QUERY_RESPONSE_TIME;
+Table	Create Table
+QUERY_RESPONSE_TIME	CREATE TEMPORARY TABLE `QUERY_RESPONSE_TIME` (
+  `TIME` varchar(14) NOT NULL DEFAULT '',
+  `COUNT` int(11) unsigned NOT NULL DEFAULT '0',
+  `TOTAL` varchar(14) NOT NULL DEFAULT ''
+) ENGINE=MEMORY DEFAULT CHARSET=utf8
+SELECT * FROM INFORMATION_SCHEMA.PLUGINS WHERE PLUGIN_NAME LIKE 'query_response_time%';;
+PLUGIN_NAME	QUERY_RESPONSE_TIME
+PLUGIN_VERSION	1.0
+PLUGIN_STATUS	ACTIVE
+PLUGIN_TYPE	INFORMATION SCHEMA
+PLUGIN_TYPE_VERSION	100002.0
+PLUGIN_LIBRARY	QUERY_RESPONSE_TIME_SO
+PLUGIN_LIBRARY_VERSION	1.4
+PLUGIN_AUTHOR	Percona and Sergey Vojtovich
+PLUGIN_DESCRIPTION	Query Response Time Distribution INFORMATION_SCHEMA Plugin
+PLUGIN_LICENSE	GPL
+LOAD_OPTION	ON
+PLUGIN_MATURITY	Alpha
+PLUGIN_AUTH_VERSION	1.0
+PLUGIN_NAME	QUERY_RESPONSE_TIME_AUDIT
+PLUGIN_VERSION	1.0
+PLUGIN_STATUS	ACTIVE
+PLUGIN_TYPE	AUDIT
+PLUGIN_TYPE_VERSION	3.0
+PLUGIN_LIBRARY	QUERY_RESPONSE_TIME_SO
+PLUGIN_LIBRARY_VERSION	1.4
+PLUGIN_AUTHOR	Percona and Sergey Vojtovich
+PLUGIN_DESCRIPTION	Query Response Time Distribution Audit Plugin
+PLUGIN_LICENSE	GPL
+LOAD_OPTION	ON
+PLUGIN_MATURITY	Alpha
+PLUGIN_AUTH_VERSION	1.0

plugin/query_response_time/mysql-test/query_response_time/basic.test

+SHOW VARIABLES WHERE VARIABLE_NAME LIKE 'query_response_time%' AND VARIABLE_NAME!='query_response_time_exec_time_debug';
+SHOW CREATE TABLE INFORMATION_SCHEMA.QUERY_RESPONSE_TIME;
+--replace_result $QUERY_RESPONSE_TIME_SO QUERY_RESPONSE_TIME_SO
+--query_vertical SELECT * FROM INFORMATION_SCHEMA.PLUGINS WHERE PLUGIN_NAME LIKE 'query_response_time%';

plugin/query_response_time/mysql-test/query_response_time/query_response_time-stored.inc

+SET SESSION query_response_time_exec_time_debug=100000;
+
+SET GLOBAL QUERY_RESPONSE_TIME_STATS=0;
+EVAL SET GLOBAL QUERY_RESPONSE_TIME_RANGE_BASE=$base;
+SET GLOBAL query_response_time_flush=1;
+SET GLOBAL QUERY_RESPONSE_TIME_STATS=1;
+
+CALL test_f(310000);
+CALL test_f(320000);
+CALL test_f(330000);
+CALL test_f(340000);
+CALL test_f(350000);
+CALL test_f(360000);
+CALL test_f(370000);
+CALL test_f(380000);
+CALL test_f(390000);
+CALL test_f(400000);
+CALL test_f(1100000);
+CALL test_f(1200000);
+CALL test_f(1300000);
+CALL test_f(1500000);
+CALL test_f(1400000);
+CALL test_f(500000);
+CALL test_f(2100000);
+CALL test_f(2300000);
+CALL test_f(2500000);
+CALL test_f(3100000);
+CALL test_f(4100000);
+CALL test_f(5100000);
+
+SET GLOBAL QUERY_RESPONSE_TIME_STATS=0;
+
+SHOW GLOBAL VARIABLES where Variable_name like 'QUERY_RESPONSE_TIME_RANGE_BASE';
+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME;
+
+SET SESSION query_response_time_exec_time_debug=default;

plugin/query_response_time/mysql-test/query_response_time/query_response_time-stored.test

+--source include/have_debug.inc
+
+CREATE TABLE t(a INT);
+
+delimiter ^;
+CREATE PROCEDURE test_f(t INT)
+BEGIN
+  SET SESSION query_response_time_exec_time_debug=t;
+  INSERT INTO t VALUES(1);
+  SET SESSION query_response_time_exec_time_debug=100000;
+  DELETE FROM t;
+END^
+delimiter ;^
+
+--let base=1
+--source query_response_time-stored.inc
+--let base=2
+--source query_response_time-stored.inc
+--let base=10
+--source query_response_time-stored.inc
+--let base=7
+--source query_response_time-stored.inc
+--let base=156
+--source query_response_time-stored.inc
+--let base=1000
+--source query_response_time-stored.inc
+--let base=1001
+--source query_response_time-stored.inc
+
+SET GLOBAL QUERY_RESPONSE_TIME_RANGE_BASE=default;
+SET GLOBAL QUERY_RESPONSE_TIME_STATS=default;
+
+DROP PROCEDURE test_f;
+
+DROP TABLE t;

plugin/query_response_time/mysql-test/query_response_time/query_response_time.inc

+SET SESSION query_response_time_exec_time_debug=100000;
+
+SET GLOBAL QUERY_RESPONSE_TIME_STATS=0;
+EVAL SET GLOBAL QUERY_RESPONSE_TIME_RANGE_BASE=$base;
+SET GLOBAL query_response_time_flush=1;
+# Following two queries check works of FLUSH and 
+# respecting of "QUERY_RESPONSE_TIME_STATS" variable (see launchpad bug #855312)
+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME;
+SET GLOBAL QUERY_RESPONSE_TIME_STATS=1;
+
+SET SESSION query_response_time_exec_time_debug=310000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=320000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=330000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=340000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=350000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=360000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=370000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=380000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=390000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=400000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=1100000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=1200000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=1300000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=1500000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=1400000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=500000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=2100000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=2300000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=2500000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=3100000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=4100000; SELECT 1;
+SET SESSION query_response_time_exec_time_debug=5100000; SELECT 1;
+
+SET SESSION query_response_time_exec_time_debug=100000;
+
+SET GLOBAL QUERY_RESPONSE_TIME_STATS=0;
+
+SHOW GLOBAL VARIABLES where Variable_name like 'QUERY_RESPONSE_TIME_RANGE_BASE';
+SELECT * FROM INFORMATION_SCHEMA.QUERY_RESPONSE_TIME;
+
+SET SESSION query_response_time_exec_time_debug=default;

plugin/query_response_time/mysql-test/query_response_time/query_response_time.test

+--source include/have_debug.inc
+
+--let base=1
+--source query_response_time.inc
+--let base=2
+--source query_response_time.inc
+--let base=10
+--source query_response_time.inc
+--let base=7
+--source query_response_time.inc
+--let base=156
+--source query_response_time.inc
+--let base=1000
+--source query_response_time.inc
+--let base=1001
+--source query_response_time.inc
+
+SET GLOBAL QUERY_RESPONSE_TIME_RANGE_BASE=default;
+SET GLOBAL QUERY_RESPONSE_TIME_STATS=default;

plugin/query_response_time/mysql-test/query_response_time/suite.opt

+--plugin-load-add=$QUERY_RESPONSE_TIME_SO --plugin-query-response-time=ON --plugin-query-response-time-audit=ON

plugin/query_response_time/mysql-test/query_response_time/suite.pm

+package My::Suite::Query_response_time;
+
+@ISA = qw(My::Suite);
+
+return "No QUERY_RESPONSE_TIME plugin" unless
+  $ENV{QUERY_RESPONSE_TIME_SO} or
+  $::mysqld_variables{'query_response_time'} eq "ON";
+
+return "Not run for embedded server" if $::opt_embedded_server;
+
+bless { };
+

plugin/query_response_time/plugin.cc

+/* Copyright (C) 2013 Percona and Sergey Vojtovich
+
+   This program is free software; you can redistribute it and/or modify
+   it under the terms of the GNU General Public License as published by
+   the Free Software Foundation; version 2 of the License.
+
+   This program is distributed in the hope that it will be useful,
+   but WITHOUT ANY WARRANTY; without even the implied warranty of
+   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+   GNU General Public License for more details.
+
+   You should have received a copy of the GNU General Public License
+   along with this program; if not, write to the Free Software
+   Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA */
+
+#define MYSQL_SERVER
+#include <sql_class.h>
+#include <table.h>
+#include <sql_show.h>
+#include <mysql/plugin_audit.h>
+#include "query_response_time.h"
+
+
+ulong opt_query_response_time_range_base= QRT_DEFAULT_BASE;
+my_bool opt_query_response_time_stats= 0;
+static my_bool opt_query_response_time_flush= 0;
+
+
+static void query_response_time_flush_update(
+              MYSQL_THD thd __attribute__((unused)),
+              struct st_mysql_sys_var *var __attribute__((unused)),
+              void *tgt __attribute__((unused)),
+              const void *save __attribute__((unused)))
+{
+  query_response_time_flush();
+}
+
+
+static MYSQL_SYSVAR_ULONG(range_base, opt_query_response_time_range_base,
+       PLUGIN_VAR_RQCMDARG,
+       "Select base of log for query_response_time ranges. WARNING: variable "
+       "change affect only after flush",
+       NULL, NULL, QRT_DEFAULT_BASE, 2, QRT_MAXIMUM_BASE, 1);
+static MYSQL_SYSVAR_BOOL(stats, opt_query_response_time_stats,
+       PLUGIN_VAR_OPCMDARG,
+       "Enable or disable query response time statisics collecting",
+       NULL, NULL, FALSE);
+static MYSQL_SYSVAR_BOOL(flush, opt_query_response_time_flush,
+       PLUGIN_VAR_NOCMDOPT,
+       "Update of this variable flushes statistics and re-reads "
+       "query_response_time_range_base",
+       NULL, query_response_time_flush_update, FALSE);
+#ifndef DBUG_OFF
+static MYSQL_THDVAR_ULONGLONG(exec_time_debug, PLUGIN_VAR_NOCMDOPT,
+       "Pretend queries take this many microseconds. When 0 (the default) use "
+       "the actual execution time. Used only for debugging.",
+       NULL, NULL, 0, 0, LONG_TIMEOUT, 1);
+#endif
+
+
+static struct st_mysql_sys_var *query_response_time_info_vars[]=
+{
+  MYSQL_SYSVAR(range_base),
+  MYSQL_SYSVAR(stats),
+  MYSQL_SYSVAR(flush),
+#ifndef DBUG_OFF
+  MYSQL_SYSVAR(exec_time_debug),
+#endif
+  NULL
+};
+
+
+ST_FIELD_INFO query_response_time_fields_info[] =
+{
+  { "TIME",  QRT_TIME_STRING_LENGTH,      MYSQL_TYPE_STRING,  0, 0,               "", SKIP_OPEN_TABLE },
+  { "COUNT", MY_INT32_NUM_DECIMAL_DIGITS, MYSQL_TYPE_LONG,    0, MY_I_S_UNSIGNED, "", SKIP_OPEN_TABLE },
+  { "TOTAL", QRT_TIME_STRING_LENGTH,      MYSQL_TYPE_STRING,  0, 0,               "", SKIP_OPEN_TABLE },
+  { 0, 0, MYSQL_TYPE_NULL, 0, 0, 0, 0 }
+};
+
+
+static int query_response_time_info_init(void *p)
+{
+  ST_SCHEMA_TABLE *i_s_query_response_time= (ST_SCHEMA_TABLE *) p;
+  i_s_query_response_time->fields_info= query_response_time_fields_info;
+  i_s_query_response_time->fill_table= query_response_time_fill;
+  query_response_time_init();
+  return 0;
+}
+
+
+static int query_response_time_info_deinit(void *arg __attribute__((unused)))
+{
+  opt_query_response_time_stats= 0;
+  query_response_time_free();
+  return 0;
+}
+
+
+static struct st_mysql_information_schema query_response_time_info_descriptor=
+{ MYSQL_INFORMATION_SCHEMA_INTERFACE_VERSION };
+
+
+static void query_response_time_audit_notify(MYSQL_THD thd,
+                                             unsigned int event_class,
+                                             const void *event)
+{
+  const struct mysql_event_general *event_general=
+    (const struct mysql_event_general *) event;
+  DBUG_ASSERT(event_class == MYSQL_AUDIT_GENERAL_CLASS);
+  if (event_general->event_subclass == MYSQL_AUDIT_GENERAL_STATUS &&
+      opt_query_response_time_stats)
+  {
+#ifndef DBUG_OFF
+    if (THDVAR(thd, exec_time_debug))
+      query_response_time_collect(thd->lex->sql_command != SQLCOM_SET_OPTION ?
+                                  THDVAR(thd, exec_time_debug) : 0);
+    else
+#endif
+    query_response_time_collect(thd->utime_after_query - thd->utime_after_lock);
+  }
+}
+
+
+static struct st_mysql_audit query_response_time_audit_descriptor=
+{
+  MYSQL_AUDIT_INTERFACE_VERSION, NULL, query_response_time_audit_notify,
+  { (unsigned long) MYSQL_AUDIT_GENERAL_CLASSMASK }
+};
+
+
+maria_declare_plugin(query_response_time)
+{
+  MYSQL_INFORMATION_SCHEMA_PLUGIN,
+  &query_response_time_info_descriptor,
+  "QUERY_RESPONSE_TIME",
+  "Percona and Sergey Vojtovich",
+  "Query Response Time Distribution INFORMATION_SCHEMA Plugin",
+  PLUGIN_LICENSE_GPL,
+  query_response_time_info_init,
+  query_response_time_info_deinit,
+  0x0100,
+  NULL,
+  query_response_time_info_vars,
+  "1.0",
+  MariaDB_PLUGIN_MATURITY_ALPHA
+},
+{
+  MYSQL_AUDIT_PLUGIN,
+  &query_response_time_audit_descriptor,
+  "QUERY_RESPONSE_TIME_AUDIT",
+  "Percona and Sergey Vojtovich",
+  "Query Response Time Distribution Audit Plugin",
+  PLUGIN_LICENSE_GPL,
+  NULL,
+  NULL,
+  0x0100,
+  NULL,
+  NULL,
+  "1.0",
+  MariaDB_PLUGIN_MATURITY_ALPHA
+}
+maria_declare_plugin_end;

plugin/query_response_time/query_response_time.cc

+#include "mysql_version.h"
+#include "my_global.h"
+#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION
+#include "mysql_com.h"
+#include "rpl_tblmap.h"
+#include "table.h"
+#include "field.h"
+#include "sql_show.h"
+#include "query_response_time.h"
+
+#define TIME_STRING_POSITIVE_POWER_LENGTH QRT_TIME_STRING_POSITIVE_POWER_LENGTH
+#define TIME_STRING_NEGATIVE_POWER_LENGTH 6
+#define TOTAL_STRING_POSITIVE_POWER_LENGTH QRT_TOTAL_STRING_POSITIVE_POWER_LENGTH
+#define TOTAL_STRING_NEGATIVE_POWER_LENGTH 6
+#define MINIMUM_BASE 2
+#define MAXIMUM_BASE QRT_MAXIMUM_BASE
+#define POSITIVE_POWER_FILLER QRT_POSITIVE_POWER_FILLER
+#define NEGATIVE_POWER_FILLER QRT_NEGATIVE_POWER_FILLER
+#define TIME_OVERFLOW   QRT_TIME_OVERFLOW
+#define DEFAULT_BASE    QRT_DEFAULT_BASE
+
+#define do_xstr(s) do_str(s)
+#define do_str(s) #s
+#define do_format(filler,width) "%" filler width "lld"
+/*
+  Format strings for snprintf. Generate from:
+  POSITIVE_POWER_FILLER and TIME_STRING_POSITIVE_POWER_LENGTH
+  NEFATIVE_POWER_FILLER and TIME_STRING_NEGATIVE_POWER_LENGTH
+*/
+#define TIME_STRING_POSITIVE_POWER_FORMAT do_format(POSITIVE_POWER_FILLER,do_xstr(TIME_STRING_POSITIVE_POWER_LENGTH))
+#define TIME_STRING_NEGATIVE_POWER_FORMAT do_format(NEGATIVE_POWER_FILLER,do_xstr(TIME_STRING_NEGATIVE_POWER_LENGTH))
+#define TIME_STRING_FORMAT		      TIME_STRING_POSITIVE_POWER_FORMAT "." TIME_STRING_NEGATIVE_POWER_FORMAT
+
+#define TOTAL_STRING_POSITIVE_POWER_FORMAT do_format(POSITIVE_POWER_FILLER,do_xstr(TOTAL_STRING_POSITIVE_POWER_LENGTH))
+#define TOTAL_STRING_NEGATIVE_POWER_FORMAT do_format(NEGATIVE_POWER_FILLER,do_xstr(TOTAL_STRING_NEGATIVE_POWER_LENGTH))
+#define TOTAL_STRING_FORMAT		      TOTAL_STRING_POSITIVE_POWER_FORMAT "." TOTAL_STRING_NEGATIVE_POWER_FORMAT
+
+#define TIME_STRING_LENGTH	QRT_TIME_STRING_LENGTH
+#define TIME_STRING_BUFFER_LENGTH	(TIME_STRING_LENGTH + 1 /* '\0' */)
+
+#define TOTAL_STRING_LENGTH	QRT_TOTAL_STRING_LENGTH
+#define TOTAL_STRING_BUFFER_LENGTH	(TOTAL_STRING_LENGTH + 1 /* '\0' */)
+
+/*
+  Calculate length of "log linear"
+  1)
+  (MINIMUM_BASE ^ result) <= (10 ^ STRING_POWER_LENGTH) < (MINIMUM_BASE ^ (result + 1))
+
+  2)
+  (MINIMUM_BASE ^ result) <= (10 ^ STRING_POWER_LENGTH)
+  and
+  (MINIMUM_BASE ^ (result + 1)) > (10 ^ STRING_POWER_LENGTH)
+
+  3)
+  result     <= LOG(MINIMUM_BASE, 10 ^ STRING_POWER_LENGTH)= STRING_POWER_LENGTH * LOG(MINIMUM_BASE,10)
+  result + 1 >  LOG(MINIMUM_BASE, 10 ^ STRING_POWER_LENGTH)= STRING_POWER_LENGTH * LOG(MINIMUM_BASE,10)
+
+  4) STRING_POWER_LENGTH * LOG(MINIMUM_BASE,10) - 1 < result <= STRING_POWER_LENGTH * LOG(MINIMUM_BASE,10)
+
+  MINIMUM_BASE= 2 always, LOG(MINIMUM_BASE,10)= 3.3219280948873626, result= (int)3.3219280948873626 * STRING_POWER_LENGTH
+
+  Last counter always use for time overflow
+*/
+#define POSITIVE_POWER_COUNT ((int)(3.32192809 * TIME_STRING_POSITIVE_POWER_LENGTH))
+#define NEGATIVE_POWER_COUNT ((int)(3.32192809 * TIME_STRING_NEGATIVE_POWER_LENGTH))
+#define OVERALL_POWER_COUNT (NEGATIVE_POWER_COUNT + 1 + POSITIVE_POWER_COUNT)
+
+#define MILLION ((unsigned long)1000 * 1000)
+
+namespace query_response_time
+{
+
+class utility
+{
+public:
+  utility() : m_base(0)
+  {
+    m_max_dec_value= MILLION;
+    for(int i= 0; TIME_STRING_POSITIVE_POWER_LENGTH > i; ++i)
+      m_max_dec_value *= 10;
+    setup(DEFAULT_BASE);
+  }
+public:
+  uint      base()            const { return m_base; }
+  uint      negative_count()  const { return m_negative_count; }
+  uint      positive_count()  const { return m_positive_count; }
+  uint      bound_count()     const { return m_bound_count; }
+  ulonglong max_dec_value()   const { return m_max_dec_value; }
+  ulonglong bound(uint index) const { return m_bound[ index ]; }
+public:
+  void setup(uint base)
+  {
+    if(base != m_base)
+    {
+      m_base= base;
+
+      const ulonglong million= 1000 * 1000;
+      ulonglong value= million;
+      m_negative_count= 0;
+      while(value > 0)
+      {
+	m_negative_count += 1;
+	value /= m_base;
+      }
+      m_negative_count -= 1;
+
+      value= million;
+      m_positive_count= 0;
+      while(value < m_max_dec_value)
+      {
+	m_positive_count += 1;
+	value *= m_base;
+      }
+      m_bound_count= m_negative_count + m_positive_count;
+
+      value= million;
+      for(uint i= 0; i < m_negative_count; ++i)
+      {
+	value /= m_base;
+	m_bound[m_negative_count - i - 1]= value;
+      }
+      value= million;
+      for(uint i= 0; i < m_positive_count;  ++i)
+      {
+	m_bound[m_negative_count + i]= value;
+	value *= m_base;
+      }
+    }
+  }
+private:
+  uint      m_base;
+  uint      m_negative_count;
+  uint      m_positive_count;
+  uint      m_bound_count;
+  ulonglong m_max_dec_value; /* for TIME_STRING_POSITIVE_POWER_LENGTH=7 is 10000000 */
+  ulonglong m_bound[OVERALL_POWER_COUNT];
+};
+
+static
+void print_time(char* buffer, std::size_t buffer_size, const char* format,
+                uint64 value)
+{
+  ulonglong second=      (value / MILLION);
+  ulonglong microsecond= (value % MILLION);
+  my_snprintf(buffer, buffer_size, format, second, microsecond);
+}
+
+class time_collector
+{
+public:
+  time_collector(utility& u) : m_utility(&u)
+  {
+    my_atomic_rwlock_init(&time_collector_lock);
+  }
+  ~time_collector()
+  {
+    my_atomic_rwlock_destroy(&time_collector_lock);
+  }
+  uint32 count(uint index) const
+  {
+    my_atomic_rwlock_rdlock(&time_collector_lock);
+    uint32 result= my_atomic_load32((int32*)&m_count[index]);
+    my_atomic_rwlock_rdunlock(&time_collector_lock);
+    return result;
+  }
+  uint64 total(uint index) const
+  {
+    my_atomic_rwlock_rdlock(&time_collector_lock);
+    uint64 result= my_atomic_load64((int64*)&m_total[index]);
+    my_atomic_rwlock_rdunlock(&time_collector_lock);
+    return result;
+  }
+public:
+  void flush()
+  {
+    my_atomic_rwlock_wrlock(&time_collector_lock);
+    memset((void*)&m_count,0,sizeof(m_count));
+    memset((void*)&m_total,0,sizeof(m_total));
+    my_atomic_rwlock_wrunlock(&time_collector_lock);
+  }
+  void collect(uint64 time)
+  {
+    int i= 0;
+    for(int count= m_utility->bound_count(); count > i; ++i)
+    {
+      if(m_utility->bound(i) > time)
+      {
+        my_atomic_rwlock_wrlock(&time_collector_lock);
+        my_atomic_add32((int32*)(&m_count[i]), 1);
+        my_atomic_add64((int64*)(&m_total[i]), time);
+        my_atomic_rwlock_wrunlock(&time_collector_lock);
+        break;
+      }
+    }
+  }
+private:
+  utility* m_utility;
+  /* The lock for atomic operations on m_count and m_total.  Only actually
+  used on architectures that do not have atomic implementation of atomic
+  operations. */
+  my_atomic_rwlock_t time_collector_lock;
+  uint32   m_count[OVERALL_POWER_COUNT + 1];
+  uint64   m_total[OVERALL_POWER_COUNT + 1];
+};
+
+class collector
+{
+public:
+  collector() : m_time(m_utility)
+  {
+    m_utility.setup(DEFAULT_BASE);
+    m_time.flush();
+  }
+public:
+  void flush()
+  {
+    m_utility.setup(opt_query_response_time_range_base);
+    m_time.flush();
+  }
+  int fill(THD* thd, TABLE_LIST *tables, COND *cond)
+  {
+    DBUG_ENTER("fill_schema_query_response_time");
+    TABLE        *table= static_cast<TABLE*>(tables->table);
+    Field        **fields= table->field;
+    for(uint i= 0, count= bound_count() + 1 /* with overflow */; count > i; ++i)
+    {
+      char time[TIME_STRING_BUFFER_LENGTH];
+      char total[TOTAL_STRING_BUFFER_LENGTH];
+      if(i == bound_count())
+      {        
+        assert(sizeof(TIME_OVERFLOW) <= TIME_STRING_BUFFER_LENGTH);
+        assert(sizeof(TIME_OVERFLOW) <= TOTAL_STRING_BUFFER_LENGTH);
+        memcpy(time,TIME_OVERFLOW,sizeof(TIME_OVERFLOW));
+        memcpy(total,TIME_OVERFLOW,sizeof(TIME_OVERFLOW));
+      }
+      else
+      {
+        print_time(time, sizeof(time), TIME_STRING_FORMAT, this->bound(i));
+        print_time(total, sizeof(total), TOTAL_STRING_FORMAT, this->total(i));
+      }
+      fields[0]->store(time,strlen(time),system_charset_info);
+      fields[1]->store(this->count(i));
+      fields[2]->store(total,strlen(total),system_charset_info);
+      if (schema_table_store_record(thd, table))
+      {
+	DBUG_RETURN(1);
+      }
+    }
+    DBUG_RETURN(0);
+  }
+  void collect(ulonglong time)
+  {
+    m_time.collect(time);
+  }
+  uint bound_count() const
+  {
+    return m_utility.bound_count();
+  }
+  ulonglong bound(uint index)
+  {
+    return m_utility.bound(index);
+  }
+  ulonglong count(uint index)
+  {
+    return m_time.count(index);
+  }
+  ulonglong total(uint index)
+  {
+    return m_time.total(index);
+  }
+private:
+  utility          m_utility;
+  time_collector   m_time;
+};
+
+static collector g_collector;
+
+} // namespace query_response_time
+
+void query_response_time_init()
+{
+}
+
+void query_response_time_free()
+{
+  query_response_time::g_collector.flush();
+}
+
+void query_response_time_flush()
+{
+  query_response_time::g_collector.flush();
+}
+void query_response_time_collect(ulonglong query_time)
+{
+  query_response_time::g_collector.collect(query_time);
+}
+
+int query_response_time_fill(THD* thd, TABLE_LIST *tables, COND *cond)
+{
+  return query_response_time::g_collector.fill(thd,tables,cond);
+}
+#endif // HAVE_RESPONSE_TIME_DISTRIBUTION

plugin/query_response_time/query_response_time.h

+#ifndef QUERY_RESPONSE_TIME_H
+#define QUERY_RESPONSE_TIME_H
+
+/*
+  Settings for query response time
+*/
+
+/*
+  Maximum string length for (10 ^ (-1 * QRT_STRING_NEGATIVE_POWER_LENGTH)) in text representation.
+  Example: for 6 is 0.000001
+  Always 2
+
+  Maximum string length for (10 ^ (QRT_STRING_POSITIVE_POWER_LENGTH + 1) - 1) in text representation.
+  Example: for 7 is 9999999.0
+*/
+#define QRT_TIME_STRING_POSITIVE_POWER_LENGTH 7
+#define QRT_TOTAL_STRING_POSITIVE_POWER_LENGTH 7
+
+/*
+  Minimum base for log - ALWAYS 2
+  Maximum base for log:
+*/
+#define QRT_MAXIMUM_BASE 1000
+
+/*
+  Filler for whole number (positive power)
+  Example: for
+  QRT_POSITIVE_POWER_FILLER ' '
+  QRT_POSITIVE_POWER_LENGTH 7
+  and number 7234 result is:
+  '   7234'
+*/
+#define QRT_POSITIVE_POWER_FILLER ""
+/*
+  Filler for fractional number. Similiary to whole number
+*/
+#define QRT_NEGATIVE_POWER_FILLER "0"
+
+/*
+  Message if time too big for statistic collecting (very long query)
+*/
+#define QRT_TIME_OVERFLOW "TOO LONG"
+
+#define QRT_DEFAULT_BASE 10
+
+#define QRT_TIME_STRING_LENGTH				\
+  max( (QRT_TIME_STRING_POSITIVE_POWER_LENGTH + 1 /* '.' */ + 6 /*QRT_TIME_STRING_NEGATIVE_POWER_LENGTH*/), \
+       (sizeof(QRT_TIME_OVERFLOW) - 1) )
+
+#define QRT_TOTAL_STRING_LENGTH				\
+  max( (QRT_TOTAL_STRING_POSITIVE_POWER_LENGTH + 1 /* '.' */ + 6 /*QRT_TOTAL_STRING_NEGATIVE_POWER_LENGTH*/), \
+       (sizeof(QRT_TIME_OVERFLOW) - 1) )
+
+extern ST_SCHEMA_TABLE query_response_time_table;
+
+#ifdef HAVE_RESPONSE_TIME_DISTRIBUTION
+extern void query_response_time_init   ();
+extern void query_response_time_free   ();
+extern void query_response_time_flush  ();
+extern void query_response_time_collect(ulonglong query_time);
+extern int  query_response_time_fill   (THD* thd, TABLE_LIST *tables, COND *cond);
+
+extern ulong   opt_query_response_time_range_base;
+extern my_bool opt_query_response_time_stats;
+#endif // HAVE_RESPONSE_TIME_DISTRIBUTION
+
+#endif // QUERY_RESPONSE_TIME_H

sql/sp_head.cc

@@ -41,6 +41,7 @@
 #include "sql_parse.h"                          // cleanup_items
 #include "sql_base.h"                           // close_thread_tables
 #include "transaction.h"       // trans_commit_stmt
+#include "sql_audit.h"
 
 /*
   Sufficient max length of printed destinations and frame offsets (all uints).
@@ -3129,6 +3130,10 @@ sp_instr_stmt::execute(THD *thd, uint *nextp)
 
       query_cache_end_of_result(thd);
 
+      mysql_audit_general(thd, MYSQL_AUDIT_GENERAL_STATUS,
+                         thd->stmt_da->is_error() ? thd->stmt_da->sql_errno() : 0,
+                         command_name[COM_QUERY].str);
+
       if (!res && unlikely(thd->enable_slow_log))
         log_slow_statement(thd);
     }