I left it here, reverting to an outdated backup, as I needed to get the system up and running. If there are new answers and things to try, I will try so that the issue can be resolved. I shut down the faulty server and I'm holding it.
I am using ubuntu 20.40 and Mariadb 10.3.38 innoDB engine.
I have deleted Moodle's log table rows via .py script.
My deletion is complete and I have 4.5GB of disk space left.
The deletion was huge and I deleted millions of rows.
The .py code proceeded by deleting the logs that met the conditions in 1 hour time frames.
At first everything seemed to work fine.
I started the OPTIMIZE TABLE operation to reduce the space occupied by the table on the disk. Since the OPTIMIZE TABLE operation locked the log table, there was a glitch in the system and I stopped it by doing CTRL+C.
Then mysql stopped and there was no start back.
Here is the log file, it is trying to start it tooks about 15 mins and this log comes up.
2023-07-15 9:55:51 0 \[Note\] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 745544095 row operations to undo
2023-07-15 9:55:51 0 \[Note\] InnoDB: Trx id counter is 8899340213
2023-07-15 9:55:51 0 \[Note\] InnoDB: 128 out of 128 rollback segments are active.
2023-07-15 9:55:51 0 \[Note\] InnoDB: Starting in background the rollback of recovered transactions
2023-07-15 9:55:51 0 \[Note\] InnoDB: To roll back: 1 transactions, 745544095 rows
2023-07-15 9:55:51 0 \[Note\] InnoDB: Creating shared tablespace for temporary tables
2023-07-15 9:55:51 0 \[Note\] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2023-07-15 9:55:52 0 \[Note\] InnoDB: File './ibtmp1' size is now 12 MB.
2023-07-15 9:55:52 0 \[Note\] InnoDB: 10.3.38 started; log sequence number 16864235312410; transaction id 8899340214
2023-07-15 9:55:52 0 \[Note\] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2023-07-15 9:55:52 0 \[Note\] Plugin 'FEEDBACK' is disabled.
2023-07-15 9:55:52 0 \[Note\] Server socket created on IP: '0.0.0.0'.
2023-07-15 9:55:52 0 \[Note\] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
2023-07-15 9:55:52 0 \[Note\] Reading of all Master_info entries succeeded
2023-07-15 9:55:52 0 \[Note\] Added new Master_info '' to hash table
2023-07-15 9:55:52 0 \[Note\] /usr/sbin/mysqld: ready for connections. Version: '10.3.38-MariaDB-0ubuntu0.20.04.1' socket: '/run/mysqld/mysqld.sock' port: 3306 Ubuntu 20.04
2023-07-15 9:55:52 0 \[Note\] Event Scheduler: Purging the queue. 0 events
2023-07-15 9:55:52 0 \[Note\] InnoDB: Starting shutdown...
2023-07-15 9:55:52 0 \[Note\] InnoDB: Buffer pool(s) load completed at 230715 9:55:52 (/var/lib/mysql/ib_buffer_pool was empty or had errors)
2023-07-15 9:55:52 0 \[Note\] InnoDB: Dumping of buffer pool not started as load was incomplete
2023-07-15 9:55:52 0 \[Note\] InnoDB: Rollback of non-prepared transactions completed
2023-07-15 9:55:57 0 \[Note\] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2023-07-15 9:55:57 0 \[Note\] InnoDB: Shutdown completed; log sequence number 16864235312799; transaction id 8899340215
2023-07-15 9:55:57 0 \[Note\] /usr/sbin/mysqld: Shutdown complete
my.cnf
[client-server]
# Import all .cnf files from configuration directory
!includedir /etc/mysql/conf.d/
!includedir /etc/mysql/mariadb.conf.d/
[mysqld]
default_storage_engine = innodb
bind-address = 0.0.0.0
symbolic-links=0
skip-character-set-client-handshake
innodb_undo_log_truncate=off
# general
table_open_cache = 200000
table_open_cache_instances=64
back_log=3500
max_connections=100000
# files
innodb_file_per_table
innodb_log_file_size=15G
innodb_log_files_in_group=2
innodb_open_files=4000
# buffers
innodb_buffer_pool_size= 40G
innodb_buffer_pool_instances=8
innodb_log_buffer_size=64M
# tune
innodb_doublewrite= 1
innodb_thread_concurrency=0
innodb_flush_log_at_trx_commit= 0
innodb_flush_method=O_DIRECT_NO_FSYNC
innodb_max_dirty_pages_pct=90
innodb_max_dirty_pages_pct_lwm=10
innodb_lru_scan_depth=2048
innodb_page_cleaners=4
join_buffer_size=256K
sort_buffer_size=256K
innodb_use_native_aio=1
innodb_stats_persistent = 1
#innodb_spin_wait_delay=96
innodb_adaptive_flushing = 1
innodb_flush_neighbors = 0
innodb_read_io_threads = 16
innodb_write_io_threads = 16
innodb_io_capacity=1500
innodb_io_capacity_max=2500
innodb_purge_threads=4
innodb_adaptive_hash_index=0
max_prepared_stmt_count=1000000
innodb_monitor_enable = '%'
performance_schema = ON
!includedir /etc/mysql/conf.d/
has 2 .cnf
/etc/mysql/conf.d/mysql.cnf
[mysql]
/etc/mysql/conf.d/mysqldump.cnf
[mysqldump]
quick
quote-names
max_allowed_packet = 16M
!includedir /etc/mysql/mariadb.conf.d/
has 4 .cnf
/etc/mysql/mariadb.conf.d/50-client.cnf
[client]
default-character-set = utf8mb4
socket = /var/run/mysqld/mysqld.sock
[client-mariadb]
/etc/mysql/mariadb.conf.d/50-mysql-clients.cnf
[mysql]
default-character-set = utf8mb4
[mysql_upgrade]
[mysqladmin]
[mysqlbinlog]
[mysqlcheck]
[mysqldump]
[mysqlimport]
[mysqlshow]
[mysqlslap]
/etc/mysql/mariadb.conf.d/50-mysqld_safe.cnf
[mysqld_safe]
location.
socket = /var/run/mysqld/mysqld.sock
nice = 0
skip_log_error
syslog
/etc/mysql/mariadb.conf.d/50-server.cnf
[server]
[mysqld]
user = mysql
pid-file = /run/mysqld/mysqld.pid
socket = /run/mysqld/mysqld.sock
#port = 3306
basedir = /usr
datadir = /var/lib/mysql
tmpdir = /tmp
lc-messages-dir = /usr/share/mysql
bind-address = 127.0.0.1
query_cache_size = 16M
log_error = /var/log/mysql/error.log
expire_logs_days = 10
character-set-server = utf8mb4
collation-server = utf8mb4_general_ci
[embedded]
[mariadb]
[mariadb-10.3]
What I have tried
1. workout
I have editted
sudo nano /etc/systemd/system.conf
And setted the value
DefaultTimeoutStartSec=345600s
sudo systemctl daemon-reload
And rebooted the server.
I think If I extend the timeout time it can be relod the 745544095 rows. Lets see..
About 30 mins later
Even though I set the time, nothing changed The status is as below
Jul 15 16:28:12 moodle-2020-db systemd[1]: Starting MariaDB 10.3.38 database server...
Jul 15 16:28:25 [Warning] Could not increase number of max_open_files to more than 1048576 (request: 25700095)
Jul 15 16:43:13 mariadb.service: start operation timed out. terminating
Jul 15 16:58:13 mariadb.service: State 'stop-sigterm' timed out. Skipping SIGKILL.
Jul 15 17:02:30 mariadb.service: Failed with result 'timeout'.
Jul 15 17:02:30 Failed to start MariaDB 10.3.38 database server.
2. Workout
I have editted my.cnf
I have added
MYSQLD_STARTUP_TIMEOUT=345600
under [mysqld]
and rebooted server. And now waiting.. Lets see..
result:
The result is the same as the 1st study
15 minutes trying to start
It tries to stop for 15 minutes and ends.
As I understand it should restore row 745544095.
ibdata1 files is 145GB.
I think it takes around 24-48 hours to load it, but timeout fails to start.
Or maybe I'm focusing in the wrong place. Anyone have any opinions?
Jul 15 17:08:17 moodle-2020-db systemd[1]: Starting MariaDB 10.3.38 database server...
Jul 15 17:08:29 moodle-2020-db mysqld[1876]: 2023-07-15 17:08:29 0 [Warning] Could not increase number of max_open_files to more than 1048576 (request: 25700095)
Jul 15 17:23:17 moodle-2020-db systemd[1]: mariadb.service: start operation timed out. Terminating.
Jul 15 17:38:17 moodle-2020-db systemd[1]: mariadb.service: State 'stop-sigterm' timed out. Skipping SIGKILL.
Jul 15 17:41:45 moodle-2020-db systemd[1]: mariadb.service: Main process exited, code=exited, status=7/NOTRUNNING
Jul 15 17:41:45 moodle-2020-db systemd[1]: mariadb.service: Failed with result 'timeout'.
Jul 15 17:41:45 moodle-2020-db systemd[1]: Failed to start MariaDB 10.3.38 database server.
3. Workout with force_innodb_recovery=3
I have editted my.cnf with force_innodb_recovery=3 and tried to restart mariadb but does not worked.
2023-07-17 8:42:30 0 [Note] InnoDB: Using Linux native AIO
2023-07-17 8:42:30 0 [Note] InnoDB: !!! innodb_force_recovery is set to 3 !!!
2023-07-17 8:42:30 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2023-07-17 8:42:30 0 [Note] InnoDB: Uses event mutexes
2023-07-17 8:42:30 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-07-17 8:42:30 0 [Note] InnoDB: Number of pools: 1
2023-07-17 8:42:30 0 [Note] InnoDB: Using SSE2 crc32 instructions
2023-07-17 8:42:30 0 [Note] InnoDB: Initializing buffer pool, total size = 40G, instances = 8, chunk size = 128M
2023-07-17 8:42:31 0 [Note] InnoDB: Completed initialization of buffer pool
2023-07-17 8:42:31 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2023-07-17 9:16:38 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 745544095 row operations to undo
2023-07-17 9:16:38 0 [Note] InnoDB: Trx id counter is 8899340213
2023-07-17 9:16:38 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2023-07-17 9:16:38 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2023-07-17 9:16:38 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2023-07-17 9:16:38 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2023-07-17 9:16:38 0 [Note] InnoDB: 10.3.38 started; log sequence number 16864235316103; transaction id 8899340213
2023-07-17 9:16:38 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2023-07-17 9:16:38 0 [Note] Plugin 'FEEDBACK' is disabled.
2023-07-17 9:16:38 0 [Note] Server socket created on IP: '0.0.0.0'.
2023-07-17 9:16:38 0 [Note] /usr/sbin/mysqld (initiated by: unknown): Normal shutdown
2023-07-17 9:16:38 0 [Note] Reading of all Master_info entries succeeded
2023-07-17 9:16:38 0 [Note] Added new Master_info '' to hash table
2023-07-17 9:16:38 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.3.38-MariaDB-0ubuntu0.20.04.1' socket: '/run/mysqld/mysqld.sock' port: 3306 Ubuntu 20.04
2023-07-17 9:16:38 0 [Note] Event Scheduler: Purging the queue. 0 events
2023-07-17 9:16:38 0 [Note] InnoDB: Starting shutdown...
2023-07-17 9:16:38 0 [Note] InnoDB: Buffer pool(s) load completed at 230717 9:16:38 (/var/lib/mysql/ib_buffer_pool was empty or had errors)
2023-07-17 9:16:38 0 [Note] InnoDB: Dumping of buffer pool not started as load was incomplete
2023-07-17 9:16:43 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2023-07-17 9:16:43 0 [Note] InnoDB: Shutdown completed; log sequence number 16864235316112; transaction id 8899340214
2023-07-17 9:16:43 0 [Note] /usr/sbin/mysqld: Shutdown complete
Status of MariaDB
root@moodle-2020-db:~# systemctl status mariadb
● mariadb.service - MariaDB 10.3.38 database server
Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
Drop-In: /etc/systemd/system/mariadb.service.d
└─override.conf
Active: failed (Result: timeout) since Mon 2023-07-17 09:16:44 UTC; 42min ago
Docs: man:mysqld(8)
https://mariadb.com/kb/en/library/systemd/
Process: 67825 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
Process: 67836 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
Process: 67839 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= || VAR=`cd /usr/bin/..; /usr/bin/galera_recovery`; [ $? -eq 0 ] && systemctl set-environment _WSREP_START_POSITION=$VAR || exit 1 (code=exited, sta>
Process: 68008 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSREP_START_POSITION (code=exited, status=0/SUCCESS)
Main PID: 68008 (code=exited, status=0/SUCCESS)
Status: "MariaDB server is down"
Jul 17 08:42:17 moodle-2020-db systemd[1]: Starting MariaDB 10.3.38 database server...
Jul 17 08:42:30 moodle-2020-db mysqld[68008]: 2023-07-17 8:42:30 0 [Warning] Could not increase number of max_open_files to more than 1048576 (request: 25700095)
Jul 17 08:57:17 moodle-2020-db systemd[1]: mariadb.service: start operation timed out. Terminating.
Jul 17 09:12:17 moodle-2020-db systemd[1]: mariadb.service: State 'stop-sigterm' timed out. Skipping SIGKILL.
Jul 17 09:16:44 moodle-2020-db systemd[1]: mariadb.service: Failed with result 'timeout'.
Jul 17 09:16:44 moodle-2020-db systemd[1]: Failed to start MariaDB 10.3.38 database server.
4. Workout deleting ib_logfile
I have taken snapshot of system and deleted ib_logfile0 and ib_logfile1.
Rebooted server and it has re created log files.
I was added max_open_files=25700095 to this .cnf file /etc/mysql/mariadb.conf.d/50-mysql-clients.cnf. It was gived an error while starting. So deleted this command and now I am trying to start again.
Here is 4. workout log
2023-07-17 11:16:12 0 [Note] Starting MariaDB 10.3.38-MariaDB-0ubuntu0.20.04.1 source revision c73985f2ce8a391582787f3e310a011c1a712bec as process 1845
2023-07-17 11:16:12 0 [Note] InnoDB: Using Linux native AIO
2023-07-17 11:16:12 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2023-07-17 11:16:12 0 [Note] InnoDB: Uses event mutexes
2023-07-17 11:16:12 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-07-17 11:16:12 0 [Note] InnoDB: Number of pools: 1
2023-07-17 11:16:12 0 [Note] InnoDB: Using SSE2 crc32 instructions
2023-07-17 11:16:12 0 [Note] InnoDB: Initializing buffer pool, total size = 40G, instances = 8, chunk size = 128M
2023-07-17 11:16:13 0 [Note] InnoDB: Completed initialization of buffer pool
2023-07-17 11:16:13 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2023-07-17 11:16:13 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 16106127360 bytes
2023-07-17 11:16:13 0 [Note] InnoDB: Setting log file ./ib_logfile1 size to 16106127360 bytes
2023-07-17 11:16:13 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2023-07-17 11:16:13 0 [Note] InnoDB: New log files created, LSN=16864235316112
2023-07-17 11:43:44 0 [Note] Starting MariaDB 10.3.38-MariaDB-0ubuntu0.20.04.1 source revision c73985f2ce8a391582787f3e310a011c1a712bec as process 1855
2023-07-17 11:43:44 0 [Note] InnoDB: Using Linux native AIO
2023-07-17 11:43:44 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2023-07-17 11:43:44 0 [Note] InnoDB: Uses event mutexes
2023-07-17 11:43:44 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-07-17 11:43:44 0 [Note] InnoDB: Number of pools: 1
2023-07-17 11:43:44 0 [Note] InnoDB: Using SSE2 crc32 instructions
2023-07-17 11:43:44 0 [Note] InnoDB: Initializing buffer pool, total size = 40G, instances = 8, chunk size = 128M
2023-07-17 11:43:45 0 [Note] InnoDB: Completed initialization of buffer pool
2023-07-17 11:43:45 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2023-07-17 11:43:45 0 [Note] InnoDB: The log sequence number 16864235316112 in the system tablespace does not match the log sequence number 16864235316236 in the ib_logfiles!
2023-07-17 12:16:36 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 745544095 row operations to undo
2023-07-17 12:16:36 0 [Note] InnoDB: Trx id counter is 8899340213
2023-07-17 12:16:37 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2023-07-17 12:16:37 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
2023-07-17 12:16:37 0 [Note] InnoDB: To roll back: 1 transactions, 745544095 rows
2023-07-17 12:16:37 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2023-07-17 12:16:37 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2023-07-17 12:16:37 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2023-07-17 12:16:37 0 [Note] InnoDB: Waiting for purge to start
2023-07-17 12:16:37 0 [Note] InnoDB: 10.3.38 started; log sequence number 16864235316236; transaction id 8899340214
2023-07-17 12:16:37 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2023-07-17 12:16:37 0 [Note] Plugin 'FEEDBACK' is disabled.
2023-07-17 12:16:37 0 [ERROR] /usr/sbin/mysqld: unknown variable 'max_open_files=25700095'
2023-07-17 12:16:37 0 [ERROR] Aborting
