MySQL Bugs: #89637: Contribution by Facebook: Slow Query Log Changes

Bug #89637	Contribution by Facebook: Slow Query Log Changes
Submitted:	13 Feb 2018 1:38	Modified:	15 Oct 2018 16:06
Reporter:	FBContrib Admin	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	8.0.4	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
Background innformation provided by Facebook:
Abstract:
MySQL 5.6's slow query log outputs the wrong timestamp time.
Instead of the start-of-query time, it outputs the end-of-query time.
This fixes that problem and tests for regressions.

Repo: https://github.com/mysql/mysql-server
Patch on top of 8.0.4: https://github.com/mysql/mysql-server/commit/577fbcf856cd693434d554545d499559bcdd3695

Also adds more attributes to slow query log....
Query_time, Lock_time, Rows_sent and Rows_examined have always been there.
All others are new and improve performance debugging.
The new output is:
	# Query_time: 0  Lock_time: 0  Rows_sent: 0  Rows_examined: 0 \
	Thread_id: 3 Errno: 0 Killed: 0 Bytes_received: 110 \
	Bytes_sent: 134 Read_first: 0 Read_last: 0 Read_key: 2 \
	Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 \
	Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 \
	Sort_scan_count: 0 Created_tmp_disk_tables: 0 \
	Created_tmp_tables: 0 Start:  9:22:58 End:  9:22:58

Also, improves performance by moving some code out of the block in which
the log mutex is locked.

The second patch modifies the additional slow query log output statistics to 
be per-query rather than cumulative.

How to repeat:
See description

Suggested fix:
See contribution code attached

Slow Query Log Changes 
(*) This code is contributed under the Facebook agreement

Contribution: fb_patch_27.txt (text/plain), 40.82 KiB.

Posted by developer:
 
Fixed in 8.0.14.

A new system variable, log_slow_extra, if enabled, causes the server
to write additional fields to slow query log lines that provide
information about slow statements. In addition, SET lines written to
the log to indicate statement timestamps now use the time from the
beginning of statement execution, rather than the time at the end of
execution. Thanks to Facebook for the contribution on which this
feature is based.

It looks like this change duplicates the session number / thread id in the slow query log file, see Bug#115285 for related bug report.

Related: Bug#115372 for adding fields in performance_schema.events_statements_summary_by_digest (this contribution added the fields Read_first, Read_last, Read_key, Read_next, Read_prev, Read_rnd and Read_rnd_next to the slow query log file, but these are not in performance_schema.events_statements_summary_by_digest).