[Solved]mariadb taking a lot of CPU with LTS after importing DB

[ahauser]

Hi, since I imported the database from the production environment otrs-6.0.30 of 16GB to znuny-LTS-6.0.46, mariadb is using a lot of CPU. (contrary to the otrs production VM itself)
Any idea what could be done to avoid this ? I tried commenting the recommended parameters in the installation guide but I can't really see a difference (also those recommended in znuny installation guide) :

max_allowed_packet = 64M
query_cache_size = 32M
innodb_log_file_size = 256M

[client]
max_allowed_packet=256M

[mysqld]
innodb_file_per_table
innodb_log_file_size = 256M
max_allowed_packet=256M

[Johannes]

There can be several reasons for this.
First I would check the MariaDB process list.
Also the process list of the machine itself.

[ahauser]

From what I can see in "top", it seems to be the mariadb process itself only.

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
264236 mysql 20 0 3601700 2.3g 10808 S 100.0 59.8 97:42.36 mariadbd
9 root 0 -20 0 0 0 I 0.7 0.0 5:02.62 kworker/0:1H-kblockd
477555 root 20 0 13100 3844 3120 R 0.7 0.1 0:00.07 top
411 root 20 0 317556 4308 2460 S 0.3 0.1 30:47.29 vmtoolsd
1 root 20 0 166124 7556 4160 S 0.0 0.2 1:19.15 systemd
2 root 20 0 0 0 0 S 0.0 0.0 0:11.12 kthreadd
3 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_gp

There are no error interrogating the status of Mariadb, but it shows the following subprocesses :

# service mariadb status
● mariadb.service - MariaDB 10.6.7 database server
Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
Active: active (running) since Fri 2022-11-18 18:31:33 CET; 4 days ago
Docs: man:mariadbd(8)
https://mariadb.com/kb/en/library/systemd/
Process: 264187 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
Process: 264188 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
Process: 264191 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= || VAR=`cd /usr/bin/..; /usr/bin/galera_recovery`; [ $? -eq 0 ] && systemctl set-e>
Process: 264253 ExecStartPost=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
Process: 264256 ExecStartPost=/etc/mysql/debian-start (code=exited, status=0/SUCCESS)
Main PID: 264236 (mariadbd)
Status: "Taking your SQL requests now..."
Tasks: 39 (limit: 4625)
Memory: 2.5G
CPU: 1h 39min 8.332s
CGroup: /system.slice/mariadb.service
└─264236 /usr/sbin/mariadbd

[Johannes]

...
First I would check the MariaDB process list.
...

can you please run "SHOW FULL PROCESSLIST"; in your MySQL / Maria client of your choice

[ahauser]

MariaDB [otrs]> SHOW FULL PROCESSLIST ;
+-------+------+-----------------+------+---------+-------+--------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
| Id | User | Host | db | Command | Time | State | Info | Progress |
+-------+------+-----------------+------+---------+-------+--------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
| 65258 | otrs | localhost:52836 | otrs | Query | 16937 | Sending data | SELECT DISTINCT st.id, st.tn, st.change_time FROM ticket st INNER JOIN article art ON st.id = art.ticket_id LEFT JOIN article_search_index ArticleFulltext ON art.id = ArticleFulltext.article_id INNER JOIN queue sq ON sq.id = st.queue_id WHERE 1=1 AND sq.group_id IN (2,3,33,35,36,39,40,41,43,45,46,49,53,61,63,9) AND (((ArticleFulltext.article_value LIKE '%test%' OR st.title LIKE '%test%' ) )) ORDER BY st.change_time DESC LIMIT 10000 | 0.000 |
| 66629 | otrs | localhost:51310 | otrs | Sleep | 1 | | NULL | 0.000 |
| 66654 | otrs | localhost:54140 | otrs | Sleep | 9 | | NULL | 0.000 |
| 66658 | otrs | localhost:41468 | otrs | Sleep | 4 | | NULL | 0.000 |
| 66817 | otrs | localhost:48380 | otrs | Sleep | 0 | | NULL | 0.000 |
| 66897 | otrs | localhost | otrs | Query | 0 | starting | SHOW FULL PROCESSLIST | 0.000 |
| 66900 | otrs | localhost:48826 | otrs | Sleep | 7 | | NULL | 0.000 |
| 66901 | otrs | localhost:48828 | otrs | Sleep | 4 | | NULL | 0.000 |
+-------+------+-----------------+------+---------+-------+--------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+
8 rows in set (0.000 sec)

[ahauser]

I have more clues about what happens : searches never give any results and seem hanged. the only error I found about it :

Nov 24 11:57:10 znuny-test-01 OTRS-otrs.Console.pl-Maint::Ticket::FulltextIndexRebuildWorker-40[505659]: [Error][Kernel::System::Daemon::DaemonModules::BaseTaskWorker::_HandleError][Line:53]: There was an error executing Execute() in Kernel::System::Console::Command::Maint::Ticket::FulltextIndexRebuildWorker: Error: Active indexing process already running! Skipping...

This message is repeated every minute.

[ahauser]

I found on other posts that rebuilding the search index could solve this issue but it's not the case :

bin/otrs.Console.pl Maint::Ticket::FulltextIndexRebuildWorker --force-pid

[ahauser]

Instead of having the CPU on high level permanently, the search isn't anymore hanged.
However, if an agent join the dashboard or a page with an important number of articles, the problem still occurs.

[Johannes]

I think the instance is currently rebuilding the ticket fulltext search.

This is what this indicates:

Nov 24 11:57:10 znuny-test-01 OTRS-otrs.Console.pl-Maint::Ticket::FulltextIndexRebuildWorker-40[505659]: [Error][Kernel::System::Daemon::DaemonModules::BaseTaskWorker::_HandleError][Line:53]: There was an error executing Execute() in Kernel::System::Console::Command::Maint::Ticket::FulltextIndexRebuildWorker: Error: Active indexing process already running! Skipping...

and what the long wait time confirms.

Can you post the output of bin/otrs.Console.pl Maint::Daemon::Summary
and
bin/otrs.Console.pl Maint::Ticket::FulltextIndex --status

[ahauser]

bin/otrs.Console.pl Maint::Daemon::Summary

Gathering summary for all daemons...

System configuration sync:
Daemon is active.

Tasks to be executed in future:
There are currently no tasks to be executed in future.

Recurrent cron tasks:
+---------------------------------+---------------------+-------------+---------------+---------------------+
| Name | Last Execution | Last Status | Last Duration | Next Execution |
+---------------------------------+---------------------+-------------+---------------+---------------------+
| ArticleSearchIndexRebuild | 2022-11-25 08:33:00 | Fail | < 1 Second | 2022-11-25 08:34:00 |
| CommunicationLogDelete | 2022-11-25 03:00:00 | Success | 7.0 Second(s) | 2022-11-26 03:00:00 |
| ConfigurationDeploymentCleanup | 2022-11-20 00:40:00 | Success | 1.0 Second(s) | 2022-11-27 00:40:00 |
| CoreCacheCleanup | 2022-11-20 00:20:00 | Success | 2.0 Second(s) | 2022-11-27 00:20:00 |
| EscalationCheck | 2022-11-25 08:30:00 | Success | < 1 Second | 2022-11-25 08:35:00 |
| GenerateDashboardStats | 2022-11-25 08:05:00 | Success | < 1 Second | 2022-11-25 09:05:00 |
| GeneticInterfaceDebugLogCleanup | 2022-11-25 03:02:00 | Success | < 1 Second | 2022-11-26 03:02:00 |
| LoaderCacheDelete | 2022-11-20 00:30:00 | Success | 1.0 Second(s) | 2022-11-27 00:30:00 |
| MailAccountFetch | 2022-11-25 08:30:00 | Success | < 1 Second | 2022-11-25 08:40:00 |
| MailQueueSend | 2022-11-25 08:33:00 | Success | 1.0 Second(s) | 2022-11-25 08:34:00 |
| RenewCustomerSMIMECertificates | 2022-11-25 02:02:00 | Success | < 1 Second | 2022-11-26 02:02:00 |
| SessionDeleteExpired | 2022-11-25 06:55:00 | Success | 1.0 Second(s) | 2022-11-25 08:55:00 |
| SpoolMailsReprocess | 2022-11-25 00:10:00 | Success | < 1 Second | 2022-11-26 00:10:00 |
| SupportDataCollectAsynchronous | 2022-11-25 08:01:00 | Success | < 1 Second | 2022-11-25 09:01:00 |
| TicketAcceleratorRebuild | 2022-11-25 01:01:00 | Success | 1.0 Second(s) | 2022-11-26 01:01:00 |
| TicketDraftDeleteExpired | 2022-11-25 07:55:00 | Success | 1.0 Second(s) | 2022-11-25 08:55:00 |
| TicketNumberCounterCleanup | 2022-11-25 08:30:00 | Success | < 1 Second | 2022-11-25 08:40:00 |
| TicketPendingCheck | 2022-11-25 06:45:00 | Success | < 1 Second | 2022-11-25 08:45:00 |
| TicketUnlockTimeout | 2022-11-25 07:35:00 | Success | < 1 Second | 2022-11-25 08:35:00 |
| WebUploadCacheCleanup | 2022-11-25 07:46:00 | Success | < 1 Second | 2022-11-25 08:46:00 |
| ITSMChangesCheck | 2022-11-25 08:30:00 | Success | < 1 Second | 2022-11-25 08:40:00 |
+---------------------------------+---------------------+-------------+---------------+---------------------+

Recurrent generic agent tasks:
There are currently no generic agent recurring tasks configured.

Unhandled Worker Tasks:
There are currently no tasks waiting to be executed.

Handled Worker Tasks:
+---------------------------+------+-----+----------+---------------+
| Name | Type | NID | PID | Duration |
+---------------------------+------+-----+----------+---------------+
| ArticleSearchIndexRebuild | Cron | 001 | 00525199 | 4.0 Second(s) |
+---------------------------+------+-----+----------+---------------+

Done.

$ bin/otrs.Console.pl Maint::Ticket::FulltextIndex --status
Indexed Articles: 56.2% (170949/304407)

[Johannes]

OK, what I thought.

Please check if the progress increases over time.
If not, the job needs to be restarted. Right now it is processing, as far as I can tell.

[ahauser]

I didn't see any progress after a long time.
I added more memory (as the VM crashed last time with a message "out of memory") and restared the job with :

bin/otrs.Console.pl Maint::Ticket::FulltextIndex --rebuild

I see the process keep being at 0.0% even after more than 1H.
Do I need to stop apache, otrs Daemon ?
Should I restart Mariadb ?

[Johannes]

The daemon has to run, otherwise it wont work. So no, don't stop that.
The DB also has to run,so no to that.

Ok, if you already purged the 52% it does not matter anyway.

bin/otrs.Console.pl Maint::Ticket::FulltextIndex --rebuild # triggers the deletion of the index and marks everything to be reindexed.
then manually start a worker Job using
bin/otrs.Console.pl Maint::Ticket::FulltextIndexRebuildWorker --force-pid

after that the reindexing will / should start. You should also see progress in the shell output.
After the job is done. Just wait and watch the number of indexed articles grow. The indexing is performed in the background.
This may take a bit of time, but should work just fine.

Maybe something is currently stuck, so we need to trigger one time with "force-pid".

[ahauser]

Thanks, with a bit more RAM, the index has processed until 100% and now I can't see high CPU usage as before.
I'll try to check with more agents and all kind of operations but yet it really seems better !