💾 Archived View for thebird.nl › gn-gemtext-threads › issues › database-not-responding.gmi captured on 2023-04-19 at 23:20:28. Gemini links have been rewritten to link to archived content
⬅️ Previous capture (2023-03-20)
-=-=-=-=-=-=-
Mariadb occassionally stops responding. We think updating myisam to InnodB is the solution because it prevents full table locking.
Also it is better to use mydumper, mydumper locks MyISAM tables and does not lock InnoDB so the dump is consistent.
+ ProbeSet
+ GeneRIF_BASIC
+ pubmedsearch
+ 2.1G Dec 4 22:15 ProbeSetXRef.MYD
+ 2.3G Dec 18 14:56 ProbeSet.MYD
+ 2.6G Aug 27 2019 ProbeSE.MYD
+ 7.1G Nov 2 05:07 ProbeSetSE.MYD
+ 11G Aug 27 2019 ProbeData.MYD
+ 63G Dec 4 22:15 ProbeSetData.MYD
In the last 12 hours GN2 monitoring shows the website is responding intermittendly. A quick check shows the database is blocking. Rather than simply restarting the database - which is known to sort the issue - the timing is that the US is sleeping so I can do some checking. Let's take a look.
Mariadb is at 4x CPU
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 40514 mysql 20 0 37.3g 1.8g 18268 S 394.4 0.7 4855:33 mysqld
The ps table shows a backup is ongoing
root 57559 0.0 0.0 2388 756 ? Ss 03:00 0:00 /bin/sh -c /bin/su mysql -c /export/backup/scripts/tux01/backup_mariadb.sh >> ~/cron.log 2>&1 mysql 57588 0.2 0.0 200112 27292 ? Sl 03:00 0:25 mariabackup --backup --target-dir=/home/backup/tux01_mariadb_new/latest/ --user=webqtlout --password=x xxxxxxx
Tales in use:
MariaDB [db_webqtl]> show open tables where in_use > 1; +-----------+----------------+--------+-------------+ | Database | Table | In_use | Name_locked | +-----------+----------------+--------+-------------+ | db_webqtl | InfoFiles | 5 | 0 | | db_webqtl | GeneRIF_BASIC | 3 | 0 | | db_webqtl | ProbeFreeze | 4 | 0 | | db_webqtl | ProbeSet | 4 | 0 | | db_webqtl | ProbeSetXRef | 4 | 0 | | db_webqtl | Species | 4 | 0 | | db_webqtl | Geno | 4 | 0 | | db_webqtl | Chr_Length | 2 | 0 | | db_webqtl | Tissue | 4 | 0 | | db_webqtl | ProbeSetFreeze | 4 | 0 | | db_webqtl | InbredSet | 4 | 0 | +-----------+----------------+--------+-------------+ 11 rows in set (0.001 sec)
MariaDB [db_webqtl]> show open tables where in_use > 1; +-----------+----------------+--------+-------------+ | Database | Table | In_use | Name_locked | +-----------+----------------+--------+-------------+ | db_webqtl | ProbeFreeze | 191 | 0 | | db_webqtl | ProbeSet | 6 | 0 | | db_webqtl | ProbeSetXRef | 6 | 0 | | db_webqtl | PublishFreeze | 13 | 0 | | db_webqtl | Species | 106 | 0 | | db_webqtl | Tissue | 106 | 0 | | db_webqtl | ProbeSetFreeze | 6 | 0 | | db_webqtl | InbredSet | 132 | 0 | | db_webqtl | GenoFreeze | 13 | 0 | +-----------+----------------+--------+-------------+ 9 rows in set (0.001 sec)
In the error log we seeing a lot of
2021-12-21 6:17:57 256179 [Warning] Aborted connection 256179 to db: 'db_webqtl' user: 'webqtlout' host: '128.169.5.59' (Got timeout reading communication packets)
SHOW FULL PROCESSLIST; 458 rows in set (0.003 sec)
with entries
| 256363 | webqtlout | 128.169.5.59:59120 | db_webqtl | Query | 15 | Waiting for table flush | SELECT Id, Name, FullName, ShortName, DataScale FROM ProbeSetFreeze WHERE public > 0 AND (Name = "CB_M_0305_R" OR FullName = "CB_M_0305_R" OR ShortName = "CB_M_0305_R")
waiting for tables to flush!
at the top of the process list we find
Id User Host db Command Time State Info Progress 1 system user NULL Daemon NULL InnoDB purge coordinator NULL 0.000 2 system user NULL Daemon NULL InnoDB purge worker NULL 0.000 3 system user NULL Daemon NULL InnoDB purge worker NULL 0.000 4 system user NULL Daemon NULL InnoDB purge worker NULL 0.000 5 system user NULL Daemon NULL InnoDB shutdown handler NULL 0.000 227365 webqtlout 127.0.0.1:33950 db_webqtl Sleep 13015 NULL 0.000 245634 webqtlout 127.0.0.1:38098 db_webqtl Sleep 23180 NULL 0.000
This is quite informative:
https://programmer.group/analysis-of-mysql-process-in-waiting-for-table-flush.html
it suggests that the backup can be the root of the problem.
And then
https://www.thegeekdiary.com/troubleshooting-mysql-query-hung-waiting-for-table-flush/
suggests
and that is somewhat amusing.
Stripping out all reqular queries we get:
grep localhost test.out |grep -vi probesetfreeze|grep -vi species 255559 webqtlout localhost NULL Query 13092 Waiting for table flush FLUSH NO_WRITE_TO_BINLOG TABLES0.000 256351 webqtlout localhost db_webqtl Field List 1588 Waiting for table flush NULL 0.000 256383 webqtlout localhost db_webqtl Query 0 Init SHOW FULL PROCESSLIST 0.000
and it appears everyone is waiting for id 255559. Let's kill that.
kill 255559;
and inspect
mysql -u webqtlout -pwebqtlout db_webqtl -A -e "show processlist;"|less
it started processing again. To speed up recovery back to:
systemctl restart mysql
of course that stopped the running backup. But processing is back in business.
My first conclusion is that this problem was triggered by the backup procedure. Interestingly, it happens irregularly. We also have seen this issue before this backup procedure was instated, so I figure it has to do with Mariadb.
The version on production is from 2017 - we should update that soon:
Server version: 10.3.27-MariaDB-0+deb10u1-log Debian 10
we have been running a more recent version of mariadb on luna. Still, that is unlikely to fix this issue because I think it really has to do with myisam and locking of large tables. Switching to innodb does away with global locks and is the default on mariadb (there are less and less people using myisam).
Arthur reports: MariaDB is not responding Saturday, July 24 2021 at 10:48 pm. I tried to enter data to the table ProbeSetXRef.pValue and when normally takes few seconds, now is more than 10 minutes without completion/responding.
Zach: before restarting the table can you check the status first?
https://mariadb.com/kb/en/show-table-status/
some ideas here
we are still using MyISAM for these tables: a switch to InnoDB may help.
Arthur complained again that the DB is slow. The standard performance tests are not failing. The slow log shows slow queries:
# Thread_id: 1715564 Schema: db_webqtl QC_hit: No # Query_time: 399.159339 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 SET timestamp=1647055599; UPDATE ProbeSet SET description = REPLACE(description, ";", "") WHERE ChipId=11; # Query_time: 2006.780492 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 SET timestamp=1647057611; update ProbeSetXRef set mean = (select AVG(value) from ProbeSetData where ProbeSetData.Id = ProbeSetXRef.DataId) where ProbeSetXRef.ProbeSetFreezeId = 385; # Query_time: 1158.804376 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 use db_webqtl; SET timestamp=1647142312; update ProbeSet set description="ArfGAP with SH3 domain, ankyrin repeat and PH domain 3" where Id=1719426 AND ChipId=11;
so we should be able to reproduce that.
So, no issues. And this query runs at
MariaDB [db_webqtl]> update ProbeSet set description="ArfGAP with SH3 domain, ankyrin repeat and PH domain 3" where Id=1719426 AND ChipId=11; Query OK, 1 row affected (0.210 sec) Rows matched: 1 Changed: 1 Warnings: 0
There must have been an update block. Best to do diagnostics when the system is blocking.
MariaDB [db_webqtl]> SHOW STATUS LIKE '%connect%'; +-----------------------------------------------+-------+ | Variable_name | Value | +-----------------------------------------------+-------+ | Aborted_connects | 0 | | Connection_errors_accept | 0 | | Connection_errors_internal | 0 | | Connection_errors_max_connections | 0 | | Connection_errors_peer_address | 0 | | Connection_errors_select | 0 | | Connection_errors_tcpwrap | 0 | | Connections | 700 | | Max_used_connections | 29 | | Performance_schema_session_connect_attrs_lost | 0 | | Slave_connections | 0 | | Slaves_connected | 0 | | Ssl_client_connects | 0 | | Ssl_connect_renegotiates | 0 | | Ssl_finished_connects | 0 | | Threads_connected | 3 | | wsrep_connected | OFF | +-----------------------------------------------+-------+ 17 rows in set (0.001 sec)
MariaDB [db_webqtl]> SHOW VARIABLES LIKE '%timeout%'; +---------------------------------------+----------+ | Variable_name | Value | +---------------------------------------+----------+ | connect_timeout | 10 | | deadlock_timeout_long | 50000000 | | deadlock_timeout_short | 10000 | | delayed_insert_timeout | 300 | | idle_readonly_transaction_timeout | 0 | | idle_transaction_timeout | 0 | | idle_write_transaction_timeout | 0 | | innodb_flush_log_at_timeout | 1 | | innodb_lock_wait_timeout | 50 | | innodb_rollback_on_timeout | OFF | | interactive_timeout | 28800 | | lock_wait_timeout | 86400 | | net_read_timeout | 30 | | net_write_timeout | 60 | | rpl_semi_sync_master_timeout | 10000 | | rpl_semi_sync_slave_kill_conn_timeout | 5 | | slave_net_timeout | 60 | | thread_pool_idle_timeout | 60 | | wait_timeout | 28800 | +---------------------------------------+----------+
If you set wait_timeout and interactive_timeout values they get reset after a while.
| Max_used_connections | 1030 | | Threads_connected | 1030 | show open tables where in_use > 1; +-----------+----------------+--------+-------------+ | Database | Table | In_use | Name_locked | +-----------+----------------+--------+-------------+ | db_webqtl | ProbeFreeze | 182 | 0 | | db_webqtl | ProbeSet | 3 | 0 | <- text, still latin1 | db_webqtl | ProbeSetXRef | 3 | 0 | | db_webqtl | PublishFreeze | 7 | 0 | | db_webqtl | Species | 94 | 0 | | db_webqtl | Tissue | 94 | 0 | | db_webqtl | ProbeSetFreeze | 3 | 0 | | db_webqtl | InbredSet | 108 | 0 | | db_webqtl | GenoFreeze | 7 | 0 | +-----------+----------------+--------+-------------+
FLUSH NO_WRITE_TO_BINLOG TABLES Waiting for table flush SELECT confidentiality, AuthorisedUsers FROM ProbeSetFreeze WHERE Name = 'EL_BXDCDScWAT_0216' 0.000 Waiting for table flush SELECT DISTINCT Tissue.Name FROM ProbeFreeze,ProbeSetFreeze, InbredSet, Tissue, Species WHERE Speci 0.000
Another one to check next time is
SHOW ENGINE INNODB STATUS
and
mariabackup --backup --kill-long-query-type=SELECT --kill-long-queries-timeout=120
Use the general log as described in
ALTER TABLE mysql.general_log ENGINE = MyISAM; ALTER TABLE mysql.general_log ADD INDEX (event_time); SET GLOBAL general_log = 'ON'; SET GLOBAL log_output = 'TABLE';
and we start logging all connections and queries! Let this run for a while and we switch it off again for analysis.
To stop logging
SET GLOBAL general_log = 'OFF';
When queries are slow they show up in MariaDB's slow log. This is a useful tool for monitoring issues. After converting tables to innodb this query slowed down to a crawl:
SELECT PublishXRef.Id, CAST(Phenotype.Pre_publication_description AS BINARY), CAST(Phenotype.Post_publication_description AS BINARY), Publication.Authors, Publication.Year, Publication.PubMed_ID, PublishXRef.mean, PublishXRef.LRS, PublishXRef.additive, PublishXRef.Locus, InbredSet.InbredSetCode, Geno.Chr, Geno.Mb FROM Species INNER JOIN InbredSet ON InbredSet.SpeciesId = Species.Id INNER JOIN PublishXRef ON PublishXRef.InbredSetId = InbredSet.Id INNER JOIN PublishFreeze ON PublishFreeze.InbredSetId = InbredSet.Id INNER JOIN Publication ON Publication.Id = PublishXRef.PublicationId INNER JOIN Phenotype ON Phenotype.Id = PublishXRef.PhenotypeId LEFT JOIN Geno ON PublishXRef.Locus = Geno.Name AND Geno.SpeciesId = Species.Id WHERE (((Phenotype.Post_publication_description REGEXP "[[:<:]]morphine[[:>:]]" OR Phenotype.Pre_publication_description REGEXP "[[:<:]]morphine[[:>:]]" OR Phenotype.Pre_publication_abbreviation REGEXP "[[:<:]]morphine[[:>:]]" OR Phenotype.Post_publication_abbreviation REGEXP "[[:<:]]morphine[[:>:]]" OR Phenotype.Lab_code REGEXP "[[:<:]]morphine[[:>:]]" OR Publication.PubMed_ID REGEXP "[[:<:]]morphine[[:>:]]" OR Publication.Abstract REGEXP "[[:<:]]morphine[[:>:]]" OR Publication.Title REGEXP "[[:<:]]morphine[[:>:]]" OR Publication.Authors REGEXP "[[:<:]]morphine[[:>:]]" OR PublishXRef.Id REGEXP "[[:<:]]morphine[[:>:]]") )) and PublishXRef.InbredSetId = 1 and PublishXRef.PhenotypeId = Phenotype.Id and PublishXRef.PublicationId = Publication.Id and PublishFreeze.Id = 1 ORDER BY PublishXRef.Id;
Initially I thought it was the mixing of innodb and myisam tables, but after converting all listed tables, the issue remained. Note I added it as a default test to sheepdog.
Narrowing it down this search is also slow
SELECT PublishXRef.Id, CAST(Phenotype.Pre_publication_description AS BINARY), CAST(Phenotype.Post_publication_description AS BINARY), Publication.Authors, Publication.Year, Publication.PubMed_ID, PublishXRef.mean, PublishXRef.LRS, PublishXRef.additive, PublishXRef.Locus, InbredSet.InbredSetCode, Geno.Chr, Geno.Mb FROM Species INNER JOIN InbredSet ON InbredSet.SpeciesId = Species.Id INNER JOIN PublishXRef ON PublishXRef.InbredSetId = InbredSet.Id INNER JOIN PublishFreeze ON PublishFreeze.InbredSetId = InbredSet.Id INNER JOIN Publication ON Publication.Id = PublishXRef.PublicationId INNER JOIN Phenotype ON Phenotype.Id = PublishXRef.PhenotypeId LEFT JOIN Geno ON PublishXRef.Locus = Geno.Name AND Geno.SpeciesId = Species.Id WHERE Publication.Abstract LIKE "%viral%" OR Publication.Title LIKE "%viral%";
but this is fast
select * from Publication WHERE Publication.Abstract LIKE "%viral%" limit 10;
and this too
select * from Publication WHERE Publication.Abstract REGEXP "[[:<:]]viral[[:>:]]" limit 10;
So the pain pint must be in the joins when using REGEXP because this is fast:
SELECT Publication.Authors, Publication.Year, Publication.PubMed_ID FROM Species INNER JOIN InbredSet ON InbredSet.SpeciesId = Species.Id INNER JOIN PublishXRef ON PublishXRef.InbredSetId = InbredSet.Id INNER JOIN PublishFreeze ON PublishFreeze.InbredSetId = InbredSet.Id INNER JOIN Publication ON Publication.Id = PublishXRef.PublicationId INNER JOIN Phenotype ON Phenotype.Id = PublishXRef.PhenotypeId LEFT JOIN Geno ON PublishXRef.Locus = Geno.Name AND Geno.SpeciesId = Species.Id WHERE Publication.Abstract LIKE "%viral%" OR Publication.Title LIKE "%viral%";
and this is slow
SELECT PublishXRef.Id, CAST(Phenotype.Pre_publication_description AS BINARY), CAST(Phenotype.Post_publication_description AS BINARY), Publication.Authors, Publication.Year, Publication.PubMed_ID, PublishXRef.mean, PublishXRef.LRS, PublishXRef.additive, PublishXRef.Locus, InbredSet.InbredSetCode, Geno.Chr, Geno.Mb FROM Species INNER JOIN InbredSet ON InbredSet.SpeciesId = Species.Id INNER JOIN PublishXRef ON PublishXRef.InbredSetId = InbredSet.Id INNER JOIN PublishFreeze ON PublishFreeze.InbredSetId = InbredSet.Id INNER JOIN Publication ON Publication.Id = PublishXRef.PublicationId INNER JOIN Phenotype ON Phenotype.Id = PublishXRef.PhenotypeId LEFT JOIN Geno ON PublishXRef.Locus = Geno.Name AND Geno.SpeciesId = Species.Id WHERE Publication.Abstract REGEXP "[[:<:]]viral[[:>:]]" OR Publication.Title LIKE "%viral%";
Now Publication lacks text search indices
| Publication | CREATE TABLE Publication ( Id int(10) NOT NULL AUTO_INCREMENT, PubMed_ID int(10) unsigned DEFAULT NULL, Abstract mediumtext DEFAULT NULL, Authors mediumtext NOT NULL, Title varchar(255) DEFAULT NULL, Journal varchar(255) DEFAULT NULL, Volume varchar(255) DEFAULT NULL, Pages varchar(255) DEFAULT NULL, Month varchar(255) DEFAULT NULL, Year varchar(255) NOT NULL DEFAULT '0', PRIMARY KEY (Id), UNIQUE KEY Name (PubMed_ID) ) ENGINE=InnoDB AUTO_INCREMENT=38639 DEFAULT CHARSET=utf8mb4 |
and we may want to introduce FULLTEXT search
https://mariadb.com/kb/en/full-text-index-overview/
but that requires introducing a MATCH command. FULLTEXT index breaks fields into keywoard which will accelerate search.