Upgrade core 11.0.1.2 to 11.0.2.41 - High search cpu usage

naspelupo

@fbartels Nothng unusual, when set to loglevel 6, I see storeid’s being processed. Normal it is set to loglevel 4. Sometimes a traceback due to the stopping of the search process, below a snippet of the log.
Normally, kopano-server sits at 0.3%cpu and 2.1% mem, when search is active, kopano-server jumps to 47% cpu and 2.1% mem, and search sits at 27% cpu and 0.7% mem. It is a kvm VM with 3 cpu’s and 6G memory, running on an intel nuc i7 10th gen.
The jump of the cpu causes the fan turn to higher speeds - that’s why I noticed it.
search.cfg comes from the example configs with logging the only change (logging file, loglevel 4)

Thanks,
Paul

[snip]
2021-07-28T05:01:26.189: [INFO ] search - stopping search
2021-07-28T05:01:26.193: [ERROR ] index0 - Traceback (most recent call last):
File “/usr/lib/python3/dist-packages/MAPICore.py”, line 662, in <lambda>
setattr = lambda self, name, value: _swig_setattr(self, IMAPIFolder, name, value)
File “/usr/lib/python3/dist-packages/kopano/service.py”, line 206, in <lambda>
signal.signal(signal.SIGTERM, lambda *args: sys.exit(0))
SystemExit: 0

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
File “/usr/lib/python3/dist-packages/kopano/log.py”, line 140, in log_exc
try: yield
{snip]

naspelupo

If I stop kopano-search the CPU returns to normal again. When kopano-search is started there is an increase in DB activity. Sample below, in less than 2 minutes 70K times on 91 unique variables; (on a system with 8 users)

              2425 Query    BEGIN
              2425 Query    SELECT 1 FROM properties WHERE hierarchyid IN(4) LOCK IN SHARE MODE
              2425 Query    SELECT val_binary FROM indexedproperties WHERE tag=26080 AND hierarchyid=3 LIMIT 1
              2425 Query    COMMIT
              2428 Query    BEGIN
              2428 Query    SELECT 1 FROM properties WHERE hierarchyid IN(4) LOCK IN SHARE MODE
              4186 Quit     
              2428 Query    SELECT val_binary FROM indexedproperties WHERE tag=26080 AND hierarchyid=3 LIMIT 1

Hello,

I have the same problem. Rollback to the old version fix the issue.

Frank

naspelupo

@sauserdauser I downgraded to 11.0.2.41 from 11.0.2.43 and have the same issue.
stop kopano
mysqldump + drop database + restore the dump
ran fix-folder-class - some folders fixed
saw during re-index issues at a folder, deleted the contents of the folder
db-find-missing-attachments - none found
delete /var/lib/kopano/search + reran search
still high cpu…

Any thoughts?

zara-kopa

Same in problem in our installation:

Community 11…2.41 Kopano on Debian 10 latest and latest MariaDB on a secound server with Debian 10 latest.
Starting Kopano Search results in an 25% CPU use one a 5 User Enviroment. CPU Usage without search looks like under 5 %. Problem still exist in C… 2.43

The Server with the MariaDB ist still calm. Only kopano-search generate the CPU usage.

(Ja das ist ein englisches Forum, ich lach mich aber gerade selbst darüber kaputt wie tief Groß und Kleinschreibung jeden auffällig macht. Ich kann nicht ohne!)

Gruetings ZARA-KOPA

zara-kopa

An other feeling.
Stopping kopano-search via “systemctl stop kopano-search” on DEBIAN 10 latest need more than 15 secounds for a result. This time is never used bef/vor.

Gre/üß/TT/ing

naspelupo

@zara-kopa my kopano db also sits on a mariadb server, which is without the kopano-search barely active. Is the problem a mariadb thingy?
When I stop kopano-search - which sometimes causes messages in syslog indicating it does not stop in time, the following is in the search logfile

2021-08-10T18:58:28.492: [INFO ] search - stopping search
2021-08-10T18:58:28.495: [ERROR ] index0 - Traceback (most recent call last):
File “/usr/lib/python3/dist-packages/MAPICore.py”, line 662, in <lambda>
setattr = lambda self, name, value: _swig_setattr(self, IMAPIFolder, name, value)
File “/usr/lib/python3/dist-packages/kopano/service.py”, line 206, in <lambda>
signal.signal(signal.SIGTERM, lambda *args: sys.exit(0))
SystemExit: 0

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
File “/usr/lib/python3/dist-packages/kopano/log.py”, line 140, in log_exc
try: yield
File “/usr/lib/python3/dist-packages/kopano_search/init.py”, line 202, in main
if not self.indexed_folder(config, store, folder):
File “/usr/lib/python3/dist-packages/kopano_search/init.py”, line 173, in indexed_folder
path = folder.path
File “/usr/lib/python3/dist-packages/kopano/folder.py”, line 250, in path
subtree_entryid = self.store.subtree.entryid
File “/usr/lib/python3/dist-packages/kopano/store.py”, line 242, in subtree
return _folder.Folder(self, _benc(ipmsubtreeid))
File “/usr/lib/python3/dist-packages/kopano/folder.py”, line 145, in init
self.mapiobj
File “/usr/lib/python3/dist-packages/kopano/folder.py”, line 157, in mapiobj
self._mapiobj = self.store.mapiobj.OpenEntry(self._entryid,
File “/usr/lib/python3/dist-packages/MAPICore.py”, line 602, in OpenEntry
return _MAPICore.IMsgStore_OpenEntry(self, cbEntryID, lpInterface, ulFlags)
SystemError: <built-in function IMsgStore_OpenEntry> returned a result with an error set

KR paul

The next weekend I’ll try the >= 11.0.2.43 on my test / DR system.

Same problem with 11.0.2.43. Even with an empty db and empty attachments / search-folder kopano-server ~ 53%, kopano-search ~ 27% and mysqld ~ 22% CPU

zara-kopa

I have a new fact for my Debian 10 enviroment:

MySQL (MariaDB 10) run in a VM on Proxmox Server. Via crontab-script there ist a daily backup-dump of the hole VM in the early morning. For this time (also via crontab) i stop the whole Kopano-Server thats resists on an other barematel server Debian 10 server. 5 minutes bevor backup-shutdown of Maria Kopano is stopped and after 30 minutes Kopano restarts again. Kopano-Search is allways on.
After nearly each restart there is the high CPU usage. Stopping K-Search helps, but after restart of Search the high CPU usage is there again. On the last weekend i updated PROXMOX (not the MARIA VM) to Debian 11. In this time Kopano was still running but Maria was down. Several Proxmox (including the VM) restarts later everything works fine, also for the running Kopano / Maria construct. Even with high CPU. — Then i have to do a last reboot of the MariaDB. It shows a new aspect. After the reboot of Maria the CPU usage low as in earlyer installations. Search was runnig! Since then i simple do a reboot of Maria if the CPU usage is high. Thats works nearly ever.

Try it on your maschine. For me it looks that there is problem in the connection between K-Search and Maria.

Same problem after os-reboot. Only workaround is a fallback to the old version.

zara-kopa

My solution only works if the mariadb is not on the same hardware as the kopano server. Absolut reliable in my configuration. Kopano runs with search on. CPU usage on the kopano server by nearly 40%. — Shutdown the MariaDB server with the kopano-db for astimate 5 minutes. Restart the MariaDB. 5 minutes alter this CPU usage on the kopano-server goes down to astimate 12%. You can’t test it on a single (all-in) server.

naspelupo

@zara-kopa I can confirm that a reboot of the mariadb server after starting kopano-search results in a normal cpu usage of both server and search again. On my installation I have a mail server and a maria-db server.
In the logfile numerous MAP_DISK_ERRORS as below and then mail and db server return to normal CPU

2021-08-25T06:58:16.291: [ERROR ] index0 - Traceback (most recent call last):
File “/usr/lib/python3/dist-packages/kopano/log.py”, line 140, in log_exc
try: yield
File “/usr/lib/python3/dist-packages/kopano_search/init.py”, line 202, in main
if not self.indexed_folder(config, store, folder):
File “/usr/lib/python3/dist-packages/kopano_search/init.py”, line 173, in indexed_folder
path = folder.path
File “/usr/lib/python3/dist-packages/kopano/folder.py”, line 250, in path
subtree_entryid = self.store.subtree.entryid
File “/usr/lib/python3/dist-packages/kopano/store.py”, line 242, in subtree
return _folder.Folder(self, _benc(ipmsubtreeid))
File “/usr/lib/python3/dist-packages/kopano/folder.py”, line 145, in init
self.mapiobj
File “/usr/lib/python3/dist-packages/kopano/folder.py”, line 157, in mapiobj
self._mapiobj = self.store.mapiobj.OpenEntry(self._entryid,
File “/usr/lib/python3/dist-packages/MAPICore.py”, line 602, in OpenEntry
return _MAPICore.IMsgStore_OpenEntry(self, cbEntryID, lpInterface, ulFlags)
MAPI.Struct.MAPIErrorDiskError: MAPI error 80040116 (MAPI_E_DISK_ERROR)

naspelupo

@zara-kopa after 6 hours without issues, kopano-search is back at excessive cpu usage. Stopping kopano-search again…

zara-kopa

@naspelupo

yes you are rigth. Without any reason k-search results in a new high cpu usage. But in my enviroment this error starts only after reveral days and not in hours. I control my network with PRTG, and create an alarm for a persistent high cpu usage over 40% for longer then 2 hours. Then i stop and restart the MariaDB server for several minutes.
After that cpu usage is normal for nearly a week. Everything, included k-search, runs fine.
Actually i have no time to get deeper in this problem.
“Ja die Sache nervt, bringt aber meine Hardware nicht ins Nirwana”

grüßing
Zara-Kopa

icey

Hi All,
same here. Fresh installation, just 6 users added, no big data yet as it is not yet running in “production”.
Core 11.0.2.43, as soon as kopano-search is started the CPU is at round about 50% continually. A service kopano-search stop takes its time and then CPU drops to 1%, everything is fine.
In the log of k-search:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/kopano/log.py", line 140, in log_exc
    try: yield
  File "/usr/lib/python3/dist-packages/kopano_search/__init__.py", line 200, in main
    path = folder.path
  File "/usr/lib/python3/dist-packages/kopano/folder.py", line 250, in path
    subtree_entryid = self.store.subtree.entryid
  File "/usr/lib/python3/dist-packages/kopano/store.py", line 242, in subtree
    return _folder.Folder(self, _benc(ipmsubtreeid))
  File "/usr/lib/python3/dist-packages/kopano/folder.py", line 145, in __init__
    self.mapiobj
  File "/usr/lib/python3/dist-packages/kopano/folder.py", line 158, in mapiobj
    IID_IMAPIFolder, MAPI_MODIFY)
  File "/usr/lib/python3/dist-packages/MAPICore.py", line 602, in OpenEntry
    return _MAPICore.IMsgStore_OpenEntry(self, cbEntryID, lpInterface, ulFlags)
SystemError: <built-in function IMsgStore_OpenEntry> returned a result with an error set

Anyone an idea?
Thanks in advance
Icey

icey

Dear all,

does nobody has an idea how this could be fixed? It is weird, cause actually there is nearly nothing to be indexed by now. Nothing in attachements folder and also approxiametly 12 mails in all mailboxes.
Would be great if anybody could help.
What about the others? Probs solved?

Thanks in advance,
Icey

JungleMarc

I experience same issue.

I am not on mariadb, but on mysql.

My sql is not part of the same machine. I can confirm mysql is very stable and no performance issues. It does not appear the issue is with the database server.

On the application server for Kopano, yes I can reach high cpu usage for both kopano-server and kopano-search after several weeks of uptime.

My only workaround is a restart of kopano-server, kopano-search

How can we debug this further?

umgfoin

@icey said in Upgrade core 11.0.1.2 to 11.0.2.41 - High search cpu usage:

does nobody has an idea how this could be fixed?

Hello @icey ,
I fixed the possible cause some time ago, but didn’t have time to create a qualified PR, yet.
You can resolve the problem by replacing a few lines in /usr/lib/python3.6/site-packages/kopano_search-11.0.2-py3.6.egg/kopano_search/__init__.py (the exact path on your system depends on distribution, python- and kopano-version).
Take a look here.

bg,
umgfoin.

umgfoin

(the exact path on your system depends on distribution, python- and kopano-version).

In your case more likely to be found here: /usr/lib/python3/dist-packages/kopano_search/__init__.py
++umgfoin.