[#MDEV-23326] aria TRANSACTIONAL=1 significantly slow on timezone intialisation (was: time zone initialision significantly slower in 10.4 compared to 10.3 (myisam))

[MDEV-23326] aria TRANSACTIONAL=1 significantly slow on timezone intialisation (was: time zone initialision significantly slower in 10.4 compared to 10.3 (myisam)) Created: 2020-07-29 Updated: 2022-04-21 Resolved: 2022-01-11
Status:	Closed
Project:	MariaDB Server
Component/s:	Scripts & Clients, Storage Engine - Aria
Affects Version/s:	10.4.3, 10.4.13
Fix Version/s:	10.4.23, 10.5.14, 10.6.6, 10.7.2

Type:

Bug

Priority:

Major

Reporter:

Daniel Black

Assignee:

Daniel Black

Resolution:

Fixed

Votes:

Labels:

not-10.1, not-10.2, not-10.3

Attachments:

perf-g-no-children-aria.txt

pod-mariadb-init.sh

Issue Links:

Blocks
is blocked by	MDEV-24268	mtr tests for mysql_install_db	Open
Problem/Incident
causes	~~MDEV-28263~~	mariadb-tzinfo-to-sql binlog, embedde...	Closed
Relates
relates to	~~MDEV-18778~~	mysql_tzinfo_to_sql does not work cor...	Closed
relates to	~~MDEV-20555~~	Transactional Aria tables are slower ...	Closed
relates to	~~MDEV-21209~~	mysql_tzinfo_to_sql's Galera checks d...	Closed
relates to	~~MDEV-23440~~	mysql_tzinfo_to_sql under innodb is slow	Closed
relates to	~~MDEV-27608~~	speed up Docker Library Initializatio...	Closed
relates to	~~MDEV-27074~~	container start-up to take a long time	Closed

Description

From https://github.com/docker-library/mariadb/issues/262.

The reason for the blocker is the number of significant name projects mentioning that issue in the reason they are disabling time zone loading in their product. From openstack, nextcloud. ibis, and these are only the ones mentioning the issue on github. From the performance data below, it used to be quick in 10.3. Its now slow enough to abort startup in many production scenarios for container deployment.

(as of time 10.5.4 corresponds to 10.5)

from attached script:

MariaDB	Plain basic time	without tz init
10.5	0m21.094s	0m4.283s
10.4. {13}	0m22.557s	0m4.553s
10.4.13	0m22.343s
10.4.12	0m22.548s
10.4.11	0m32.815s
10.4.10	0m33.566s
10.4.8	0m29.068s
10.4.7	0m19.067s
10.4.6	0m18.089s
10.4.5	0m18.859s
10.4.4	0m20.296s
10.4.3	0m20.071s
10.3	0m6.305s	0m4.559s
10.2	0m6.289s	0m5.533s
10.1	0m14.059s	0m12.289s

this isn't a factor of the mysql_tzinfo_to_sql script::

10.5.5-ubsan build
[dan@grit build-mariadb-server-10.5-ubsan]$ time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo \| mysql -S /tmp/s.sock mysql
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real 0m21.056s
user 0m0.365s
sys 0m0.204s


(reinitialised the datadir and still using a 10.5 server)
\|build-mariadb-server-10.2-debug]$ time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo \| mysql -S /tmp/s.sock mysql
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real 0m20.688s
user 0m0.283s
sys 0m0.202s

scripts/m*dumpslow /tmp/slow.log \| grep Time= \| grep -v Time=0.0

Reading mysql slow query log from /tmp/slow.log
Count: 1 Time=3.93s (3s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=120290.0 (120290), dan[dan]@localhost
Count: 1 Time=0.32s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=9581.0 (9581), dan[dan]@localhost

10.2.33-debug server version
time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo \| mysql -S /tmp/s.sock -u root mysql
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.
time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo \| mysql -S /tmp/s.sock -u root mysql
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real 0m2.199s
user 0m0.203s
sys 0m0.087s

$ scripts/m*dumpslow /tmp/slow.log \| grep Time= \| grep -v Time=0.0

Reading mysql slow query log from /tmp/slow.log

Count: 1 Time=0.24s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=120290.0 (120290), root[root]@localhost

10.2
CREATE TABLE `time_zone` (
`Time_zone_id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`Use_leap_seconds` enum('Y','N') NOT NULL DEFAULT 'N',
PRIMARY KEY (`Time_zone_id`)
) ENGINE=MyISAM AUTO_INCREMENT=1784 DEFAULT CHARSET=utf8 COMMENT='Time zones'

10.5
CREATE TABLE `time_zone` (
`Time_zone_id` int(10) unsigned NOT NULL AUTO_INCREMENT,
`Use_leap_seconds` enum('Y','N') NOT NULL DEFAULT 'N',
PRIMARY KEY (`Time_zone_id`)
) ENGINE=Aria DEFAULT CHARSET=utf8 PAGE_CHECKSUM=1 TRANSACTIONAL=1 COMMENT='Time zones'

Comments

Comment by Daniel Black [ 2020-07-29 ]

MariaDB [mysql]> select version();

+--------------------------+

| version()                |

+--------------------------+

| 10.5.5-MariaDB-debug-log |

+--------------------------+

1 row in set (0.001 sec)

MariaDB [mysql]> alter table time_zone  ENGINE=MyISAM;

Query OK, 0 rows affected, 1 warning (0.010 sec)

Records: 0  Duplicates: 0  Warnings: 1

MariaDB [mysql]> alter table time_zone_leap_seconds  ENGINE=MyISAM;

ERROR 1146 (42S02): Table 'mysql.time_zone_leap_seconds' doesn't exist

MariaDB [mysql]> alter table time_zone_leap_second  ENGINE=MyISAM;

Query OK, 0 rows affected, 1 warning (0.009 sec)

Records: 0  Duplicates: 0  Warnings: 1

MariaDB [mysql]> alter table time_zone_name  ENGINE=MyISAM;

Query OK, 0 rows affected, 1 warning (0.009 sec)

Records: 0  Duplicates: 0  Warnings: 1

MariaDB [mysql]> alter table time_zone_transition ENGINE=MyISAM;

Query OK, 0 rows affected, 1 warning (0.002 sec)

Records: 0  Duplicates: 0  Warnings: 1

MariaDB [mysql]> alter table time_zone_transition_type ENGINE=MyISAM;

Query OK, 0 rows affected, 1 warning (0.009 sec)

Records: 0  Duplicates: 0  Warnings: 1

MariaDB [mysql]> show warnings;

+---------+------+------------------------------------------------------------------------------------+

| Level   | Code | Message                                                                            |

+---------+------+------------------------------------------------------------------------------------+

| Warning | 1478 | Table storage engine 'MyISAM' does not support the create option 'TRANSACTIONAL=1' |

+---------+------+------------------------------------------------------------------------------------+

1 row in set (0.007 sec)

build-mariadb-server-10.2-debug]$ time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo | mysql -S /tmp/s.sock   mysql

Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.

Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real	0m8.733s

user	0m0.302s

sys	0m0.158

So MyISAM bring it back from 20 seconds to 8

Comment by Daniel Black [ 2020-07-29 ]

known good version looking a docker-library issue is before 10.4.8

Comment by Geoff Montee (Inactive) [ 2020-07-29 ]

This problem seemed to pop up around the same time that this bug was fixed: ~~MDEV-18778~~

In the original fix for ~~MDEV-18778~~, its Galera checks were broken. I reported ~~MDEV-21209~~ with the hope that the Docker performance issues would go away when the checks worked properly, but apparently the performance issues are still there.

Comment by Daniel Black [ 2020-07-30 ]

Looking again it seems to be all of 10.4 (when MyISAM got changed to Aria, but its probably something more than that).

Tested locally on a 10.4.13-relwithdebinfo and 10.4-92499ae95ce(pre.14) and both where < 2 seconds (with and without --skip-write-binlog ) with/without binlog too.

build-mariadb-server-10.4-upstream]$ time perf record -g -o /tmp/10.4.13.perf -p $(pidof mysqld) --  sql/mysql_tzinfo_to_sql --skip-write-binlog  /usr/share/zoneinfo | mysql -S /tmp/s.sock mysql

Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.

Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

[ perf record: Woken up 1 times to write data ]

[ perf record: Captured and wrote 0.373 MB /tmp/10.4.13.perf (4706 samples) ]

real	0m1.400s

user	0m0.190s

sys	0m0.095s

Debug builds are a bit slower at 10 seconds, which still doesn't match the container startup times of ~20s

Comment by Daniel Black [ 2020-07-31 ]

use volume tmpfs
mkdir -p /tmp/datadir
+ mkdir -p /tmp/datadir
podman unshare chown 999:999 -R /tmp/datadir
+ podman unshare chown 999:999 -R /tmp/datadir

+ podman run -d --rm -e MYSQL_ROOT_PASSWORD=pass -p 3306:3306/tcp --volume /tmp/datadir:/var/lib/mysql:Z --name maria mariadb:10.4.13
32c899820f6375c3a78124fb5fc9edd3074fb3c6fd7f6737af326b8f666aa5f3
+ grep -iq 'ready for start up' /dev/fd/63
++ podman logs -f maria

real 0m6.791s
user 0m0.000s
sys 0m0.002s

with no volume specified::

default container / mount
$ podman exec maria mount
fuse-overlayfs on / type fuse.fuse-overlayfs (rw,nodev,noatime,user_id=0,group_id=0,default_permissions,allow_other)
...

myisam initialized
podman run -d --rm -e MYSQL_ROOT_PASSWORD=pass -p 3306:3306/tcp -e MYSQL_INITDB_SKIP_TZINFO=1 --name maria mariadb:10.4.13

$ mysql -u root -ppass -P 3306 -h 127.0.0.1

MariaDB [mysql]> alter table time_zone engine=myisam;
Query OK, 0 rows affected, 1 warning (0.020 sec)
Records: 0 Duplicates: 0 Warnings: 1

MariaDB [mysql]> alter table time_zone_name engine=myisam;
Query OK, 0 rows affected, 1 warning (0.027 sec)
Records: 0 Duplicates: 0 Warnings: 1

MariaDB [mysql]> alter table time_zone_leap_second engine=myisam;
Query OK, 0 rows affected, 1 warning (0.027 sec)
Records: 0 Duplicates: 0 Warnings: 1
MariaDB [mysql]> alter table time_zone_transition engine=myisam;
Query OK, 0 rows affected, 1 warning (0.028 sec)
Records: 0 Duplicates: 0 Warnings: 1

MariaDB [mysql]> alter table time_zone_transition_type engine=myisam;
Query OK, 0 rows affected, 1 warning (0.028 sec)
Records: 0 Duplicates: 0 Warnings: 1

MariaDB [(none)]> set global slow_query_log=ON, global long_query_time=0;
Query OK, 0 rows affected (0.011 sec)

$ time sql/mysql_tzinfo_to_sql --skip-write-binlog /usr/share/zoneinfo \| mysql -u root -ppass -P 3306 -h 127.0.0.1 mysql
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real 0m1.441s
user 0m0.149s
sys 0m0.142s

aria
(clean restart of container above without altering tables)
$ time sql/mysql_tzinfo_to_sql --skip-write-binlog /usr/share/zoneinfo \| mysql -u root -ppass -P 3306 -h 127.0.0.1 mysql
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real 0m19.244s
user 0m0.625s
sys 0m0.839

On the slow query logs:

aria slow query log
$ scripts/mysqldumpslow /tmp/aria-slow.log \| grep Time=

Reading mysql slow query log from /tmp/aria-slow.log
Count: 1 Time=0.16s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=120290.0 (120290), root[root]@[127.0.0.1]
Count: 1 Time=0.06s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=9581.0 (9581), root[root]@[127.0.0.1]
Count: 1 Time=0.01s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), root[root]@[127.0.0.1]
Count: 21 Time=0.01s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=243.0 (5103), root[root]@[127.0.0.1]
Count: 13 Time=0.01s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=236.0 (3068), root[root]@[127.0.0.1]
...

myisam slow query log
$ scripts/mysqldumpslow /tmp/myisam-slow.log \| grep Time=

Reading mysql slow query log from /tmp/myisam-slow.log
Count: 1 Time=0.09s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=120290.0 (120290), root[root]@[127.0.0.1]
Count: 1 Time=0.01s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=9581.0 (9581), root[root]@[127.0.0.1]
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), root[root]@[127.0.0.1]
Count: 3 Time=0.00s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=186.0 (558), root[root]@[127.0.0.1]
Count: 6 Time=0.00s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=229.0 (1374), root[root]@[127.0.0.1]
Count: 21 Time=0.00s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=243.0 (5103), root[root]@[127.0.0.1]
Count: 3 Time=0.00s (0s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=127.0 (381), root[root]@[127.0.0.1]

So, Aria is slow on fuse-overlayfs, but not in any particular query.

Comment by Daniel Black [ 2020-08-01 ]

forcing mysql_tzinfo_to_sql to use InnoDB for the transition was worse (30 seconds).

basic fuse-overlayfs on tmpfs insufficent to reproduce
mkdir /tmp/datadir
mkdir /tmp/datadir_lower
mkdir /tmp/datadir_work
mkdir /tmp/datadir_upper
fuse-overlayfs -o lowerdir=/tmp/datadir_lower -o upperdir=/tmp/datadir_upper -o workdir=/tmp/datadir_work /tmp/datadir
scripts/mysql_install_db --no-defaults --srcdir=${OLDPWD} --builddir=${PWD} --datadir=/tmp/datadir --log-bin=/tmp/datadir/mysqlbin --verbose
sql/mysqld --no-defaults --skip-networking --datadir=/tmp/datadir --log-bin=/tmp/datadir/mysqlbin --socket /tmp/s.sock --lc-messages-dir=${PWD}/sql/share --verbose

[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo \| mysql -S /tmp/s.sock mysql
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real 0m1.661s
user 0m0.139s
sys 0m0.068s

[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ time sql/mysql_tzinfo_to_sql --skip-write-binlog /usr/share/zoneinfo \| mysql -S /tmp/s.sock mysql
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real 0m1.705s
user 0m0.135s
sys 0m0.087s

On a home partition (ext4/lvm/nvme) is sufficient to reproduce problem without a container.

"fuse-overlayfs on /home/"
]$ mkdir /home/dan/datadir /home/dan/datadir_lower /home/dan/datadir_upper /home/dan/datadir_work
$ fuse-overlayfs -o lowerdir=~//datadir_lower -o upperdir=~/datadir_upper -o workdir=~/datadir_work ~/datadir


fuse-overlayfs on /home/dan/datadir type fuse.fuse-overlayfs (rw,nosuid,nodev,relatime,user_id=1000,group_id=1000,default_permissions)
$ time sudo perf record -g -a -o /tmp/perfdir/all.perf -- sql/mysql_tzinfo_to_sql --skip-write-binlog /usr/share/zoneinfo \| mysql -S /tmp/s.sock mysql
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.
[ perf record: Woken up 74 times to write data ]
[ perf record: Captured and wrote 20.089 MB /tmp/perfdir/all.perf (158892 samples) ]

real 0m21.173s
user 0m0.928s
sys 0m0.855s

Comment by Daniel Black [ 2020-08-01 ]

vfscount system wide during load+
$ sudo /usr/share/bcc/tools/vfscount 16
cannot attach kprobe, Invalid argument
Tracing... Ctrl-C to end.

ADDR FUNC COUNT
ffffffffb932f851 b'vfs_readlink' 6
ffffffffb931d131 b'vfs_readv' 21
ffffffffb9321e21 b'vfs_statx_fd' 1783
ffffffffb9321fd1 b'vfs_statx' 8209
ffffffffb9321671 b'vfs_getattr_nosec' 9941
ffffffffb9347ec1 b'vfs_getxattr_alloc' 12939
ffffffffb9347141 b'vfs_getxattr' 12939
ffffffffb9318471 b'vfs_open' 14846
ffffffffb931c861 b'vfs_write' 23892
ffffffffb931b161 b'vfs_writev' 32041
ffffffffb931c581 b'vfs_read' 40461

compared to myisam during same load (that took ~4 seconds)
$ mysql -S /tmp/s.sock mysql -e "alter table time_zone engine=myisam;alter table time_zone_name engine=myisam; alter table time_zone_leap_second engine=myisam; alter table time_zone_transition engine=myisam;"
$ sudo /usr/share/bcc/tools/vfscount 4
cannot attach kprobe, Invalid argument
Tracing... Ctrl-C to end.

ADDR FUNC COUNT
ffffffffb9357b71 b'vfs_statfs.part.0.isra.0' 2
ffffffffb931d131 b'vfs_readv' 7
ffffffffb932b331 b'vfs_unlink' 21
ffffffffb932c521 b'vfs_rename' 30
ffffffffb9321e21 b'vfs_statx_fd' 1773
ffffffffb9321fd1 b'vfs_statx' 3684
ffffffffb9321671 b'vfs_getattr_nosec' 5247
ffffffffb9347ec1 b'vfs_getxattr_alloc' 68578
ffffffffb9347141 b'vfs_getxattr' 69162
ffffffffb9318471 b'vfs_open' 70756
ffffffffb931b161 b'vfs_writev' 71550
ffffffffb931c861 b'vfs_write' 74252
ffffffffb931c581 b'vfs_read' 202059

kernel version: 5.7.10-201.fc32.x86_64

Comment by Daniel Black [ 2020-08-04 ]

moving aria_log off overlayfs restores performance
datadir]$ ls -la
total 137128
drwxrwxr-x. 5 dan dan 4096 Aug 4 20:42 .
lrwxrwxrwx. 1 dan dan 22 Aug 4 20:42 aria_log.00000001 -> /tmp/aria_log.00000001
lrwxrwxrwx. 1 dan dan 21 Aug 4 20:42 aria_log_control -> /tmp/aria_log_control

( time sql/mysql_tzinfo_to_sql --skip-write-binlog /usr/share/zoneinfo \| mysql -S /tmp/s.sock mysql_container_load_time_zone)
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real 0m2.059s
user 0m0.181s
sys 0m0.082s

Having the mysql aria tables on overlayfs is only marginly slower

 ( time  sql/mysql_tzinfo_to_sql --skip-write-binlog  /usr/share/zoneinfo |  mysql -S /tmp/s.sock mysql)

Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.

Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real	0m2.645s

user	0m0.213s

sys	0m0.105s

Comment by Daniel Black [ 2020-08-05 ]

disable transaction on aria during load restores performance
$ more ../aria_p*
::::::::::::::
../aria_post.sql
::::::::::::::

alter table time_zone transactional=1;
alter table time_zone_leap_second transactional=1;
alter table time_zone_name transactional=1;
alter table time_zone_transition transactional=1;
alter table time_zone_transition_type transactional=1;
::::::::::::::
../aria_pre.sql
::::::::::::::

alter table time_zone transactional=0;
alter table time_zone_leap_second transactional=0;
alter table time_zone_name transactional=0;
alter table time_zone_transition transactional=0;
alter table time_zone_transition_type transactional=0;

$ time ( cat ../aria_pre.sql; sql/mysql_tzinfo_to_sql --skip-write-binlog /usr/share/zoneinfo; cat ../aria_post.sql ) \| mysql -S /tmp/s.sock mysql
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.

real 0m1.732s
user 0m0.143s
sys 0m0.067s

Comment by Daniel Black [ 2020-08-05 ]

So disabling by transaction=0 is just disabling the crash safety.

timings on potential crash mitigation
$ time client/mysqlcheck -S /tmp/s.sock mysql time_zone time_zone_leap_second time_zone_name time_zone_transition time_zone_transition_type
mysql.time_zone OK
mysql.time_zone_leap_second OK
mysql.time_zone_name OK
mysql.time_zone_transition OK
mysql.time_zone_transition_type OK

real 0m0.040s
user 0m0.008s
sys 0m0.008s

Comment by Daniel Black [ 2020-08-05 ]

proof of concept code:

https://github.com/MariaDB/server/compare/10.4...grooverdan:10.4-MDEV-23326-mysql-tzinfo-aria-slow?expand=1

POC tz initialization during bootstrap (with transactions disabled)

[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ rm -rf /home/dan/datadir/*
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ time scripts/mysql_install_db --no-defaults --srcdir=${OLDPWD} --builddir=${PWD} --datadir=/home/dan/datadir --log-bin=/home/dan/datadir/mysqlbin --verbose --timezones
Installing MariaDB/MySQL system tables in '/home/dan/datadir' ...
2020-08-05 18:10:21 0 [Note] /home/dan/repos/build-mariadb-server-10.4-RelWithDebugInfo/sql/mysqld (mysqld 10.4.14-MariaDB-log) starting as process 54771 ...
2020-08-05 18:10:21 0 [Note] InnoDB: Using Linux native AIO
2020-08-05 18:10:21 0 [Note] InnoDB: The first innodb_system data file 'ibdata1' did not exist. A new tablespace will be created!
2020-08-05 18:10:21 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-08-05 18:10:21 0 [Note] InnoDB: Uses event mutexes
2020-08-05 18:10:21 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-08-05 18:10:21 0 [Note] InnoDB: Number of pools: 1
2020-08-05 18:10:21 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-08-05 18:10:21 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
2020-08-05 18:10:21 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2020-08-05 18:10:21 0 [Note] InnoDB: Completed initialization of buffer pool
2020-08-05 18:10:21 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-08-05 18:10:21 0 [Note] InnoDB: Setting file './ibdata1' size to 12 MB. Physically writing the file full; Please wait ...
2020-08-05 18:10:21 0 [Note] InnoDB: File './ibdata1' size is now 12 MB.
2020-08-05 18:10:21 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes
2020-08-05 18:10:21 0 [Note] InnoDB: Setting log file ./ib_logfile1 size to 50331648 bytes
2020-08-05 18:10:21 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2020-08-05 18:10:21 0 [Note] InnoDB: New log files created, LSN=11451
2020-08-05 18:10:21 0 [Note] InnoDB: Doublewrite buffer not found: creating new
2020-08-05 18:10:21 0 [Note] InnoDB: Doublewrite buffer created
2020-08-05 18:10:21 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-08-05 18:10:21 0 [Note] InnoDB: Creating foreign key constraint system tables.
2020-08-05 18:10:21 0 [Note] InnoDB: Creating tablespace and datafile system tables.
2020-08-05 18:10:21 0 [Note] InnoDB: Creating sys_virtual system tables.
2020-08-05 18:10:21 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-08-05 18:10:21 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-08-05 18:10:21 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-08-05 18:10:21 0 [Note] InnoDB: Waiting for purge to start
2020-08-05 18:10:22 0 [Note] InnoDB: 10.4.14 started; log sequence number 0; transaction id 7
2020-08-05 18:10:22 6 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1017: Can't find file: './mysql/' (errno: 2 "No such file or directory")
Warning: Unable to load '/usr/share/zoneinfo/leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo/tzdata.zi' as time zone. Skipping it.
OK

real 0m4.220s
user 0m0.975s
sys 0m0.329s

GeoffMontee, jplindst, above is really early POC code. Tests will be added. Please let me know if your happy with the concept of extending mysql_install_db and/or mysql_zoneinfo_to_sql.

Comment by Geoff Montee (Inactive) [ 2020-08-05 ]

Hi danblack,

I don't have a problem with your implementation, but I am not sure that my opinion about this holds much weight. You might want to check with someone like serg.

I originally suggested that we should convert these tables to InnoDB to fix ~~MDEV-18778~~, but engineering decided to keep using Aria for these tables.

Comment by Daniel Black [ 2020-08-06 ]

Docker library work around submitted - https://github.com/docker-library/mariadb/pull/320

Comment by Daniel Black [ 2020-08-10 ]

overflayfs fresh initialization
[dan@grit ~]$ fusermount -u datadir
[dan@grit ~]$ rm -rf datadir/
[dan@grit ~]$ fuse-overlayfs -o lowerdir=~//datadir_lower -o upperdir=~/datadir_upper -o workdir=~/datadir_work ~/datadir
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ time scripts/mysql_install_db --no-defaults --srcdir=${OLDPWD} --builddir=${PWD} --datadir=/home/dan/datadir --log-bin=/home/dan/datadir/mysqlbin --verbose
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ sql/mysqld --no-defaults --skip-networking --datadir=/home/dan/datadir --log-bin=/home/dan/datadir/mysqlbin --socket /tmp/s.sock --lc-messages-dir=${PWD}/sql/share --verbose
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ client/mysql -S /tmp/s.sock < ../aria_non_transactional.sql
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ cat ../aria_non_transactional.sql


create database if not exists aria_non_transactional;
use aria_non_transactional;

create table time_zone like mysql.time_zone ;
create table time_zone_leap_second like mysql.time_zone_leap_second ;
create table time_zone_name like mysql.time_zone_name ;
create table time_zone_transition like mysql.time_zone_transition ;
create table time_zone_transition_type like mysql.time_zone_transition_type;

alter table time_zone transactional=0;
alter table time_zone_leap_second transactional=0;
alter table time_zone_name transactional=0;
alter table time_zone_transition transactional=0;
alter table time_zone_transition_type transactional=0;

[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo/ > /dev/null
Warning: Unable to load '/usr/share/zoneinfo//leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo//tzdata.zi' as time zone. Skipping it.

real 0m0.029s
user 0m0.021s
sys 0m0.007s

overlayfs aria T=1
$ sudo //usr/share/bcc/tools/biolatency -F -Q & PID=$! ; sleep 4; time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo/ \| client/mysql -S /tmp/s.sock mysql ; sudo kill -INT $PID
[2] 61204
Tracing block device I/O... Hit Ctrl-C to end.
Warning: Unable to load '/usr/share/zoneinfo//leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo//tzdata.zi' as time zone. Skipping it.

real 0m20.554s
user 0m0.769s
sys 0m0.537s


flags = Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 1 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 50 \|****************************************\|
1024 -> 2047 : 0 \| \|
2048 -> 4095 : 5 \|**** \|

flags = Background-Priority-Metadata-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 1 \|*** \|
64 -> 127 : 0 \| \|
128 -> 255 : 11 \|****************************************\|
256 -> 511 : 0 \| \|
512 -> 1023 : 7 \|************************* \|
1024 -> 2047 : 0 \| \|
2048 -> 4095 : 7 \|************************* \|
4096 -> 8191 : 10 \|************************************ \|

flags = Background-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 1 \|****************************************\|
64 -> 127 : 0 \| \|
128 -> 255 : 1 \|****************************************\|
256 -> 511 : 0 \| \|
512 -> 1023 : 1 \|****************************************\|
1024 -> 2047 : 0 \| \|
2048 -> 4095 : 1 \|****************************************\|

flags = NoMerge-Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 0 \| \|
256 -> 511 : 4 \|****************************************\|
512 -> 1023 : 2 \|******************** \|
1024 -> 2047 : 2 \|******************** \|

flags = Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 181 \|* \|
16 -> 31 : 628 \|*** \|
32 -> 63 : 5592 \|******************************* \|
64 -> 127 : 1963 \|*********** \|
128 -> 255 : 13 \| \|
256 -> 511 : 1 \| \|
512 -> 1023 : 7017 \|****************************************\|
1024 -> 2047 : 11 \| \|
2048 -> 4095 : 40 \| \|
4096 -> 8191 : 6 \| \|

flags = ForcedUnitAccess-Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 0 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 0 \| \|
1024 -> 2047 : 1287 \|****************************************\|
2048 -> 4095 : 2 \| \|
4096 -> 8191 : 3 \| \|

overlayfs aria T=0
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ sudo //usr/share/bcc/tools/biolatency -F -Q & PID=$! ; sleep 4; time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo/ \| client/mysql -S /tmp/s.sock aria_non_transactional ; sudo kill -INT $PID
[2] 61246
Tracing block device I/O... Hit Ctrl-C to end.
Warning: Unable to load '/usr/share/zoneinfo//leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo//tzdata.zi' as time zone. Skipping it.

real 0m1.106s
user 0m0.129s
sys 0m0.063s


flags = Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 1 \|** \|
16 -> 31 : 3 \|******** \|
32 -> 63 : 6 \|**************** \|
64 -> 127 : 7 \|****************** \|
128 -> 255 : 0 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 15 \|****************************************\|
1024 -> 2047 : 2 \|***** \|
2048 -> 4095 : 2 \|***** \|
4096 -> 8191 : 2 \|***** \|

flags = NoMerge-Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 1 \|************* \|
256 -> 511 : 3 \|****************************************\|
512 -> 1023 : 1 \|************* \|
1024 -> 2047 : 1 \|************* \|
2048 -> 4095 : 1 \|************* \|

flags = ForcedUnitAccess-Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 0 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 0 \| \|
1024 -> 2047 : 13 \|****************************************\|

change to non-overlayfs
[dan@grit ~]$ fusermount -u datadir
[dan@grit ~]$ rm -rf datadir/
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ time scripts/mysql_install_db --no-defaults --srcdir=${OLDPWD} --builddir=${PWD} --datadir=/home/dan/datadir --log-bin=/home/dan/datadir/mysqlbin --verbose
Installing MariaDB/MySQL system tables in '/home/dan/datadir' ...
2020-08-10 14:42:25 0 [Note] /home/dan/repos/build-mariadb-server-10.4-RelWithDebugInfo/sql/mysqld (mysqld 10.4.14-MariaDB-log) starting as process 61953 ...
..
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ sql/mysqld --no-defaults --skip-networking --datadir=/home/dan/datadir --log-bin=/home/dan/datadir/mysqlbin --socket /tmp/s.sock --lc-messages-dir=${PWD}/sql/share --verbose
2020-08-10 14:42:35 0 [Note] sql/mysqld (mysqld 10.4.14-MariaDB-log) starting as process 61988 ...
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ client/mysql -S /tmp/s.sock < ../aria_non_transactional.sql

non-overlayfs aria T=1
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ sudo //usr/share/bcc/tools/biolatency -F -Q & PID=$! ; sleep 4; time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo/ \| client/mysql -S /tmp/s.sock mysql ; sudo kill -INT $PID
[3] 62063
Tracing block device I/O... Hit Ctrl-C to end.
Warning: Unable to load '/usr/share/zoneinfo//leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo//tzdata.zi' as time zone. Skipping it.

real 0m17.315s
user 0m0.597s
sys 0m0.493s


flags = Background-Priority-Metadata-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 13 \|**************************** \|
64 -> 127 : 14 \|******************************* \|
128 -> 255 : 0 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 18 \|****************************************\|

flags = Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 22 \| \|
16 -> 31 : 1058 \|****** \|
32 -> 63 : 4999 \|**************************** \|
64 -> 127 : 2271 \|************ \|
128 -> 255 : 14 \| \|
256 -> 511 : 5 \| \|
512 -> 1023 : 6998 \|****************************************\|
1024 -> 2047 : 18 \| \|
2048 -> 4095 : 48 \| \|
4096 -> 8191 : 4 \| \|

flags = Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 1 \|* \|
64 -> 127 : 19 \|******************* \|
128 -> 255 : 39 \|****************************************\|
256 -> 511 : 1 \|* \|
512 -> 1023 : 4 \|**** \|

flags = NoMerge-Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 3 \|*************** \|
256 -> 511 : 8 \|****************************************\|
512 -> 1023 : 8 \|****************************************\|
1024 -> 2047 : 3 \|*************** \|

flags = Background-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 1 \|******************** \|
64 -> 127 : 0 \| \|
128 -> 255 : 0 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 2 \|****************************************\|

flags = ForcedUnitAccess-Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 0 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 0 \| \|
1024 -> 2047 : 1286 \|****************************************\|
2048 -> 4095 : 2 \| \|
4096 -> 8191 : 1 \| \|

non-overlayfs aria T=0
[dan@grit build-mariadb-server-10.4-RelWithDebugInfo]$ sudo //usr/share/bcc/tools/biolatency -F -Q & PID=$! ; sleep 4; time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo/ \| client/mysql -S /tmp/s.sock aria_non_transactional ; sudo kill -INT $PID
[4] 62082
Tracing block device I/O... Hit Ctrl-C to end.
[3] Done sudo //usr/share/bcc/tools/biolatency -F -Q
Warning: Unable to load '/usr/share/zoneinfo//leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo//tzdata.zi' as time zone. Skipping it.

real 0m0.888s
user 0m0.133s
sys 0m0.073s


flags = NoMerge-Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 3 \|******************** \|
256 -> 511 : 6 \|****************************************\|
512 -> 1023 : 6 \|****************************************\|
1024 -> 2047 : 1 \|****** \|
2048 -> 4095 : 2 \|************* \|

flags = Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 1 \|***** \|
256 -> 511 : 1 \|***** \|
512 -> 1023 : 0 \| \|
1024 -> 2047 : 0 \| \|
2048 -> 4095 : 0 \| \|
4096 -> 8191 : 8 \|****************************************\|

flags = Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 2 \|***** \|
32 -> 63 : 8 \|********************** \|
64 -> 127 : 9 \|************************* \|
128 -> 255 : 1 \|** \|
256 -> 511 : 3 \|******** \|
512 -> 1023 : 14 \|****************************************\|
1024 -> 2047 : 1 \|** \|
2048 -> 4095 : 4 \|*********** \|
4096 -> 8191 : 1 \|** \|

flags = ForcedUnitAccess-Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 0 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 0 \| \|
1024 -> 2047 : 11 \|****************************************\|

flags = Background-Priority-Metadata-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 0 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 0 \| \|
1024 -> 2047 : 0 \| \|
2048 -> 4095 : 0 \| \|
4096 -> 8191 : 7 \|****************************************\|

flags = Background-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 0 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 0 \| \|
1024 -> 2047 : 0 \| \|
2048 -> 4095 : 0 \| \|
4096 -> 8191 : 1 \|****************************************\|

Summary of above times:

Aria load time of timezones (seconds)

	T=1	T=0
Overlays	20.554	1.106
ext4	17.315	0.888

mysql_tzinfo_to_sql stats
$ time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo/ \| grep ^INSERT \| wc -l
Warning: Unable to load '/usr/share/zoneinfo//leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo//tzdata.zi' as time zone. Skipping it.
6991

for i in $( client/mysql -S /tmp/s.sock -ABNe "show tables like 'time_%'" mysql); do echo -n "$i: "; client/mysql -S /tmp/s.sock -ABNe "select count(*) from mysql.$i;"; done
time_zone: 1783
time_zone_leap_second: 0
time_zone_name: 1783
time_zone_transition: 120290
time_zone_transition_type: 9581

So ~7k inserts and 2 ALTER TABLE time_zone_transition* ORDER BY requires 15k Sync Writes with TRANSACTION=1. Comments monty?

Comment by Daniel Black [ 2020-08-10 ]

With mysql_tzinfo_to_sql that is patched actually uses innodb and start transaction and COMMIT

non-overlayfs innodb T=1

$ sudo //usr/share/bcc/tools/biolatency -F -Q & PID=$! ; sleep 4; ( time sql/mysql_tzinfo_to_sql /usr/share/zoneinfo/ ;) \| client/mysql -S /tmp/s.sock innodb ; sudo kill -INT $PID
[6] 69433
Tracing block device I/O... Hit Ctrl-C to end.
[5] Done sudo //usr/share/bcc/tools/biolatency -F -Q
Warning: Unable to load '/usr/share/zoneinfo//leapseconds' as time zone. Skipping it.
Warning: Unable to load '/usr/share/zoneinfo//tzdata.zi' as time zone. Skipping it.

real 0m1.229s
user 0m0.059s
sys 0m0.027s


flags = Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 4 \| \|
16 -> 31 : 86 \|************** \|
32 -> 63 : 130 \|********************* \|
64 -> 127 : 89 \|************** \|
128 -> 255 : 9 \|* \|
256 -> 511 : 2 \| \|
512 -> 1023 : 239 \|****************************************\|
1024 -> 2047 : 7 \|* \|
2048 -> 4095 : 1 \| \|
4096 -> 8191 : 2 \| \|

flags = Background-Priority-Metadata-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 17 \|****************************************\|
128 -> 255 : 8 \|****************** \|

flags = ForcedUnitAccess-Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 0 \| \|
256 -> 511 : 0 \| \|
512 -> 1023 : 0 \| \|
1024 -> 2047 : 233 \|****************************************\|

flags = NoMerge-Sync-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 0 \| \|
128 -> 255 : 0 \| \|
256 -> 511 : 3 \|***************** \|
512 -> 1023 : 5 \|**************************** \|
1024 -> 2047 : 7 \|****************************************\|

flags = Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 1 \|************* \|
64 -> 127 : 3 \|****************************************\|

flags = Background-Write
usecs : count distribution
0 -> 1 : 0 \| \|
2 -> 3 : 0 \| \|
4 -> 7 : 0 \| \|
8 -> 15 : 0 \| \|
16 -> 31 : 0 \| \|
32 -> 63 : 0 \| \|
64 -> 127 : 1 \|****************************************\|

Not quite the 0m0.864s that MyISAM was however 0m1.229s is much better than Aria (T=1) and not significantly worse thatn Aria (T=0, 0.888s)

Comment by Daniel Black [ 2020-08-13 ]

$ sql/mysql_tzinfo_to_sql   /usr/share/zoneinfo/  | grep '^[A-Z]' | grep -v ^SET  |  uniq -c --check-chars=5

      1 IF (select count(*) from information_schema.global_variables where

      4 ALTER TABLE time_zone ENGINE=InnoDB;

      1 END IF|

      4 TRUNCATE TABLE time_zone;

      1 START TRANSACTION;

Warning: Unable to load '/usr/share/zoneinfo//leapseconds' as time zone. Skipping it.

Warning: Unable to load '/usr/share/zoneinfo//tzdata.zi' as time zone. Skipping it.

   6991 INSERT INTO time_zone (Use_leap_seconds) VALUES ('N');

      1 COMMIT;

      2 ALTER TABLE time_zone_transition ORDER BY Time_zone_id, Transition_time;

      1 IF (select count(*) from information_schema.global_variables where

      4 ALTER TABLE time_zone ENGINE=Aria;

      1 END IF|

10.5.(pre)6-5eff7c022608af69c5f3591326e2be5132033977
bpftrace -e 'tracepoint:syscalls:sys_enter_fdatasync { @start[args->fd] = nsecs; @fd = args->fd} tracepoint:syscalls:sys_exit_fdatasync { @us[ustack, @fd] = hist((nsecs - @start[@fd]) / 1000); delete(@start[@fd]) } ' -p 331087

...
@us[
fdatasync+59
translog_sync_files+228
translog_flush+1282
ma_commit+80
ha_maria::external_lock(THD*, int)+591
handler::ha_external_lock(THD*, int)+220
mysql_unlock_tables(THD, st_mysql_lock, bool)+394
close_thread_tables(THD*)+357
mysql_execute_command(THD*)+3116
mysql_parse(THD, char, unsigned int, Parser_state*, bool, bool)+495
dispatch_command(enum_server_command, THD, char, unsigned int, bool, bool)+7596
do_command(THD*)+272
do_handle_one_connection(CONNECT*, bool)+1025
handle_one_connection+93
pfs_spawn_thread+322
start_thread+226
, 5]:
[512, 1K) 5697 \|@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@\|
[1K, 2K) 15 \| \|
[2K, 4K) 1255 \|@@@@@@@@@@@ \|
[4K, 8K) 23 \| \|
[8K, 16K) 1 \| \|

# ls -la /proc/331087/fd/5
lrwx------. 1 dan dan 64 Aug 13 16:00 /proc/331087/fd/5 -> /home/dan/datadir/MDEV-20555_test/aria_log.00000001

So 6991 calls to fdatasync corresponding to number of insert statements.

Comment by Daniel Black [ 2021-01-15 ]

robertbindar can I please get a review of bb-10.2-danielblack-~~MDEV-23326~~-mysql_tzinfo_to_sql being part 1 of the solution here.

This is targeted as 10.2 as the building of containers as the container scripts are easier to maintain if they don't need version dependant scripts.

The end goal is to merge this into functionality of mysql_install_db like in the test branch https://buildbot.mariadb.org/#/grid?branch=bb-10.2-danielblack-MDEV-23326-mysql_tzinfo_to_sql. We don't want binary logs enabled nor is accessing galera status available in mysqld --bootstrap.

Comment by Daniel Black [ 2022-01-11 ]

monty https://github.com/MariaDB/server/pull/1962 is the latest code. The bb-10.2 can be ignored.

Generated at Thu Feb 08 09:21:33 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.

[MDEV-23326] aria TRANSACTIONAL=1 significantly slow on timezone intialisation (was: time zone initialision significantly slower in 10.4 compared to 10.3 (myisam)) Created: 2020-07-29 Updated: 2022-04-21 Resolved: 2022-01-11