~percona-core/percona-server/5.1

+# Profile_starting: X.X Profile_starting_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X

+# Profile_total: X.X Profile_total_cpu: X.X

+# User@Host: root[root] @ localhost []

+# Thread_id: X Schema: test Last_errno: X Killed: X

+# Query_time: X.X Lock_time: X.X Rows_sent: X Rows_examined: X Rows_affected: X Rows_read: X

+# Bytes_sent: X Tmp_tables: X Tmp_disk_tables: X Tmp_table_sizes: X

+# Profile_starting: X.X Profile_starting_cpu: X.X Profile_checking_permissions: X.X Profile_checking_permissions_cpu: X.X Profile_Opening_tables: X.X Profile_Opening_tables_cpu: X.X Profile_init: X.X Profile_init_cpu: X.X Profile_optimizing: X.X Profile_optimizing_cpu: X.X Profile_executing: X.X Profile_executing_cpu: X.X Profile_end: X.X Profile_end_cpu: X.X Profile_query_end: X.X Profile_query_end_cpu: X.X Profile_freeing_items: X.X Profile_freeing_items_cpu: X.X Profile_logging_slow_query: X.X Profile_logging_slow_query_cpu: X.X

+# Profile_total: X.X Profile_total_cpu: X.X

+SET GLOBAL slow_query_log_file=@old_slow_query_log_file;

--- /dev/null

+++ b/mysql-test/t/percona_bug643149.test

@@ -0,0 +1,52 @@

+# This test suffers from server

+# Bug#38124 "general_log_file" variable silently unset when using expression

+# In short:

+# SET GLOBAL general_log_file = @<whatever>

+# SET GLOBAL slow_query_log = @<whatever>

+# cause that the value of these server system variables is set to default

+# instead of the assigned values. There comes no error message or warning.

+# If this bug is fixed please

+# 1. try this test with "let $fixed_bug38124 = 0;"

+# 2. remove all workarounds if 1. was successful.

+let $fixed_bug38124 = 0;

+SET @old_slow_query_log_file=@@global.slow_query_log_file;

+SET GLOBAL slow_query_log=on;

+SET LOCAL profiling_server=on;

+SET LOCAL long_query_time=0;

+let slogfile=$MYSQLTEST_VARDIR/percona_bug643149_slow.log;

+--replace_result $MYSQLTEST_VARDIR MYSQLTEST_VARDIR

+--eval SET GLOBAL slow_query_log_file='$slogfile';

+--disable_ps_protocol

+SELECT 1;

+--enable_ps_protocol

+perl;

+ $slogfile= $ENV{'slogfile'};

+ open(FILE, "$slogfile") or

+ die("Unable to read slow query log file $slogfile: $!\n");

+ while(<FILE>) {

+ next if (!/^#/);

+ next if (/^# Time:/);

+ s/[0-9]+/X/g;

+ print;

+ }

+ close(FILE);

+ open(FILE, '>', "$slogfile");

+ close(FILE);

+EOF

+SET GLOBAL slow_query_log_file=@old_slow_query_log_file;

+if(!$fixed_bug38124)

+ --disable_query_log

+ let $my_var = `SELECT @old_slow_query_log_file`;

+ eval SET @@global.slow_query_log_file = '$my_var';

+ --enable_query_log

--- /dev/null

+++ b/patch_info/profiling_slow.info

@@ -0,0 +1,9 @@

+File=profiling_slow.info

+Name=profiling from SHOW PROFILE to slow.log

+Version=1.0

+Author=Percona <info@percona.com>

+License=GPL

+Comment=

+Changelog

+2009-05-18

+Initial implementation

--- a/sql/log.cc

100

+++ b/sql/log.cc

101

@@ -2436,6 +2436,11 @@

102

my_b_printf(&log_file,"# No InnoDB statistics available for this query\n") == (uint) -1)

103

tmp_errno= errno;

104

}

105

106

+#if defined(ENABLED_PROFILING) && defined(COMMUNITY_SERVER)

107

+ thd->profiling.print_current(&log_file);

108

+#endif

109

110

if (thd->db && strcmp(thd->db, db))

111

{ // Database changed

112

if (my_b_printf(&log_file,"use %s;\n",thd->db) == (uint) -1)

113

--- a/sql/mysqld.cc

114

+++ b/sql/mysqld.cc

115

@@ -5809,6 +5809,8 @@

116

OPT_LOG_OUTPUT,

117

OPT_PORT_OPEN_TIMEOUT,

118

OPT_PROFILING,

119

+ OPT_PROFILING_SERVER,

120

+ OPT_PROFILING_USE_GETRUSAGE,

121

OPT_KEEP_FILES_ON_CREATE,

122

OPT_GENERAL_LOG,

123

OPT_SLOW_LOG,

124

@@ -6424,6 +6426,16 @@

125

&global_system_variables.profiling_history_size,

126

&max_system_variables.profiling_history_size,

127

0, GET_ULONG, REQUIRED_ARG, 15, 0, 100, 0, 0, 0},

128

+ {"profiling_server", OPT_PROFILING_SERVER,

129

+ "Enable profiling of all threads",

130

+ (uchar**) &global_system_variables.profiling_server,

131

+ (uchar**) &max_system_variables.profiling_server, 0, GET_BOOL,

132

+ OPT_ARG, 0, 0, 0, 0, 0, 0 },

133

+ {"profiling_use_getrusage", OPT_PROFILING_USE_GETRUSAGE,

134

+ "Enable getrusage function call for profiling",

135

+ (uchar**) &global_system_variables.profiling_use_getrusage,

136

+ (uchar**) &max_system_variables.profiling_use_getrusage, 0, GET_BOOL,

137

+ OPT_ARG, 0, 0, 0, 0, 0, 0 },

138

#endif

139

{"relay-log", OPT_RELAY_LOG,

140

"The location and name to use for relay logs.",

141

--- a/sql/set_var.cc

142

+++ b/sql/set_var.cc

143

@@ -860,6 +860,10 @@

144

ulonglong(OPTION_PROFILING));

145

static sys_var_thd_ulong sys_profiling_history_size(&vars, "profiling_history_size",

146

&SV::profiling_history_size);

147

+static sys_var_thd_bool sys_profiling_server(&vars, "profiling_server",

148

+ &SV::profiling_server);

149

+static sys_var_thd_bool sys_profiling_use_getrusage(&vars, "profiling_use_getrusage",

150

+ &SV::profiling_use_getrusage);

151

#endif

152

153

/* Local state variables */

154

--- a/sql/sql_class.h

155

+++ b/sql/sql_class.h

156

@@ -330,6 +330,8 @@

157

ulong optimizer_switch;

158

ulong preload_buff_size;

159

ulong profiling_history_size;

160

+ my_bool profiling_server;

161

+ my_bool profiling_use_getrusage;

162

ulong query_cache_type;

163

ulong read_buff_size;

164

ulong read_rnd_buff_size;

165

--- a/sql/sql_profile.cc

166

+++ b/sql/sql_profile.cc

167

@@ -225,8 +225,22 @@

168

{

169

time_usecs= (double) my_getsystime() / 10.0; /* 1 sec was 1e7, now is 1e6 */

170

#ifdef HAVE_GETRUSAGE

171

- getrusage(RUSAGE_SELF, &rusage);

172

+ if ((profile->get_profiling())->enabled_getrusage())

173

+ getrusage(RUSAGE_SELF, &rusage);

174

#endif

175

176

+#ifdef HAVE_CLOCK_GETTIME

177

+ struct timespec tp;

178

179

+ if (!(clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tp)))

180

+ {

181

+ cpu_time_usecs= tp.tv_sec*1000000000.0 + tp.tv_nsec;

182

+ }

183

+ else

184

+#endif

185

+ {

186

+ cpu_time_usecs= 0;

187

+ }

188

}

189

190

191

@@ -343,7 +357,7 @@

192

finish_current_query();

193

}

194

195

- enabled= (((thd)->options & OPTION_PROFILING) != 0);

196

+ enabled= (((thd)->options & OPTION_PROFILING) != 0) || ( thd->variables.profiling_server );

197

198

if (! enabled) DBUG_VOID_RETURN;

199

200

@@ -381,7 +395,8 @@

201

status_change("ending", NULL, NULL, 0);

202

203

if ((enabled) && /* ON at start? */

204

- ((thd->options & OPTION_PROFILING) != 0) && /* and ON at end? */

205

+ (((thd->options & OPTION_PROFILING) != 0) ||

206

+ (thd->variables.profiling_server)) && /* and ON at end? */

207

(current->query_source != NULL) &&

208

(! current->entries.is_empty()))

209

{

210

@@ -482,6 +497,118 @@

211

DBUG_VOID_RETURN;

212

}

213

214

+bool PROFILING::enabled_getrusage()

215

216

+ return thd->variables.profiling_use_getrusage;

217

218

219

+/**

220

+ For a given profile entry specified by a name and 2 time measurements,

221

+ print its normalized name (i.e. with all spaces replaced with underscores)

222

+ along with its wall clock and CPU time.

223

+*/

224

225

+static void my_b_print_status(IO_CACHE *log_file, const char *status,

226

+ PROF_MEASUREMENT *start, PROF_MEASUREMENT *stop)

227

228

+ DBUG_ENTER("my_b_print_status");

229

+ DBUG_ASSERT(log_file != NULL && status != NULL);

230

+ char query_time_buff[22+7];

231

+ const char *tmp;

232

233

+ my_b_printf(log_file, "Profile_");

234

+ for (tmp= status; *tmp; tmp++)

235

+ my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);

236

237

+ snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",

238

+ (stop->time_usecs - start->time_usecs) / (1000.0 * 1000));

239

+ my_b_printf(log_file, ": %s ", query_time_buff);

240

241

+ my_b_printf(log_file, "Profile_");

242

+ for (tmp= status; *tmp; tmp++)

243

+ my_b_write_byte(log_file, *tmp == ' ' ? '_' : *tmp);

244

+ my_b_printf(log_file, "_cpu: ");

245

246

+ snprintf(query_time_buff, sizeof(query_time_buff), "%.6f",

247

+ (stop->cpu_time_usecs - start->cpu_time_usecs) /

248

+ (1000.0 * 1000 * 1000));

249

+ my_b_printf(log_file, "%s ", query_time_buff);

250

251

+ DBUG_VOID_RETURN;

252

253

254

+/**

255

+ Print output for current query to file

256

+*/

257

258

+int PROFILING::print_current(IO_CACHE *log_file)

259

260

+ DBUG_ENTER("PROFILING::print_current");

261

+ ulonglong row_number= 0;

262

263

+ QUERY_PROFILE *query;

264

+ /* Get current query */

265

+ if (current == NULL)

266

+ {

267

+ DBUG_RETURN(0);

268

+ }

269

270

+ query= current;

271

272

+ my_b_printf(log_file, "# ");

273

274

+ void *entry_iterator;

275

+ PROF_MEASUREMENT *entry= NULL, *previous= NULL, *first= NULL;

276

+ /* ...and for each query, go through all its state-change steps. */

277

+ for (entry_iterator= query->entries.new_iterator();

278

+ entry_iterator != NULL;

279

+ entry_iterator= query->entries.iterator_next(entry_iterator),

280

+ previous=entry, row_number++)

281

+ {

282

+ entry= query->entries.iterator_value(entry_iterator);

283

284

+ /* Skip the first. We count spans of fence, not fence-posts. */

285

+ if (previous == NULL) {first= entry; continue;}

286

287

+ if (thd->lex->sql_command == SQLCOM_SHOW_PROFILE)

288

+ {

289

+ /*

290

+ We got here via a SHOW command. That means that we stored

291

+ information about the query we wish to show and that isn't

292

+ in a WHERE clause at a higher level to filter out rows we

293

+ wish to exclude.

294

295

+ Because that functionality isn't available in the server yet,

296

+ we must filter here, at the wrong level. Once one can con-

297

+ struct where and having conditions at the SQL layer, then this

298

+ condition should be ripped out.

299

+ */

300

+ if (thd->lex->profile_query_id == 0) /* 0 == show final query */

301

+ {

302

+ if (query != last)

303

+ continue;

304

+ }

305

+ else

306

+ {

307

+ if (thd->lex->profile_query_id != query->profiling_query_id)

308

+ continue;

309

+ }

310

+ }

311

312

+ my_b_print_status(log_file, previous->status, previous, entry);

313

+ }

314

315

+ my_b_write_byte(log_file, '\n');

316

+ if ((entry != NULL) && (first != NULL))

317

+ {

318

+ my_b_printf(log_file, "# ");

319

+ my_b_print_status(log_file, "total", first, entry);

320

+ my_b_write_byte(log_file, '\n');

321

+ }

322

323

+ DBUG_RETURN(0);

324

325

326

/**

327

Fill the information schema table, "query_profile", as defined in show.cc .

328

There are two ways to get to this function: Selecting from the information

329

@@ -577,6 +704,8 @@

330

331

#ifdef HAVE_GETRUSAGE

332

333

+ if (enabled_getrusage())

334

+ {

335

my_decimal cpu_utime_decimal, cpu_stime_decimal;

336

337

double2my_decimal(E_DEC_FATAL_ERROR,

338

@@ -647,6 +776,7 @@

339

table->field[14]->store((uint32)(entry->rusage.ru_nswap -

340

previous->rusage.ru_nswap), true);

341

table->field[14]->set_notnull();

342

+ }

343

#else

344

/* TODO: Add swap info for non-BSD systems */

345

#endif

346

--- a/sql/sql_profile.h

347

+++ b/sql/sql_profile.h

348

@@ -168,11 +168,15 @@

349

350

class PROF_MEASUREMENT

351

{

352

-private:

353

- friend class QUERY_PROFILE;

354

- friend class PROFILING;

355

356

QUERY_PROFILE *profile;

357

358

+ char *allocated_status_memory;

359

360

+ void set_label(const char *status_arg, const char *function_arg,

361

+ const char *file_arg, unsigned int line_arg);

362

+ void clean_up();

363

364

+public:

365

char *status;

366

#ifdef HAVE_GETRUSAGE

367

struct rusage rusage;

368

@@ -183,12 +187,7 @@

369

unsigned int line;

370

371

double time_usecs;

372

- char *allocated_status_memory;

373

374

- void set_label(const char *status_arg, const char *function_arg,

375

- const char *file_arg, unsigned int line_arg);

376

- void clean_up();

377

378

+ double cpu_time_usecs;

379

PROF_MEASUREMENT();

380

PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg);

381

PROF_MEASUREMENT(QUERY_PROFILE *profile_arg, const char *status_arg,

382

@@ -233,6 +232,11 @@

383

384

/* Show this profile. This is called by PROFILING. */

385

bool show(uint options);

386

387

+public:

388

389

+ inline PROFILING * get_profiling() { return profiling; };

390

391

};

392

393

394

@@ -278,9 +282,11 @@

395

396

/* SHOW PROFILES */

397

bool show_profiles();

398

+ bool enabled_getrusage();

399

400

/* ... from INFORMATION_SCHEMA.PROFILING ... */

401

int fill_statistics_info(THD *thd, TABLE_LIST *tables, Item *cond);

402

+ int print_current(IO_CACHE *log_file);

403

};

404

405

# endif /* HAVE_PROFILING */

Older »