MySQL Bugs: #89122: Severe performance regression in server bootstrap

Bug #89122	Severe performance regression in server bootstrap
Submitted:	5 Jan 2018 16:47	Modified:	16 Jan 2018 16:19
Reporter:	Georgi Kodinov	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: GIS	Severity:	S3 (Non-critical)
Version:	8.0.5	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
> On 12/20/2017 1:03 AM, Deepa Dixit wrote:
>> Hi Norvald,
>>
>>
>> After your commit:
>>
>> commit d0764b98f0f076c6b8b09e377938024633d5ef20
>> Author: Norvald H. Ryeng <norvald.ryeng@oracle.com>
>> Date:   Fri Dec 8 13:01:22 2017 +0100
>>
>>     WL#9059: [7/8] Hide dictionary table and rewrite tests
>>
>>     Hide the mysql.st_spatial_reference_systems table so that it's
>> no longer
>>     possible to do SELECT/INSERT/UPDATE/DELETE operations on it. All
>>     modification of the table has to be done through CREATE/DROP
>> SPATIAL REFERENCE SYSTEM statements.
>>
>>     Hiding the table means that all tests that create spatial
>> reference systems using INSERT statements must be rewritten to use
>> CREATE and DROP
>>     statements.
>>
>>     Some test cases are removed since they now fail in CREATE
>> SPATIAL REFERENCE SYSTEM instead of in each function.
>>
>>     Change-Id: Icf906cb92bb8c57f7b3c946379e06c2810ca4995
>>
>> the "installing system database" part of MTR is taking longer than 
>> usual on Windows. When I reverted your patch locally, the time
>> taken came back to normal.
>>
>> Could you please take a look?

It takes longer than before because we're now using CREATE SPATIAL
REFERENCE SYSTEM statements that (like all other DDL
statements) auto-commit after each statement instead of inserting all
the spatial reference systems with INSERT statements in the same
transaction.

How to repeat:
Try to bootstrap the server on windows and compare the time it takes to complete mtr's "Installing system database..." on older 8.0's to the current 8.0.

Suggested fix:
It should not be slow.
This is executed every time mtr is called and needs to be fast otherwise it will affect the productivity of all developers and the pb2 throughput !

Posted by developer:
 
The regression I see is from 67.7 secs for 8.0.3 to 311.9 secs for 8.0.5. This is about 5 times slower !

I've taken 8.0.3 from the website and have compiled it with debug, similarly to my 8.0 git repo:
cmake -G "Visual Studio 15 2017 Win64" -DWITH_DEBUG=1 -DWITH_EMBEDDED_SERVER=0 -DWITH_SSL=c:/openssl/64bit -DWITH_UNIT_TESTS=0 

I've then tested running the main.1st test case that doesn't do a whole lot.

Here's what I get on my computer:
d:\ade\git\8.0.3\mysql-8.0.3-rc\bld\mysql-test>timeit perl mysql-test-run.pl  1st --timer
Logging: D:/ade/git/8.0.3/mysql-8.0.3-rc/mysql-test/mysql-test-run.pl  1st --timer
MySQL Version 8.0.3
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory 'D:/ade/git/8.0.3/mysql-8.0.3-rc/bld/mysql-test/var'...
Installing system database...
Using parallel: 1

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.1st                                 [ pass ]     32
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.032 of 68 seconds executing testcases

Completed: All 1 tests were successful.

Days              : 0
Hours             : 0
Minutes           : 1
Seconds           : 7
Milliseconds      : 667
Ticks             : 676673711
TotalDays         : 0.000783187165509259
TotalHours        : 0.0187964919722222
TotalMinutes      : 1.12778951833333
TotalSeconds      : 67.6673711
TotalMilliseconds : 67667.3711

d:\ade\git\mysql-8.0\bld\mysql-test>timeit perl mysql-test-run.pl  1st --timer
Logging: D:/ade/git/mysql-8.0/mysql-test/mysql-test-run.pl  1st --timer
2018-01-09T10:55:18.078444Z 0 [System] [MY-010116] D:/ade/git/mysql-8.0/bld/runtime_output_directory/Debug/mysqld.exe (mysqld 8.0.5-debug-log) starting as process 10920 ...
MySQL Version 8.0.5
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Removing old var directory...
Creating var directory 'D:/ade/git/mysql-8.0/bld/mysql-test/var'...
Installing system database...
Using parallel: 1

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.1st                                 [ pass ]     27
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.027 of 312 seconds executing testcases

Completed: All 1 tests were successful.

Days              : 0
Hours             : 0
Minutes           : 5
Seconds           : 11
Milliseconds      : 904
Ticks             : 3119049123
TotalDays         : 0.00361001055902778
TotalHours        : 0.0866402534166667
TotalMinutes      : 5.198415205
TotalSeconds      : 311.9049123
TotalMilliseconds : 311904.9123

FYI, the timeit macro is defined as follows:
timeit=powershell -Command "Measure-Command { $* | out-default}"

Posted by developer:
 
This is the same test, but as run against a ramdrive (r: is a ramdisk on my pc).

Still it's 38 secs for 8.0.3 vs 50 secs on latest mysql-8.0

d:\ade\git\8.0.3\mysql-8.0.3-rc\bld\mysql-test>timeit perl mysql-test-run.pl --vardir=r:/ade/mtr 1st --timer
Logging: D:/ade/git/8.0.3/mysql-8.0.3-rc/mysql-test/mysql-test-run.pl  --vardir=r:/ade/mtr 1st --timer
MySQL Version 8.0.3
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory 'r:/ade/mtr'...
Installing system database...
Using parallel: 1

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.1st                                 [ pass ]     35
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.035 of 38 seconds executing testcases

Completed: All 1 tests were successful.

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 38
Milliseconds      : 219
Ticks             : 382199049
TotalDays         : 0.000442360010416667
TotalHours        : 0.01061664025
TotalMinutes      : 0.636998415
TotalSeconds      : 38.2199049
TotalMilliseconds : 38219.9049

d:\ade\git\mysql-8.0\bld\mysql-test>timeit perl mysql-test-run.pl --vardir=r:/ade/mtr 1st --timer
Logging: D:/ade/git/mysql-8.0/mysql-test/mysql-test-run.pl  --vardir=r:/ade/mtr 1st --timer
2018-01-09T11:04:56.508521Z 0 [System] [MY-010116] D:/ade/git/mysql-8.0/bld/runtime_output_directory/Debug/mysqld.exe (mysqld 8.0.5-debug-log) starting as process 19652 ...
MySQL Version 8.0.5
Checking supported features...
 - SSL connections supported
 - binaries are debug compiled
Collecting tests...
Checking leftover processes...
Removing old var directory...
Creating var directory 'r:/ade/mtr'...
Installing system database...
Using parallel: 1

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
main.1st                                 [ pass ]     28
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.028 of 50 seconds executing testcases

Completed: All 1 tests were successful.

Days              : 0
Hours             : 0
Minutes           : 0
Seconds           : 50
Milliseconds      : 750
Ticks             : 507507543
TotalDays         : 0.000587392989583333
TotalHours        : 0.01409743175
TotalMinutes      : 0.845845905
TotalSeconds      : 50.7507543
TotalMilliseconds : 50750.7543

Posted by developer:
 
For the record the box is a lenovo desktop with the following hardware:
Processor	Intel(R) Core(TM) i7-4770 CPU @ 3.40GHz, 3401 Mhz, 4 Core(s), 8 Logical Processor(s)
Installed Physical Memory (RAM)	16.0 GB
OS Name	Microsoft Windows 10 Pro
Version	10.0.15063 Build 15063
Disk Model	ST1000DM003-1ER162

Posted by developer:
 
Terje and I have looked at this, and the cause seems to be transaction performance on specific file systems.

We've tested:

 1. CREATE statements
 2. INSERT statements in one transaction
 3. INSERT statements in auto-commit mode (5000+ transactions)

We see a slowdown in cases 1 and 3 compared to case 2. The conclusion is that we can rule out slowdown caused by writing through the DD interface. It's the number of transactions that is the problem.

We've also discovered that this depends on the file system. We can reproduce this problem on Linux when using the xfs file system. The reason why I haven't been able to reproduce it, is that I'm using ext4, which is not impacted. Since Windows performance is affected, I assume transactions on NTFS are also slow.

Performance regression in --initialize is just a symptom. The root cause is that transactions are slow on various file systems. Users will experience poor performance also after initialization.

We can replace CREATE SPATIAL REFERENCE SYSTEM statements with INSERT statements to fix the symptom, but the root cause requires a different fix.

Bug#89444 8.0.4rc --initialize-insecure is prohibitively slow

was marked as a duplicate.

Posted by developer:
 
Fixed in 8.0.11.

On some systems, mysqld --initialize to initialize the data directory
was very slow.