← Back to branch summary

~drizzle-trunk/drizzle/development

« back to all changes in this revision

Viewing changes to plugin/logging_query/logging_query.cc

  • Committer: Monty Taylor
  • Date: 2009-03-08 23:45:12 UTC
  • mto: (923.2.1 mordred)
  • mto: This revision was merged to the branch mainline in revision 921.
  • Revision ID: mordred@inaugust.com-20090308234512-tqkygxtu1iaig23s
Removed C99 isnan() usage, which allows us to remove the util/math.{cc,h} workarounds. Yay for standards!

Show diffs side-by-side

added added

removed removed

Lines of Context:
plugin/logging_query/logging_query.cc
1
 
/* drizzle/plugin/logging_query/logging_query.cc */
 
1
/* -*- mode: c++; c-basic-offset: 2; indent-tabs-mode: nil; -*-
 
2
 *  vim:expandtab:shiftwidth=2:tabstop=2:smarttab:
 
3
 *
 
4
 *  Copyright (C) 2008,2009 Mark Atwood
 
5
 *
 
6
 *  This program is free software; you can redistribute it and/or modify
 
7
 *  it under the terms of the GNU General Public License as published by
 
8
 *  the Free Software Foundation; version 2 of the License.
 
9
 *
 
10
 *  This program is distributed in the hope that it will be useful,
 
11
 *  but WITHOUT ANY WARRANTY; without even the implied warranty of
 
12
 *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
 
13
 *  GNU General Public License for more details.
 
14
 *
 
15
 *  You should have received a copy of the GNU General Public License
 
16
 *  along with this program; if not, write to the Free Software
 
17
 *  Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 
18
 */
2
19
 
3
 
/* need to define DRIZZLE_SERVER to get inside the THD */
4
 
#define DRIZZLE_SERVER 1
5
20
#include <drizzled/server_includes.h>
6
21
#include <drizzled/plugin_logging.h>
7
 
 
8
 
#define MAX_MSG_LEN (32*1024)
9
 
 
10
 
static char* logging_query_filename= NULL;
 
22
#include <drizzled/gettext.h>
 
23
#include <drizzled/session.h>
 
24
 
 
25
/* TODO make this dynamic as needed */
 
26
static const int MAX_MSG_LEN= 32*1024;
 
27
 
 
28
static bool sysvar_logging_query_enable= false;
 
29
static char* sysvar_logging_query_filename= NULL;
 
30
/* TODO fix these to not be unsigned long one we have sensible sys_var system */
 
31
static unsigned long sysvar_logging_query_threshold_slow= 0;
 
32
static unsigned long sysvar_logging_query_threshold_big_resultset= 0;
 
33
static unsigned long sysvar_logging_query_threshold_big_examined= 0;
11
34
 
12
35
static int fd= -1;
13
36
 
14
 
// copied from drizzled/sql_parse.cc
15
 
 
16
 
const LEX_STRING command_name[]={
17
 
  { C_STRING_WITH_LEN("Sleep") },
18
 
  { C_STRING_WITH_LEN("Quit") },
19
 
  { C_STRING_WITH_LEN("InitDB") },
20
 
  { C_STRING_WITH_LEN("Query") },
21
 
  { C_STRING_WITH_LEN("FieldList") },
22
 
  { C_STRING_WITH_LEN("CreateDB") },
23
 
  { C_STRING_WITH_LEN("DropDB") },
24
 
  { C_STRING_WITH_LEN("Refresh") },
25
 
  { C_STRING_WITH_LEN("Shutdown") },
26
 
  { C_STRING_WITH_LEN("Processlist") },
27
 
  { C_STRING_WITH_LEN("Connect") },
28
 
  { C_STRING_WITH_LEN("Kill") },
29
 
  { C_STRING_WITH_LEN("Ping") },
30
 
  { C_STRING_WITH_LEN("Time") },
31
 
  { C_STRING_WITH_LEN("ChangeUser") },
32
 
  { C_STRING_WITH_LEN("BinlogDump") },
33
 
  { C_STRING_WITH_LEN("ConnectOut") },
34
 
  { C_STRING_WITH_LEN("RegisterSlave") },
35
 
  { C_STRING_WITH_LEN("SetOption") },
36
 
  { C_STRING_WITH_LEN("Daemon") },
37
 
  { C_STRING_WITH_LEN("Error") }
38
 
};
39
 
 
40
 
 
41
 
bool logging_query_func_pre (THD *thd)
 
37
/* stolen from mysys/my_getsystime
 
38
   until the Session has a good utime "now" we can use
 
39
   will have to use this instead */
 
40
 
 
41
#include <sys/time.h>
 
42
static uint64_t get_microtime()
42
43
{
43
 
  char msgbuf[MAX_MSG_LEN];
44
 
  int msgbuf_len= 0;
45
 
  int wrv;
46
 
 
47
 
  if (fd < 0) 
48
 
    return false;
49
 
 
50
 
  assert(thd != NULL);
51
 
 
52
 
  msgbuf_len=
53
 
    snprintf(msgbuf, MAX_MSG_LEN,
54
 
             "log bgn thread_id=%ld query_id=%ld command=%.*s"
55
 
             " db=\"%.*s\" query=\"%.*s\"\n",
56
 
             (unsigned long) thd->thread_id,
57
 
             (unsigned long) thd->query_id,
58
 
             (uint32_t)command_name[thd->command].length, command_name[thd->command].str,
59
 
             thd->db_length, thd->db,
60
 
             thd->query_length, thd->query);
61
 
  /* a single write has a OS level thread lock
62
 
     so there is no need to have mutexes guarding this write,
 
44
#if defined(HAVE_GETHRTIME)
 
45
  return gethrtime()/1000;
 
46
#else
 
47
  uint64_t newtime;
 
48
  struct timeval t;
 
49
  /*
 
50
    The following loop is here because gettimeofday may fail on some systems
63
51
  */
64
 
  wrv= write(fd, msgbuf, msgbuf_len);
65
 
  assert(wrv == msgbuf_len);
66
 
 
 
52
  while (gettimeofday(&t, NULL) != 0) {}
 
53
  newtime= (uint64_t)t.tv_sec * 1000000 + t.tv_usec;
 
54
  return newtime;
 
55
#endif  /* defined(HAVE_GETHRTIME) */
 
56
}
 
57
 
 
58
/* quote a string to be safe to include in a CSV line
 
59
   that means backslash quoting all commas, doublequotes, backslashes,
 
60
   and all the ASCII unprintable characters
 
61
   as long as we pass the high-bit bytes unchanged
 
62
   this is safe to do to a UTF8 string
 
63
   we dont allow overrunning the targetbuffer
 
64
   to avoid having a very long query overwrite memory
 
65
 
 
66
   TODO consider remapping the unprintables instead to "Printable
 
67
   Representation", the Unicode characters from the area U+2400 to
 
68
   U+2421 reserved for representing control characters when it is
 
69
   necessary to print or display them rather than have them perform
 
70
   their intended function.
 
71
 
 
72
*/
 
73
 
 
74
static unsigned char *quotify (const unsigned char *src, size_t srclen,
 
75
                               unsigned char *dst, size_t dstlen)
 
76
{
 
77
  static const char hexit[]= { '0', '1', '2', '3', '4', '5', '6', '7',
 
78
                          '8', '9', 'a', 'b', 'c', 'd', 'e', 'f' };
 
79
  size_t dst_ndx;  /* ndx down the dst */
 
80
  size_t src_ndx;  /* ndx down the src */
 
81
 
 
82
  assert(dst);
 
83
  assert(dstlen > 0);
 
84
 
 
85
  for (dst_ndx= 0,src_ndx= 0; src_ndx < srclen; src_ndx++)
 
86
  {
 
87
 
 
88
    /* Worst case, need 5 dst bytes for the next src byte.
 
89
       backslash x hexit hexit null
 
90
       so if not enough room, just terminate the string and return
 
91
    */
 
92
    if ((dstlen - dst_ndx) < 5)
 
93
    {
 
94
      dst[dst_ndx]= (unsigned char)0x00;
 
95
      return dst;
 
96
    }
 
97
 
 
98
    if (src[src_ndx] > 0x7f)
 
99
    {
 
100
      // pass thru high bit characters, they are non-ASCII UTF8 Unicode
 
101
      dst[dst_ndx++]= src[src_ndx];
 
102
    }
 
103
    else if (src[src_ndx] == 0x00)  // null
 
104
    {
 
105
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) '0';
 
106
    }
 
107
    else if (src[src_ndx] == 0x07)  // bell
 
108
    {
 
109
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'a';
 
110
    }
 
111
    else if (src[src_ndx] == 0x08)  // backspace
 
112
    {
 
113
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'b';
 
114
    }
 
115
    else if (src[src_ndx] == 0x09)  // horiz tab
 
116
    {
 
117
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 't';
 
118
    }
 
119
    else if (src[src_ndx] == 0x0a)  // line feed
 
120
    {
 
121
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'n';
 
122
    }
 
123
    else if (src[src_ndx] == 0x0b)  // vert tab
 
124
    {
 
125
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'v';
 
126
    }
 
127
    else if (src[src_ndx] == 0x0c)  // formfeed
 
128
    {
 
129
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'f';
 
130
    }
 
131
    else if (src[src_ndx] == 0x0d)  // carrage return
 
132
    {
 
133
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'r';
 
134
    }
 
135
    else if (src[src_ndx] == 0x1b)  // escape
 
136
    {
 
137
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= (unsigned char) 'e';
 
138
    }
 
139
    else if (src[src_ndx] == 0x22)  // quotation mark
 
140
    {
 
141
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x22;
 
142
    }
 
143
    else if (src[src_ndx] == 0x2C)  // comma
 
144
    {
 
145
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x2C;
 
146
    }
 
147
    else if (src[src_ndx] == 0x5C)  // backslash
 
148
    {
 
149
      dst[dst_ndx++]= 0x5C; dst[dst_ndx++]= 0x5C;
 
150
    }
 
151
    else if ((src[src_ndx] < 0x20) || (src[src_ndx] == 0x7F))  // other unprintable ASCII
 
152
    {
 
153
      dst[dst_ndx++]= 0x5C;
 
154
      dst[dst_ndx++]= (unsigned char) 'x';
 
155
      dst[dst_ndx++]= hexit[(src[src_ndx] >> 4) & 0x0f];
 
156
      dst[dst_ndx++]= hexit[src[src_ndx] & 0x0f];
 
157
    }
 
158
    else  // everything else
 
159
    {
 
160
      dst[dst_ndx++]= src[src_ndx];
 
161
    }
 
162
    dst[dst_ndx]= '\0';
 
163
  }
 
164
  return dst;
 
165
}
 
166
 
 
167
 
 
168
/* we could just not have a pre entrypoint at all,
 
169
   and have logging_pre == NULL
 
170
   but we have this here for the sake of being an example */
 
171
bool logging_query_func_pre (Session *)
 
172
{
67
173
  return false;
68
174
}
69
175
 
70
 
bool logging_query_func_post (THD *thd)
 
176
bool logging_query_func_post (Session *session)
71
177
{
72
178
  char msgbuf[MAX_MSG_LEN];
73
179
  int msgbuf_len= 0;
74
180
  int wrv;
75
181
 
76
 
  if (fd < 0) return false;
77
 
 
78
 
  assert(thd != NULL);
 
182
  assert(session != NULL);
 
183
 
 
184
  if (fd < 0)
 
185
    return false;
 
186
 
 
187
  /* Yes, we know that checking sysvar_logging_query_enable,
 
188
     sysvar_logging_query_threshold_big_resultset, and
 
189
     sysvar_logging_query_threshold_big_examined is not threadsafe,
 
190
     because some other thread might change these sysvars.  But we
 
191
     don't care.  We might start logging a little late as it spreads
 
192
     to other threads.  Big deal. */
 
193
 
 
194
  // return if not enabled or query was too fast or resultset was too small
 
195
  if (sysvar_logging_query_enable == false)
 
196
    return false;
 
197
  if (session->sent_row_count < sysvar_logging_query_threshold_big_resultset)
 
198
    return false;
 
199
  if (session->examined_row_count < sysvar_logging_query_threshold_big_examined)
 
200
    return false;
 
201
 
 
202
  // logging this is far too verbose
 
203
  if (session->command == COM_FIELD_LIST)
 
204
    return false;
 
205
 
 
206
  /* TODO, looks like connect_utime isnt being set in the session
 
207
     object.  We could store the time this plugin was loaded, but that
 
208
     would just be a dumb workaround. */
 
209
  /* TODO, the session object should have a "utime command completed"
 
210
     inside itself, so be more accurate, and so this doesnt have to
 
211
     keep calling current_utime, which can be slow */
 
212
 
 
213
  uint64_t t_mark= get_microtime();
 
214
 
 
215
  if ((t_mark - session->start_utime) < (sysvar_logging_query_threshold_slow))
 
216
    return false;
 
217
 
 
218
  // buffer to quotify the query
 
219
  unsigned char qs[255];
 
220
 
 
221
  // to avoid trying to printf %s something that is potentially NULL
 
222
  const char *dbs= (session->db) ? session->db : "";
 
223
  int dbl= 0;
 
224
  if (dbs != NULL)
 
225
    dbl= session->db_length;
79
226
 
80
227
  msgbuf_len=
81
228
    snprintf(msgbuf, MAX_MSG_LEN,
82
 
             "log end thread_id=%ld query_id=%ld command=%.*s"
83
 
             " rows.sent=%ld rows.exam=%u\n",
84
 
             (unsigned long) thd->thread_id, 
85
 
             (unsigned long) thd->query_id,
86
 
             (uint32_t)command_name[thd->command].length, command_name[thd->command].str,
87
 
             (unsigned long) thd->sent_row_count,
88
 
             (uint32_t) thd->examined_row_count);
89
 
  /* a single write has a OS level thread lock
90
 
     so there is no need to have mutexes guarding this write,
91
 
  */
 
229
             "%"PRIu64",%"PRIu64",%"PRIu64",\"%.*s\",\"%s\",\"%.*s\","
 
230
             "%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64",%"PRIu64"\n",
 
231
             t_mark,
 
232
             session->thread_id,
 
233
             session->query_id,
 
234
             // dont need to quote the db name, always CSV safe
 
235
             dbl, dbs,
 
236
             // do need to quote the query
 
237
             quotify((unsigned char *)session->query,
 
238
                     session->query_length, qs, sizeof(qs)),
 
239
             // command_name is defined in drizzled/sql_parse.cc
 
240
             // dont need to quote the command name, always CSV safe
 
241
             (int)command_name[session->command].length,
 
242
             command_name[session->command].str,
 
243
             // counters are at end, to make it easier to add more
 
244
             (t_mark - session->connect_utime),
 
245
             (t_mark - session->start_utime),
 
246
             (t_mark - session->utime_after_lock),
 
247
             session->sent_row_count,
 
248
             session->examined_row_count);
 
249
 
 
250
 
 
251
  // a single write has a kernel thread lock, thus no need mutex guard this
92
252
  wrv= write(fd, msgbuf, msgbuf_len);
93
253
  assert(wrv == msgbuf_len);
94
 
 
95
254
 
96
255
  return false;
97
256
}
98
257
 
99
258
static int logging_query_plugin_init(void *p)
100
259
{
101
 
  logging_t *l= (logging_t *) p;
 
260
  logging_t *l= static_cast<logging_t *>(p);
102
261
 
103
 
  if (logging_query_filename == NULL)
 
262
  if (sysvar_logging_query_filename == NULL)
104
263
  {
105
264
    /* no destination filename was specified via system variables
106
 
       return now, dont set the callback pointers 
 
265
       return now, dont set the callback pointers
107
266
    */
108
267
    return 0;
109
268
  }
110
269
 
111
 
  fd= open(logging_query_filename, O_WRONLY | O_APPEND | O_CREAT);
112
 
  if (fd < 0) 
 
270
  fd= open(sysvar_logging_query_filename,
 
271
           O_WRONLY | O_APPEND | O_CREAT,
 
272
           S_IRUSR|S_IWUSR);
 
273
  if (fd < 0)
113
274
  {
114
 
    fprintf(stderr, "fail open fn=%s er=%s\n",
115
 
            logging_query_filename,
116
 
            strerror(errno));
 
275
    errmsg_printf(ERRMSG_LVL_ERROR, _("fail open() fn=%s er=%s\n"),
 
276
                  sysvar_logging_query_filename,
 
277
                  strerror(errno));
117
278
 
118
 
    /* we should return an error here, so the plugin doesnt load
 
279
    /* TODO
 
280
       we should return an error here, so the plugin doesnt load
119
281
       but this causes Drizzle to crash
120
282
       so until that is fixed,
121
283
       just return a success,
134
296
{
135
297
  logging_st *l= (logging_st *) p;
136
298
 
137
 
  if (fd >= 0) 
 
299
  if (fd >= 0)
138
300
  {
139
301
    close(fd);
140
302
    fd= -1;
146
308
  return 0;
147
309
}
148
310
 
149
 
static DRIZZLE_SYSVAR_STR(filename, logging_query_filename,
 
311
static DRIZZLE_SYSVAR_BOOL(
 
312
  enable,
 
313
  sysvar_logging_query_enable,
 
314
  PLUGIN_VAR_NOCMDARG,
 
315
  N_("Enable logging to CSV file"),
 
316
  NULL, /* check func */
 
317
  NULL, /* update func */
 
318
  false /* default */);
 
319
 
 
320
static DRIZZLE_SYSVAR_STR(
 
321
  filename,
 
322
  sysvar_logging_query_filename,
150
323
  PLUGIN_VAR_READONLY,
151
 
  "File to log queries to.",
152
 
  NULL, NULL, NULL);
 
324
  N_("File to log to"),
 
325
  NULL, /* check func */
 
326
  NULL, /* update func*/
 
327
  NULL /* default */);
 
328
 
 
329
static DRIZZLE_SYSVAR_ULONG(
 
330
  threshold_slow,
 
331
  sysvar_logging_query_threshold_slow,
 
332
  PLUGIN_VAR_OPCMDARG,
 
333
  N_("Threshold for logging slow queries, in microseconds"),
 
334
  NULL, /* check func */
 
335
  NULL, /* update func */
 
336
  0, /* default */
 
337
  0, /* min */
 
338
  UINT32_MAX, /* max */
 
339
  0 /* blksiz */);
 
340
 
 
341
static DRIZZLE_SYSVAR_ULONG(
 
342
  threshold_big_resultset,
 
343
  sysvar_logging_query_threshold_big_resultset,
 
344
  PLUGIN_VAR_OPCMDARG,
 
345
  N_("Threshold for logging big queries, for rows returned"),
 
346
  NULL, /* check func */
 
347
  NULL, /* update func */
 
348
  0, /* default */
 
349
  0, /* min */
 
350
  UINT32_MAX, /* max */
 
351
  0 /* blksiz */);
 
352
 
 
353
static DRIZZLE_SYSVAR_ULONG(
 
354
  threshold_big_examined,
 
355
  sysvar_logging_query_threshold_big_examined,
 
356
  PLUGIN_VAR_OPCMDARG,
 
357
  N_("Threshold for logging big queries, for rows examined"),
 
358
  NULL, /* check func */
 
359
  NULL, /* update func */
 
360
  0, /* default */
 
361
  0, /* min */
 
362
  UINT32_MAX, /* max */
 
363
  0 /* blksiz */);
153
364
 
154
365
static struct st_mysql_sys_var* logging_query_system_variables[]= {
 
366
  DRIZZLE_SYSVAR(enable),
155
367
  DRIZZLE_SYSVAR(filename),
 
368
  DRIZZLE_SYSVAR(threshold_slow),
 
369
  DRIZZLE_SYSVAR(threshold_big_resultset),
 
370
  DRIZZLE_SYSVAR(threshold_big_examined),
156
371
  NULL
157
372
};
158
373
 
159
 
mysql_declare_plugin(logging_query)
 
374
drizzle_declare_plugin(logging_query)
160
375
{
161
376
  DRIZZLE_LOGGER_PLUGIN,
162
377
  "logging_query",
163
 
  "0.1",
 
378
  "0.2",
164
379
  "Mark Atwood <mark@fallenpegasus.com>",
165
 
  "Log queries",
 
380
  N_("Log queries to a CSV file"),
166
381
  PLUGIN_LICENSE_GPL,
167
382
  logging_query_plugin_init,
168
383
  logging_query_plugin_deinit,
170
385
  logging_query_system_variables,
171
386
  NULL
172
387
}
173
 
mysql_declare_plugin_end;
 
388
drizzle_declare_plugin_end;