A Little Noise

A customer showed that a particular client reported a less-than-helpful error message when it tried to display some meta-data about a table.

I couldn’t repeat the behavior with just a copy of the schema, so I suspected it was because of the size of data in the customer’s server – somebody had used an int where they needed a long.

The customer’s data was quite large – many hundreds of GB – more than I could easily whip up on my laptop to test. But, I didn’t really need all that data, or even any data at all; I just needed MySQL to pretend it had all that data. Specifically, I needed information_schema to report a large data_length.

Enter Rewriter, the query rewrite plugin that ships with MySQL 5.7 and later.

First, the general query log gave the exact query sent by the client:

select * FROM information_schema.partitions WHERE TABLE_SCHEMA = 'schemaNameHere' AND TABLE_NAME = 'tableNameHere'

Create a copy of that table:

CREATE DATABASE debug_schema;
CREATE TABLE debug_schema.partitions LIKE information_schema.partitions;
INSERT INTO debug_schema.partitions SELECT * FROM information_schema.partitions;

Adjust the copy to report a different value:

UPDATE debug_schema.partitions SET data_length = POW(2, 32);

Install the Rewriter plugin, and add a rule to modify the schema name:

INSERT INTO query_rewrite.rewrite_rules(pattern, replacement) VALUES (
'select * FROM information_schema.partitions WHERE TABLE_SCHEMA = ? AND TABLE_NAME = ?',
'select * FROM debug_schema.partitions WHERE TABLE_SCHEMA = ? AND TABLE_NAME = ?'
);

CALL query_rewrite.flush_rewrite_rules();

Now when I try the client, it thinks information_schema has reported a huge data_length, and I get the same error which my customer had reported. Success!

Workbench announced support for a spatial view in 6.2, but examples are somewhat lacking. Just how do you get a SHP into MySQL?

Download and unpack a SHP file such as these country boundaries.

In the Workbench installation directory, you’ll find a program “ogr2ogr” that can convert .shp to .csv. Run it like this:

"C:\Program Files\MySQL\MySQL Workbench 8.0\ogr2ogr.exe" -f CSV countries.csv countries.shp -lco GEOMETRY=AS_WKT

Now create a table and load the CSV.

CREATE TABLE worldmap (
	OBJECTID smallint unsigned,
	NAME varchar(50),
	ISO3 char(3),
	ISO2 char(2),
	FIPS varchar(5),
	COUNTRY varchar(50),
	ENGLISH varchar(50),
	FRENCH varchar(50),
	SPANISH varchar(50),
	LOCAL varchar(50),
	FAO varchar(50),
	WAS_ISO varchar(3),
	SOVEREIGN varchar(50),
	CONTINENT varchar(15),
	UNREG1 varchar(30),
	UNREG2 varchar(15),
	EU boolean,
	SQKM decimal(20,11),
	g geometry
);

LOAD DATA LOCAL INFILE 'countries.csv' INTO TABLE worldmap FIELDS TERMINATED BY ',' OPTIONALLY ENCLOSED BY '"' IGNORE 1 LINES
(@WKT, OBJECTID, NAME, ISO3, ISO2, FIPS, COUNTRY, ENGLISH, FRENCH, SPANISH, LOCAL, FAO, WAS_ISO, SOVEREIGN, CONTINENT, UNREG1, UNREG2, EU, SQKM)
SET g = ST_GeomFromText(@WKT);

Now just select rows of interest in Workbench, click the Spatial View format button, and there’s your world map.

You can run multiple selects (such as the citylot data from yesterday’s post) to overlay on top of the world map.

MySQL 5.7 came out with support for JSON, improved geometry, and virtual columns. Here’s an example showing them all playing together.

Download citylots.json.

It comes as one big object, so we’ll break it up into separate lines:
grep "^{ .type" citylots.json > properties.json

Connect to a 5.7 instance of MySQL.

CREATE TABLE citylots (id serial, j json, p geometry as (ST_GeomFromGeoJSON(j, 2)));
LOAD DATA LOCAL INFILE 'properties.json' INTO TABLE citylots (j);

A few of the rows don’t contain useful data:
DELETE FROM citylots WHERE j->'$.geometry.type' IS NULL;

In MySQL Workbench, do:
SELECT id, p FROM citylots;

Then click on Spatial View. It takes a couple of minutes for 200k rows, but there’s a map of San Francisco.

The default projection, ‘Robinson’, is designed for showing the whole world at once and so is pretty distorted for this particular data set. Mercator or Equirectangular are better choices. Fortunately, Workbench repaints the data in just a few seconds.

If you selected some other fields, you can click on the map and see the relevant data for that particular geometry.

mysql < quarto.sql

Example game play:

mysql> -- Start the game and pass the first piece in the lower nibble
mysql> CALL SetupGame(0x0A);
-----------------------------------------------------------------------+
| rules                                                                |
-----------------------------------------------------------------------+
| Quarto: 4 in a line (row, column, or long diagonal) with at least one bit in common wins.
CALL Play(move); -- high 4 bits are board position, low 4 bits are piece for next player
CALL PrintBoard(base); -- to display the board. Useful bases are 16 and 2. |
-----------------------------------------------------------------------+

+------------------------+
| instructions           |
+------------------------+
| Player 1, play piece A |
+------------------------+

mysql> CALL Play(0x00);
+---------+
| board   |
+---------+
| A| | |  |
|  | | |  |
|  | | |  |
|  | | |  |
+---------+

+------------------------+
| instructions           |
+------------------------+
| Player 0, play piece 0 |
+------------------------+

mysql> CALL Play(0x1C);
+---------+
| board   |
+---------+
| A|0| |  |
|  | | |  |
|  | | |  |
|  | | |  |
+---------+

+------------------------+
| instructions           |
+------------------------+
| Player 1, play piece C |
+------------------------+

mysql> CALL Play(0x2E);
+---------+
| board   |
+---------+
| A|0|C|  |
|  | | |  |
|  | | |  |
|  | | |  |
+---------+

+------------------------+
| instructions           |
+------------------------+
| Player 0, play piece E |
+------------------------+

mysql> CALL Play(0x3F);
+---------+
| board   |
+---------+
| A|0|C|E |
|  | | |  |
|  | | |  |
|  | | |  |
+---------+

+---------------+
| result        |
+---------------+
| player 0 wins |
+---------------+

Because somebody asked for it on Freenode:

CREATE FUNCTION DATE_TRUNC(field ENUM('microsecond', 'millisecond', 'second', 'minute', 'hour', 'day', 'week', 'month', 'quarter', 'year', 'decade', 'century', 'millennium'), source datetime(6))
RETURNS datetime(6)
DETERMINISTIC
BEGIN
  IF field IN ('millisecond') THEN SET source = source - INTERVAL MICROSECOND(source) % 1000 MICROSECOND; END IF;
  IF field NOT IN ('microsecond', 'millisecond') THEN SET source = source - INTERVAL MICROSECOND(source) MICROSECOND; END IF;
  IF field NOT IN ('microsecond', 'millisecond', 'second') THEN SET source = source - INTERVAL SECOND(source) SECOND; END IF;
  IF field NOT IN ('microsecond', 'millisecond', 'second', 'minute') THEN SET source = source - INTERVAL MINUTE(source) MINUTE; END IF;
  IF field NOT IN ('microsecond', 'millisecond', 'second', 'minute', 'hour') THEN SET source = source - INTERVAL HOUR(source) HOUR; END IF;
  IF field NOT IN ('microsecond', 'millisecond', 'second', 'minute', 'hour', 'day') THEN SET source = source - INTERVAL DAYOFWEEK(source) - 1 DAY; END IF;
  IF field NOT IN ('microsecond', 'millisecond', 'second', 'minute', 'hour', 'day', 'week') THEN SET source = source - INTERVAL DAY(source) - 1 DAY; END IF;
  IF field IN ('quarter') THEN SET source = source - INTERVAL MONTH(source) % 3 - 1 MONTH; END IF;
  IF field NOT IN ('microsecond', 'millisecond', 'second', 'minute', 'hour', 'week', 'day', 'month', 'quarter') THEN SET source = source - INTERVAL MONTH(source) - 1 MONTH; END IF;

  -- Year ranges go from 1 - 10, e.g. 1961-1970, not 1960-1969. The third millenium started 2001, not 2000. If you want it the other way, remove the "- 1" from each of the following.
  IF field IN ('decade') THEN SET source = source - INTERVAL YEAR(source) % 10 - 1 YEAR; END IF;
  IF field IN ('century') THEN SET source = source - INTERVAL YEAR(source) % 100  - 1 YEAR; END IF;
  IF field IN ('millennium') THEN SET source = source - INTERVAL YEAR(source) % 1000 - 1 YEAR; END IF;
 
  RETURN source;
END

When called with the date ‘1996-02-29 12:28:53.123456’, returns the following:

CREATE FUNCTION SWAP_ENDIAN(inString text)
RETURNS TEXT
DETERMINISTIC
-- Expects a hex string: AbCdEf
-- Returns the string swapped for endianness: EfCdAb

BEGIN
  DECLARE position INT DEFAULT 1;
  DECLARE holder TEXT DEFAULT '';

  WHILE position < LENGTH(inString) DO
    SET holder = CONCAT(SUBSTRING(inString, position, 2), holder);
    SET position = position + 2;
  END WHILE;

  RETURN holder;
END

So you can do things like:

SELECT
  FROM_UNIXTIME(
    CONV(
      SWAP_ENDIAN(
        SUBSTRING(
          HEX(
            FROM_BASE64(
              'Yk3XVQ8pAAAAZgAAAGoAAAAAAAQANS4xLjczLWxvZwAAAAAABBAAAAAAAAAAAAAAAA'
              'AAAAAAAAAAAAAAAAAAAAAAAABiTddVEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC'
            )
          ), 1, 8
        )
      ), 16, 10)
  ) AS event_timestamp;

and without creating a table to pass the state around (really just an excuse to use the named locks feature).

DELIMITER //
DROP FUNCTION IF EXISTS SET_BREAKPOINT//
CREATE FUNCTION SET_BREAKPOINT()
RETURNS tinyint
NO SQL
BEGIN
	-- Acquire lock 1
	-- Wait until lock 2 is taken to signal that we may continue
	DO GET_LOCK(CONCAT('lock_1_', CONNECTION_ID()), -1);
	REPEAT
		DO 1;
	UNTIL IS_USED_LOCK(CONCAT('lock_2_', CONNECTION_ID())) END REPEAT;
	DO RELEASE_LOCK(CONCAT('lock_1_', CONNECTION_ID()));

	-- Acquire lock 3 to acknowledge message to continue.
	-- Wait for lock 2 to be released as signal of receipt.
	DO GET_LOCK(CONCAT('lock_3_', CONNECTION_ID()), -1);
	REPEAT
		DO 1;
	UNTIL IS_FREE_LOCK(CONCAT('lock_2_', CONNECTION_ID())) END REPEAT;
	DO RELEASE_LOCK(CONCAT('lock_3_', CONNECTION_ID()));

	RETURN 1;
END//

DROP FUNCTION IF EXISTS NEXT_BREAKPOINT//
CREATE FUNCTION NEXT_BREAKPOINT(connection_id int)
RETURNS tinyint
NO SQL
BEGIN
	-- Acquire lock 2 as a signal to go past the breakpoint
	-- Wait until lock 3 is taken as signal of receipt.
	DO GET_LOCK(CONCAT('lock_2_', connection_id), -1);
	REPEAT
		DO 1;
	UNTIL IS_USED_LOCK(CONCAT('lock_3_', connection_id)) END REPEAT;
	DO RELEASE_LOCK(CONCAT('lock_2_', connection_id));

	RETURN 1;
END//

DROP PROCEDURE IF EXISTS test_the_breakpoints//
CREATE PROCEDURE test_the_breakpoints()
NO SQL
BEGIN
	SELECT CONCAT('In another session: DO NEXT_BREAKPOINT(', CONNECTION_ID(), ');') as `instructions`;

	DO SET_BREAKPOINT();

	SELECT 'do it again' as `now:`;

	DO SET_BREAKPOINT();

	SELECT 'end' as `the`;
END//
DELIMITER ;

CALL test_the_breakpoints();

Sometimes replication halts with an error like:

Slave I/O: Got fatal error 1236 from master when reading data from binary log
Error reading packet from server: log event entry exceeded max_allowed_packet; Increase max_allowed_packet on master;

If it’s the SQL thread instead of the I/O thread, it might complain about ‘Event too big’. The error could also be the other direction, complaining of ‘Event too small’.

I rarely see this error actually have anything to do with max_allowed_packet. You can check the largest event in the master’s binary log file. Even though the binary log records the length in each entry, mysqlbinlog doesn’t expose it, so we have to do the math ourselves:

mysqlbinlog mysql-bin.00XXX | gawk "/^# at / { diff = $3 - prev; prev = $3; } (diff > max) { max = diff } END {print max}" -

If the result is larger than max_allowed_packet, then the problem and solution are exactly what the the error message says. If it’s smaller, or if that also gives you an error about the length, then read on.

Assuming that’s not the problem, here’s what may be happening:

After the 4-byte magic number at the very beginning of the binary log, every entry in the binary log (regardless of the binlog_format) starts with a 19-byte header.

1. 4 bytes for the timestamp
2. 1 byte for the event type
3. 4 bytes for the server_id that wrote the event
4. 4 bytes for the length of the event (including the header)
5. 4 bytes for the position where the next event starts (which should be the position where this event starts plus the length of this event)
6. 2 bytes for some flags that are usually set to 0.

These are all written little-endian. An example:

123e d254 0201 0000 005b 0000 0083 9f3c 3300 00…

4 byte timestamp: 123e d254 = 1423064594 = 2015-02-04 09:43:14 CST
1 byte type code: 02 = QUERY_EVENT
4 byte server id: 01 0000 00 = 1
4 byte length: 5b 0000 00 = 91 bytes
4 byte next pos: 83 9f3c 33 = 859,611,011

Replication works like this:

1. the master executes a statement and records the statement or resulting row events in its binary log
2. the slave’s IO thread says to the master, “I’m at position X. What’s next?”
3. the master reads the binary log and passes the statement or row events to the slave
4. the slave’s IO thread writes what it got from the master into its relay log
5. the slave’s SQL thread reads the relay log and executes the statement or row events

Occasionally, something goes wrong somewhere in that chain:

• Sometimes a piece of the event never makes it into the binary log (the header says “I contain 100 bytes”, but then only 90 bytes appear in the file before the next event begins).
• Sometimes the slave asks the master for the wrong position (someone has been mucking about with CHANGE MASTER TO and using the wrong numbers?)
• Sometimes the event doesn’t make it across the wire from the master to the slave in one piece (network problems?)

However it happens, we end up in the wrong place in the stream of bits, usually somewhere in the middle of the next event’s data section. The slave doesn’t know it’s in the wrong place (there are no sign posts or magic numbers to identify an event), so it just reads the next 19 bytes it sees as if they were the event header. Let’s see what happens when just one byte has gone missing:

123e d254 0201 0000 005b 0000 0083 9f3c 3300

4 byte timestamp: 3ed2 5402 = 39113278 = 1971-03-29 11:47:58 CST
1 byte type code: 01 = START_EVENT_V3
4 byte server id: 0000 005b = 1526726656
4 byte length: 0000 0083 = 2,197,815,296 bytes
4 byte next pos: 9f3c 3300 = 3,357,855

So the slave gets this header and thinks the event length is over 2GB, which is double the highest possible max_allowed_packet, so it throws an error. The real problem isn’t that the event is too big, but that it’s reading the wrong place and interpreting the wrong data as a length.

It would be nice if it would do a sanity check and notice that the current position plus the length doesn’t equal the next position and produce a more helpful error message.

From MySQL 5.6.6 on, by default a checksum is written at the end of each event in the log, which would also catch most of these kinds of errors. But neither the master nor the slave examine those checksums by default. Consider enabling –master-verify-checksum on the master and –slave-sql-verify-checksum on the slave.

How do you fix it?

First check if the master’s binary log is OK. Just run it through mysqlbinlog and redirect the output to NUL or /dev/null. If it makes it through the whole thing with no errors, then the problem is just with the slave’s relay log or file position. If you’re not using GTIDs, then use CHANGE MASTER TO and give it the Exec_Master_Log_Pos from SHOW SLAVE STATUS. It will discard the old relay logs and copy them fresh from the master. Hopefully this time it will get the whole event properly and the problem will go away. If you are using GTIDs, then a RESET SLAVE will discard the relay logs, and when you START SLAVE it will figure out on its own what it needs from the master. If you have to do this frequently, check your network.

If the master’s binary log produces errors when you run it through mysqlbinlog, recovery is not so easy. There have been a few bugs where the master doesn’t record the whole event properly, often having to do with binlogs that exceed 4GB in size. You (or the people you pay for MySQL support) might be able to examine the binary log file, figure out exactly what statement has been corrupted, run it directly on the slave, find the position where the next good event begins, and continue from there. If you can’t recover that statement but you know the tables it affected, you might be able to just copy those few tables from the master to the slave, and have replication ignore them until it catches up to the time of the copy. Or you can use some utility to compare the two servers and fix any differences. Or you can copy all the data from the master and set up the slave again as if it was brand new.

Whatever you do, don’t just set SQL_SLAVE_SKIP_COUNTER=1 or slave_skip_errors and hope the problem goes away. It will only make it worse.