High cpu utilization since update 1.25.1

imc67

@joseph said in High cpu utilization since update 1.25.1:

@humptydumpty @imc67 is it constantly crashing with KeyError for you as well?

No it never crashed but it has 4GB for its own

humptydumpty

I kept the app running last night and the RAM has high"er" usage too. App has 2GB allocated and is using 600-700mb and 80-100% CPU when idle.

danigl

I have the same problem. Also after update.

Purple8

@humptydumpty Hi, no i did not beacause i couldn't reproduce the error after a reinstall.

nebulon

Looks like this is indeed a regression in the app itself if so many of you hit this now. I still cannot reproduce this here, has anyone already reported this as an upstream issue with paperless?

girish

To isolate the issue a bit further, can you see the output of docker stats ? Is it showing the same high CPU usage? This would eliminate any bugs in Cloudron's graph data collection and rendering.

humptydumpty

@girish I’ll check the output in an hour or so but i can physically hear my fan kick in at full speed so it can’t be just a graph issue.

humptydumpty

@girish docker stats result in screenshot, it's high alright.

girish

@humptydumpty next step would be to docker exec -it 73c74bd70aef /bin/bash (hopefully, I got the container name correct from the screenshot) and then run top and see which process is consuming so much CPU. Usually, > 100% means some process is taking one core completely.

humptydumpty

I tried to inspect the cloudron pid further, but the pid keeps changing.

humptydumpty

@girish more info..

docker logs 73c74bd70aef | grep "celery beat"

full page w/ single repeating line celery beat v5.4.0 (opalescent) is starting.

I also ran docker logs 73c74bd70aef | grep celery and saved it to a log file. I can't paste it anywhere as it's too long. Here's a sliver of the bottom portion.

[2024-08-10 12:09:46,892] [WARNING] [celery.redirected] cannot add item to database
[2024-08-10 12:09:46,953] [WARNING] [celery.redirected] Exception ignored in: 
[2024-08-10 12:09:46,954] [WARNING] [celery.redirected] <function Shelf.__del__ at 0x7ee070a90f70>
[2024-08-10 12:09:46,954] [WARNING] [celery.redirected] Traceback (most recent call last):
[2024-08-10 12:09:46,955] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 162, in __del__
[2024-08-10 12:09:46,955] [WARNING] [celery.redirected]     
[2024-08-10 12:09:46,955] [WARNING] [celery.redirected] self.close()
[2024-08-10 12:09:46,955] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 144, in close
[2024-08-10 12:09:46,955] [WARNING] [celery.redirected]     
[2024-08-10 12:09:46,956] [WARNING] [celery.redirected] self.sync()
[2024-08-10 12:09:46,956] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 168, in sync
[2024-08-10 12:09:46,956] [WARNING] [celery.redirected]     
[2024-08-10 12:09:46,956] [WARNING] [celery.redirected] self[key] = entry
[2024-08-10 12:09:46,956] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 125, in __setitem__
[2024-08-10 12:09:46,957] [WARNING] [celery.redirected]     
[2024-08-10 12:09:46,957] [WARNING] [celery.redirected] self.dict[key.encode(self.keyencoding)] = f.getvalue()
[2024-08-10 12:09:46,957] [WARNING] [celery.redirected] _dbm
[2024-08-10 12:09:46,957] [WARNING] [celery.redirected] .
[2024-08-10 12:09:46,957] [WARNING] [celery.redirected] error
[2024-08-10 12:09:46,958] [WARNING] [celery.redirected] : 
[2024-08-10 12:09:46,958] [WARNING] [celery.redirected] cannot add item to database
[2024-08-10 12:09:49,950] [DEBUG] [celery.utils.functional] 
def empty_trash(doc_ids=0):
    return 1

[2024-08-10 12:09:49,951] [DEBUG] [celery.utils.functional] 
def chunks(task, it, n):
    return 1

[2024-08-10 12:09:49,951] [DEBUG] [celery.utils.functional] 
def bulk_update_documents(document_ids):
    return 1

[2024-08-10 12:09:49,951] [DEBUG] [celery.utils.functional] 
def consume_file(self, input_doc, overrides=0):
    return 1

[2024-08-10 12:09:49,952] [DEBUG] [celery.utils.functional] 
def group(self, tasks, result, group_id, partial_args, add_to_parent=0):
    return 1

[2024-08-10 12:09:49,952] [DEBUG] [celery.utils.functional] 
def delete(doc_ids):
    return 1

[2024-08-10 12:09:49,953] [DEBUG] [celery.utils.functional] 
def index_optimize():
    return 1

[2024-08-10 12:09:49,953] [DEBUG] [celery.utils.functional] 
def error_callback(request, exc, tb, rule_id, message_uid, message_subject, message_date):
    return 1

[2024-08-10 12:09:49,953] [DEBUG] [celery.utils.functional] 
def chain(*args, **kwargs):
    return 1

[2024-08-10 12:09:49,954] [DEBUG] [celery.utils.functional] 
def process_mail_accounts():
    return 1

[2024-08-10 12:09:49,954] [DEBUG] [celery.utils.functional] 
def chord(self, header, body, partial_args=0, interval=1, countdown=2, max_retries=3, eager=4, **kwargs):
    return 1

[2024-08-10 12:09:49,955] [DEBUG] [celery.utils.functional] 
def accumulate(self, *args, **kwargs):
    return 1

[2024-08-10 12:09:49,955] [DEBUG] [celery.utils.functional] 
def update_document_archive_file(document_id):
    return 1

[2024-08-10 12:09:49,956] [DEBUG] [celery.utils.functional] 
def unlock_chord(self, group_id, callback, interval=0, max_retries=1, result=2, Result=3, GroupResult=4, result_from_tuple=5, **kwargs):
    return 1

[2024-08-10 12:09:49,956] [DEBUG] [celery.utils.functional] 
def backend_cleanup():
    return 1

[2024-08-10 12:09:49,956] [DEBUG] [celery.utils.functional] 
def sanity_check():
    return 1

[2024-08-10 12:09:49,957] [DEBUG] [celery.utils.functional] 
def xmap(task, it):
    return 1

[2024-08-10 12:09:49,957] [DEBUG] [celery.utils.functional] 
def train_classifier():
    return 1

[2024-08-10 12:09:49,958] [DEBUG] [celery.utils.functional] 
def apply_mail_action(result, rule_id, message_uid, message_subject, message_date):
    return 1

[2024-08-10 12:09:49,958] [DEBUG] [celery.utils.functional] 
def xstarmap(task, it):
    return 1

[2024-08-10 12:09:49,972] [DEBUG] [celery.beat] Setting default socket timeout to 30
[2024-08-10 12:09:49,972] [INFO] [celery.beat] beat: Starting...
[2024-08-10 12:09:49,982] [CRITICAL] [celery.beat] beat raised exception <class '_dbm.error'>: error('cannot add item to database')
Traceback (most recent call last):
  File "/usr/lib/python3.10/shelve.py", line 111, in __getitem__
    value = self.cache[key]
KeyError: 'entries'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 570, in _create_schedule
    self._store['entries']
  File "/usr/lib/python3.10/shelve.py", line 113, in __getitem__
    f = BytesIO(self.dict[key.encode(self.keyencoding)])
KeyError: b'entries'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/celery/apps/beat.py", line 113, in start_scheduler
    service.start()
  File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 634, in start
    humanize_seconds(self.scheduler.max_interval))
  File "/usr/local/lib/python3.10/dist-packages/kombu/utils/objects.py", line 40, in __get__
    return super().__get__(instance, owner)
  File "/usr/lib/python3.10/functools.py", line 981, in __get__
    val = self.func(instance)
  File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 677, in scheduler
    return self.get_scheduler()
  File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 668, in get_scheduler
    return symbol_by_name(self.scheduler_cls, aliases=aliases)(
  File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 513, in __init__
    super().__init__(*args, **kwargs)
  File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 264, in __init__
    self.setup_schedule()
  File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 541, in setup_schedule
    self._create_schedule()
  File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 574, in _create_schedule
    self._store['entries'] = {}
  File "/usr/lib/python3.10/shelve.py", line 125, in __setitem__
    self.dict[key.encode(self.keyencoding)] = f.getvalue()
_dbm.error: cannot add item to database
[2024-08-10 12:09:49,983] [WARNING] [celery.redirected] Traceback (most recent call last):
[2024-08-10 12:09:49,983] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 111, in __getitem__
[2024-08-10 12:09:49,984] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,984] [WARNING] [celery.redirected] value = self.cache[key]
[2024-08-10 12:09:49,984] [WARNING] [celery.redirected] KeyError
[2024-08-10 12:09:49,984] [WARNING] [celery.redirected] : 
[2024-08-10 12:09:49,984] [WARNING] [celery.redirected] 'entries'
[2024-08-10 12:09:49,984] [WARNING] [celery.redirected] 
During handling of the above exception, another exception occurred:
[2024-08-10 12:09:49,985] [WARNING] [celery.redirected] Traceback (most recent call last):
[2024-08-10 12:09:49,985] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 570, in _create_schedule
[2024-08-10 12:09:49,985] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,985] [WARNING] [celery.redirected] self._store['entries']
[2024-08-10 12:09:49,985] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 113, in __getitem__
[2024-08-10 12:09:49,986] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,986] [WARNING] [celery.redirected] f = BytesIO(self.dict[key.encode(self.keyencoding)])
[2024-08-10 12:09:49,986] [WARNING] [celery.redirected] KeyError
[2024-08-10 12:09:49,986] [WARNING] [celery.redirected] : 
[2024-08-10 12:09:49,986] [WARNING] [celery.redirected] b'entries'
[2024-08-10 12:09:49,986] [WARNING] [celery.redirected] 
During handling of the above exception, another exception occurred:
[2024-08-10 12:09:49,987] [WARNING] [celery.redirected] Traceback (most recent call last):
[2024-08-10 12:09:49,987] [WARNING] [celery.redirected]   File "/usr/local/bin/celery", line 8, in <module>
[2024-08-10 12:09:49,987] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,987] [WARNING] [celery.redirected] sys.exit(main())
[2024-08-10 12:09:49,987] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/__main__.py", line 15, in main
[2024-08-10 12:09:49,988] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,988] [WARNING] [celery.redirected] sys.exit(_main())
[2024-08-10 12:09:49,988] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/bin/celery.py", line 236, in main
[2024-08-10 12:09:49,988] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,988] [WARNING] [celery.redirected] return celery(auto_envvar_prefix="CELERY")
[2024-08-10 12:09:49,988] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/click/core.py", line 1157, in __call__
[2024-08-10 12:09:49,989] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,989] [WARNING] [celery.redirected] return self.main(*args, **kwargs)
[2024-08-10 12:09:49,989] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/click/core.py", line 1078, in main
[2024-08-10 12:09:49,990] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,990] [WARNING] [celery.redirected] rv = self.invoke(ctx)
[2024-08-10 12:09:49,990] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/click/core.py", line 1688, in invoke
[2024-08-10 12:09:49,990] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,990] [WARNING] [celery.redirected] return _process_result(sub_ctx.command.invoke(sub_ctx))
[2024-08-10 12:09:49,991] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/click/core.py", line 1434, in invoke
[2024-08-10 12:09:49,991] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,991] [WARNING] [celery.redirected] return ctx.invoke(self.callback, **ctx.params)
[2024-08-10 12:09:49,991] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/click/core.py", line 783, in invoke
[2024-08-10 12:09:49,992] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,992] [WARNING] [celery.redirected] return __callback(*args, **kwargs)
[2024-08-10 12:09:49,992] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/click/decorators.py", line 33, in new_func
[2024-08-10 12:09:49,992] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,993] [WARNING] [celery.redirected] return f(get_current_context(), *args, **kwargs)
[2024-08-10 12:09:49,993] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/bin/base.py", line 135, in caller
[2024-08-10 12:09:49,993] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,993] [WARNING] [celery.redirected] return f(ctx, *args, **kwargs)
[2024-08-10 12:09:49,993] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/bin/beat.py", line 72, in beat
[2024-08-10 12:09:49,993] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,994] [WARNING] [celery.redirected] return beat().run()
[2024-08-10 12:09:49,994] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/apps/beat.py", line 84, in run
[2024-08-10 12:09:49,994] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,994] [WARNING] [celery.redirected] self.start_scheduler()
[2024-08-10 12:09:49,994] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/apps/beat.py", line 113, in start_scheduler
[2024-08-10 12:09:49,995] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,995] [WARNING] [celery.redirected] service.start()
[2024-08-10 12:09:49,995] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 634, in start
[2024-08-10 12:09:49,995] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,995] [WARNING] [celery.redirected] humanize_seconds(self.scheduler.max_interval))
[2024-08-10 12:09:49,996] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/kombu/utils/objects.py", line 40, in __get__
[2024-08-10 12:09:49,996] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,996] [WARNING] [celery.redirected] return super().__get__(instance, owner)
[2024-08-10 12:09:49,996] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/functools.py", line 981, in __get__
[2024-08-10 12:09:49,997] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,997] [WARNING] [celery.redirected] val = self.func(instance)
[2024-08-10 12:09:49,997] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 677, in scheduler
[2024-08-10 12:09:49,997] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,997] [WARNING] [celery.redirected] return self.get_scheduler()
[2024-08-10 12:09:49,997] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 668, in get_scheduler
[2024-08-10 12:09:49,998] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,998] [WARNING] [celery.redirected] return symbol_by_name(self.scheduler_cls, aliases=aliases)(
[2024-08-10 12:09:49,998] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 513, in __init__
[2024-08-10 12:09:49,998] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,999] [WARNING] [celery.redirected] super().__init__(*args, **kwargs)
[2024-08-10 12:09:49,999] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 264, in __init__
[2024-08-10 12:09:49,999] [WARNING] [celery.redirected]     
[2024-08-10 12:09:49,999] [WARNING] [celery.redirected] self.setup_schedule()
[2024-08-10 12:09:49,999] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 541, in setup_schedule
[2024-08-10 12:09:50,000] [WARNING] [celery.redirected]     
[2024-08-10 12:09:50,000] [WARNING] [celery.redirected] self._create_schedule()
[2024-08-10 12:09:50,000] [WARNING] [celery.redirected]   File "/usr/local/lib/python3.10/dist-packages/celery/beat.py", line 574, in _create_schedule
[2024-08-10 12:09:50,000] [WARNING] [celery.redirected]     
[2024-08-10 12:09:50,000] [WARNING] [celery.redirected] self._store['entries'] = {}
[2024-08-10 12:09:50,001] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 125, in __setitem__
[2024-08-10 12:09:50,001] [WARNING] [celery.redirected]     
[2024-08-10 12:09:50,001] [WARNING] [celery.redirected] self.dict[key.encode(self.keyencoding)] = f.getvalue()
[2024-08-10 12:09:50,001] [WARNING] [celery.redirected] _dbm
[2024-08-10 12:09:50,001] [WARNING] [celery.redirected] .
[2024-08-10 12:09:50,002] [WARNING] [celery.redirected] error
[2024-08-10 12:09:50,002] [WARNING] [celery.redirected] : 
[2024-08-10 12:09:50,002] [WARNING] [celery.redirected] cannot add item to database
[2024-08-10 12:09:50,059] [WARNING] [celery.redirected] Exception ignored in: 
[2024-08-10 12:09:50,059] [WARNING] [celery.redirected] <function Shelf.__del__ at 0x7bef67d94f70>
[2024-08-10 12:09:50,059] [WARNING] [celery.redirected] Traceback (most recent call last):
[2024-08-10 12:09:50,059] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 162, in __del__
[2024-08-10 12:09:50,060] [WARNING] [celery.redirected]     
[2024-08-10 12:09:50,060] [WARNING] [celery.redirected] self.close()
[2024-08-10 12:09:50,060] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 144, in close
[2024-08-10 12:09:50,060] [WARNING] [celery.redirected]     
[2024-08-10 12:09:50,061] [WARNING] [celery.redirected] self.sync()
[2024-08-10 12:09:50,061] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 168, in sync
[2024-08-10 12:09:50,061] [WARNING] [celery.redirected]     
[2024-08-10 12:09:50,061] [WARNING] [celery.redirected] self[key] = entry
[2024-08-10 12:09:50,061] [WARNING] [celery.redirected]   File "/usr/lib/python3.10/shelve.py", line 125, in __setitem__
[2024-08-10 12:09:50,062] [WARNING] [celery.redirected]     
[2024-08-10 12:09:50,062] [WARNING] [celery.redirected] self.dict[key.encode(self.keyencoding)] = f.getvalue()
[2024-08-10 12:09:50,062] [WARNING] [celery.redirected] _dbm
[2024-08-10 12:09:50,062] [WARNING] [celery.redirected] .
[2024-08-10 12:09:50,062] [WARNING] [celery.redirected] error
[2024-08-10 12:09:50,062] [WARNING] [celery.redirected] : 
[2024-08-10 12:09:50,063] [WARNING] [celery.redirected] cannot add item to database

nebulon

This very much reads like task tries to work a job which then fails due to a database conflict. Since that job never finishes it just retries in a loop. I think it is worth if you report this upstream as it kinda seems like a regression in the app itself.

humptydumpty

Upstream ticket opened here: https://github.com/paperless-ngx/paperless-ngx/issues/7439

humptydumpty

@nebulon upstream closed the ticket and said the following:

Perhaps a better question for cloudron not a bug report here. Memory yes, 100% CPU, no.

I appreciate that cloud hosting companies tend to push users to the project itself but since the only people having this problem are those hosting on cloudron (there have been no similar reports lately and I think there would be since it sounds like the app is effectively broken) I think the more logical conclusion is that this is a cloudron issue not a paperless one.

Could you please get in touch with them and sort this out?

niquon

Googling this suggests trying to remove a corrupted file eg data/celerybeat.db

https://stackoverflow.com/questions/12362045/django-celery-error-when-starting-celerybeat-cannot-add-item-to-database

humptydumpty

Shoutout to stumpylog (paperless maintainer) for the fix. Using the file manager, browse to /app/data/data and delete celerybeat-schedule.db.db and restart the ~~server~~ app. CPU usage went down for me. Hopefully, it stays that way.

imc67

@humptydumpty said in High cpu utilization since update 1.25.1:

Shoutout to stumpylog (paperless maintainer) for the fix. Using the file manager, browse to /app/data/data and delete celerybeat-schedule.db.db and restart the ~~server~~ app. CPU usage went down for me. Hopefully, it stays that way.

This solution solved the issue for me! Thanks!!

necrevistonnezr

@humptydumpty said in High cpu utilization since update 1.25.1:

Shoutout to stumpylog (paperless maintainer) for the fix. Using the file manager, browse to /app/data/data and delete celerybeat-schedule.db.db and restart the ~~server~~ app. CPU usage went down for me. Hopefully, it stays that way.

So it was not a Cloudron issue in the end?

humptydumpty

@necrevistonnezr we still don’t know the root cause of the file corruption. It could happen again anytime. Upstream closed the discussion and moved on. It looks like only Cloudron users are affected on existing installs and not on a fresh app. App update snafu?

Btw, upstream said the +500mb ram on idle is normal. I don’t get why it should be that high.

humptydumpty

@nebulon I uploaded the corrupted db file upstream as requested.. edit: just realized I can copy the github link https://github.com/user-attachments/files/16591433/celerybeat-schedule.db.zip

I'll keep the cloned app for the time being. Please let me know if you need more info.

Cloudron makes it easy to run web apps like WordPress, Nextcloud, GitLab on your server. Find out more or install now.

Cloudron Forum

High cpu utilization since update 1.25.1