High cpu utilization since update 1.25.1

[joseph]

@Purple8 might be worth reporting this upstream at https://github.com/paperless-ngx/paperless-ngx/issues with steps to reproduce from a fresh install . Looks like it is constantly crashing which is the reason for the increased cpu use.

[Purple8]

@joseph thank you, i try to do this

[humptydumpty]

I'm running into the same high cpu usage too. @Purple8 did you report this upstream? If so, please share the ticket number/link.

[imc67]

Indeed, same issue here!

[joseph]

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

[humptydumpty]

@joseph I have the app turned off but it wasn’t crashing for me. Just high cpu usage. I knew something was off when the fan was running at full speed.

[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?