Fix fractional timeout values used with WAIT_FOR_EXECUTED_GTID_SET #230

dbussink · 2018-11-15T10:02:29Z

The casting logic here resulted in the timeout double to be cast into a ulonglong before the multiplication happened. This resulted in all timeouts being rounded down to whole seconds.

The behavior is visible with statements like the following:

mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 0.1);
+------------------------------------------------------------------------------+
| WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 0.1) |
+------------------------------------------------------------------------------+
|                                                                            1 |
+------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 0.5);
+------------------------------------------------------------------------------+
| WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 0.5) |
+------------------------------------------------------------------------------+
|                                                                            1 |
+------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 1.0);
+------------------------------------------------------------------------------+
| WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 1.0) |
+------------------------------------------------------------------------------+
|                                                                            1 |
+------------------------------------------------------------------------------+
1 row in set (1.00 sec)

mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 1.5);
+------------------------------------------------------------------------------+
| WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 1.5) |
+------------------------------------------------------------------------------+
|                                                                            1 |
+------------------------------------------------------------------------------+
1 row in set (1.00 sec)

The query execution time here shows the problem. Everything between 0.0 and 1.0 is rounted to a wait time of 0.0 seconds. When using a value in a 1.0 to 2.0 window, it rounds down to 1 seconds as visible in the query execution time.

After this change it works as expected, again visible in the query execution time:

mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 1.0);
+---------------------------------------------------------------------------+
| WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 1.0) |
+---------------------------------------------------------------------------+
|                                                                         1 |
+---------------------------------------------------------------------------+
1 row in set (1.01 sec)

mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 0.5);
+---------------------------------------------------------------------------+
| WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 0.5) |
+---------------------------------------------------------------------------+
|                                                                         1 |
+---------------------------------------------------------------------------+
1 row in set (0.50 sec)

mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 0.1);
+---------------------------------------------------------------------------+
| WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 0.1) |
+---------------------------------------------------------------------------+
|                                                                         1 |
+---------------------------------------------------------------------------+
1 row in set (0.10 sec)

The casting logic here resulted in the timeout double to be cast into a ulonglong before the multiplication happened. This resulted in all timeouts being rounded down to whole seconds. The behavior is visible with statements like the following: mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 0.1); +------------------------------------------------------------------------------+ | WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 0.1) | +------------------------------------------------------------------------------+ | 1 | +------------------------------------------------------------------------------+ 1 row in set (0.00 sec) mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 0.5); +------------------------------------------------------------------------------+ | WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 0.5) | +------------------------------------------------------------------------------+ | 1 | +------------------------------------------------------------------------------+ 1 row in set (0.00 sec) mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 1.0); +------------------------------------------------------------------------------+ | WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 1.0) | +------------------------------------------------------------------------------+ | 1 | +------------------------------------------------------------------------------+ 1 row in set (1.00 sec) mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 1.5); +------------------------------------------------------------------------------+ | WAIT_FOR_EXECUTED_GTID_SET('16d22a8b-e803-11e8-b46f-003d70c354d2:9067', 1.5) | +------------------------------------------------------------------------------+ | 1 | +------------------------------------------------------------------------------+ 1 row in set (1.00 sec) The query execution time here shows the problem. Everything between 0.0 and 1.0 is rounted to a wait time of 0.0 seconds. When using a value in a 1.0 to 2.0 window, it rounds down to 1 seconds as visible in the query execution time. After this change it works as expected, again visible in the query execution time: mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 1.0); +---------------------------------------------------------------------------+ | WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 1.0) | +---------------------------------------------------------------------------+ | 1 | +---------------------------------------------------------------------------+ 1 row in set (1.01 sec) mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 0.5); +---------------------------------------------------------------------------+ | WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 0.5) | +---------------------------------------------------------------------------+ | 1 | +---------------------------------------------------------------------------+ 1 row in set (0.50 sec) mysql> SELECT WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 0.1); +---------------------------------------------------------------------------+ | WAIT_FOR_EXECUTED_GTID_SET('f9702b80-e826-11e8-b833-f64268411190:4', 0.1) | +---------------------------------------------------------------------------+ | 1 | +---------------------------------------------------------------------------+ 1 row in set (0.10 sec)

shlomi-noach · 2018-11-15T10:03:52Z

We were hoping, seeing that this is a simple fix to an existing implementation, that this could find its way into the next [edit: 5.7] GA release. 🙇

dbussink · 2018-11-15T10:05:11Z

We were hoping, seeing that this is a simple fix to an existing implementation, that this could find its way into the next GA release. 🙇

Also ideally this can also be backported to 5.7 (and perhaps even 5.6 where applicable) as well, so we don't have to upgrade everything to 8 before getting the benefits from this fix.

dbussink · 2018-11-15T10:21:37Z

Looks like this was also partially identified in https://bugs.mysql.com/bug.php?id=83537, but not resolved correctly for fractional timeouts.

mysql-oca-bot · 2018-11-15T12:49:59Z

Hi, thank you for submitting this pull request. In order to consider your code we need you to sign the Oracle Contribution Agreement (OCA). Please review the details and follow the instructions at http://www.oracle.com/technetwork/community/oca-486395.html
Please make sure to include your MySQL bug system user (email) in the returned form.
Thanks

mysql-oca-bot · 2018-12-16T12:49:55Z

Hi, there was no response to our request to sign an OCA or confirm the code is submitted under the terms of the OCA. As such this request will be closed.
Thanks

shlomi-noach · 2018-12-16T12:52:38Z

I do believe @dbussink has signed the OCA, and so I'm puzzled on why the bot would close this issue. @dbussink if you wish, I can resubmit, seeing that my account is confirmed to have signed OCA.

dbussink · 2018-12-16T13:55:40Z

I have signed and submitted the OCA on November 26 but have never heard anything back on that.

shlomi-noach · 2018-12-16T14:17:17Z

Oracle people, can you please look into this?

mysql-admin · 2018-12-17T16:36:34Z

@dbussink @shlomi-noach looking into what happened to the OCA - reopening the request
==Omer

mysql-oca-bot · 2018-12-17T16:40:01Z

Hi, thank you for submitting this pull request. In order to consider your code we need you to sign the Oracle Contribution Agreement (OCA). Please review the details and follow the instructions at http://www.oracle.com/technetwork/community/oca-486395.html
Please make sure to include your MySQL bug system user (email) in the returned form.
Thanks

mysql-admin · 2018-12-17T16:40:50Z

Please ignore last OCA request from the bot
==Omer

mysql-oca-bot · 2019-01-17T12:50:22Z

Hi, there was no response to our request to sign an OCA or confirm the code is submitted under the terms of the OCA. As such this request will be closed.
Thanks

shlomi-noach · 2019-01-17T13:27:54Z

Oh please!

mysql-admin · 2019-01-17T13:32:34Z

I hate bots ;-)
BTW, we are waiting for you guys ...
==Omer

shlomi-noach · 2019-01-17T14:43:47Z

Ummm... last I heard we were waiting on Oracle legal...

mysql-admin · 2019-01-17T15:22:15Z

@shlomi-noach email me - omer.barnir@oracle.com - we can discuss there
Thanks
--Omer

mysql-oca-bot · 2019-01-18T12:50:04Z

Hi, thank you for submitting this pull request. In order to consider your code we need you to sign the Oracle Contribution Agreement (OCA). Please review the details and follow the instructions at http://www.oracle.com/technetwork/community/oca-486395.html
Please make sure to include your MySQL bug system user (email) in the returned form.
Thanks

dbussink · 2019-02-07T13:59:44Z

Hi all, it took a while bit from what I have heard the OCA should be set up at this point.

mysql-oca-bot · 2019-02-07T16:01:39Z

Hi, thank you for your contribution. Please confirm this code is submitted under the terms of the OCA (Oracle's Contribution Agreement) you have previously signed by cutting and pasting the following text as a comment:
"I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it."
Thanks

dbussink · 2019-02-07T16:24:53Z

I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

mysql-oca-bot · 2019-02-07T17:38:36Z

Hi, thank you for your contribution. Your code has been assigned to an internal queue. Please follow
bug http://bugs.mysql.com/bug.php?id=94247 for updates.
Thanks

mysql-oca-bot closed this Dec 16, 2018

mysql-admin reopened this Dec 17, 2018

mysql-oca-bot closed this Jan 17, 2019

mysql-admin reopened this Jan 17, 2019

mysql-oca-bot closed this Feb 7, 2019

dbussink mentioned this pull request Oct 15, 2020

RFC: Read After Write vitessio/vitess#6843

Open

6 tasks

Fix fractional timeout values used with WAIT_FOR_EXECUTED_GTID_SET #230

Fix fractional timeout values used with WAIT_FOR_EXECUTED_GTID_SET #230

Uh oh!

Conversation

dbussink commented Nov 15, 2018

Uh oh!

shlomi-noach commented Nov 15, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

dbussink commented Nov 15, 2018

Uh oh!

dbussink commented Nov 15, 2018

Uh oh!

mysql-oca-bot commented Nov 15, 2018

Uh oh!

mysql-oca-bot commented Dec 16, 2018

Uh oh!

shlomi-noach commented Dec 16, 2018

Uh oh!

dbussink commented Dec 16, 2018

Uh oh!

shlomi-noach commented Dec 16, 2018

Uh oh!

mysql-admin commented Dec 17, 2018

Uh oh!

mysql-oca-bot commented Dec 17, 2018

Uh oh!

mysql-admin commented Dec 17, 2018

Uh oh!

mysql-oca-bot commented Jan 17, 2019

Uh oh!

shlomi-noach commented Jan 17, 2019

Uh oh!

mysql-admin commented Jan 17, 2019

Uh oh!

shlomi-noach commented Jan 17, 2019

Uh oh!

mysql-admin commented Jan 17, 2019

Uh oh!

mysql-oca-bot commented Jan 18, 2019

Uh oh!

dbussink commented Feb 7, 2019

Uh oh!

mysql-oca-bot commented Feb 7, 2019

Uh oh!

dbussink commented Feb 7, 2019

Uh oh!

mysql-oca-bot commented Feb 7, 2019

Uh oh!

Uh oh!

shlomi-noach commented Nov 15, 2018 •

edited

Loading