mysql 5.7 general_log table has user_host but the file does not

Question

I'm trying to resolve an issue where one particular user hammers our mysql 5.7 database every 2 hours, for a few minutes. Not evil, but I'm suspicious it may be inefficient (or it may not be and it's just the way it is).

The mysql.general_log table gives me everything I want, but I prefer the ease of a file. The output to the file specified with general_log_file works fine, but doesn't include the user_host data that the database table has.

I've read 5.4.3 The General Query Log, googled, but can't seem to find any hint of this.

Is there a format I can set that will include user_host into the file system log file? I must of missed something obvious, why wouldn't the output be exactly the same, file or table?

example of what I see in the file:

2018年03月01日T15:41:45.450491Z 137300 Query SHOW COLLATION
2018年03月01日T15:41:45.451280Z 137299 Query SET NAMES latin1
2018年03月01日T15:41:45.451425Z 137299 Query SET character_set_results = NULL
2018年03月01日T15:41:45.451554Z 137299 Query SET autocommit=1

PS

My workaround is

mysql --user etc... -e "select user_host,argument from general_log where user_host like 'billybob%'" > junk

which isn't as nice as (IMO)

grep billybob log_file

edit:

2018年03月01日T15:41:45.450317Z 137300 Query /* mysql-connector-java-5.1.16 ( Revision: ${bzr.revision-id} ) */SELECT
 @@session.auto_increment_increment

• Rick James: What does the first line with 137300 have in it?
• Jim: @RickJames I'm not sure I understand. That is the complete cut of those lines from the file.
• Rick James: I would expect something about connection #137300 being connected to show up before SHOW.... (But maybe I am wrong.)
• Jim: I understand, I have added the line above the SHOW. I see the connector is out of rev, would that have anything to do with log output?

Answer 1

IDEA #1 : USE THE SLOW LOG !!!

The Slow Log ??? Yea, I know what I said : USE THE SLOW LOG !!!

How can you ???

With the slow log being written to a text file, the header info for each slow log entry has the user@host right on the first line of each entry (ignore the # Time: line since one or more slow log entries can be saves within a single time window)

For example, the post Mysql slow query log always include "# Time:" has this example slow log:

# Time: 150419 6:00:43
# User@Host: web[web] @ localhost []
# Query_time: 7.730519 Lock_time: 0.000070 Rows_sent: 167620 Rows_examined: 167620
SET timestamp=1429416043;
SELECT /*!40001 SQL_NO_CACHE */ * FROM `messages`;
# Time: 150419 6:00:45
# User@Host: web[web] @ localhost []
# Query_time: 3.480173 Lock_time: 0.000101 Rows_sent: 0 Rows_examined: 0
SET timestamp=1429416045;
INSERT INTO user (lastupdated, fk_id, user_id) ..
# User@Host: web[web] @ localhost []
# Query_time: 3.388204 Lock_time: 0.000133 Rows_sent: 0 Rows_examined: 0
SET timestamp=1429416045;
INSERT INTO user (lastupdated, fk_id, user_id) ..

In your case, you could probably run

grep -A 3 billybob log_file

which shows for each occurrence of billybob

• The line matching billybob
• The Query Time
• Actual timestamp
• Line 1 of the actual SQL

In order to make the slow log behave like a general log you must run

mysql> SET GLOBAL long_query_time = 0.01;

Then, everything and its grandmother will be written to the slow log.

When you are done with your analysis, set the long_query_time back to its old value:

mysql> SET GLOBAL long_query_time = 10;

Don't forget to truncate the slow log after the analysis by doing

echo -n > log_file

IDEA #2 : Poll the Processlist

The problem with using either the slow log or the general log is that entry will not entry the log until the action is done. In other words, if a query takes 10 min to run, the entry will not land in the log file until the command is done executing 10 minutes after it started.

Wouldn't it be nice to catch the bad queries in the act ???

You should use pt-query-digest. Even with queries that are not done, a histogram will be generated with the pattern of queries that have executed or are still in progress.

Rather than write up an example, please see my posts where I discuss using pt-query-digest

• Dec 28, 2011 : Is there a tool like Microsoft's "SQL Server Profiler" for MySQL?
• Nov 24, 2011 ": MySQL general query log performance effects

GIVE IT A TRY !!!

• Jim: I've been waiting any other answers to come in, but it's amazingly quiet. Even on the mysql dev forum there isn't any notice. I still don't understand why a logger would change data out/format depending on the output destination. But, this is pretty inventive and I wouldn't have thought of using the slow log in this fashion. I love the out of the box thinking! thank you!