very bad performance with too many DBTaskResult entries

[kakulukia]

I had the db_worker running all of yesterday but noticed today that it was orders of magnitudes slower than yesterday. I changed quite a lot of code so it was not clear right from the start, but eventually i got the idea of deleting all finished tasks.

And voila - it deleted about 230k entries and the db_worker was as fast as yesterday where i started.

Of course this will vary on the used DB (sqlite in my case).
But i would propose a setting like:

RESUL_TTL which could be a backend setting.

And while the prune_db_task_results manage.py command already exists it SHOULD BE NOTED in the docs that --min-age-days has a default of 14 days!

I was wondering why it refused to delete anything while the shell version found quite a lot of tasks after running a few minutes again:
DBTaskResult.objects.finished().delete()
Out[1]: (12958, {'django_tasks_database.DBTaskResult': 12958})

That said i wonder why those 230k of finished tasks were such a big deal for the db_worker as in general its not a large dataset. The sqlite DB is 120m in total. Those finished task should not affect the speed of the db_worker, but it did.

[RealOrangeOne]

I think the most interesting point here is that performance is so slow with 230k entries - it should be much faster than that.

There currently isn't any indexing on the table, which would probably help. That should be fixed in #113.

Eventually, I'd also like pruning to be handled by the worker process themselves, but that's a future change.

[kakulukia]

I will collect some more task results today. If you like i can do some testing - just throw me some ideas of what you think might help speeding up the worker again.

Once collected i will test that PR branch for adding indexes and report back.

[kakulukia]

A lil update .. it starts to drop in performance very heavily:
I started to measure the execution times.

My task: ~0.002s
Worker.start while.running: ~0.07s

That is about 35x slower than the task itself - wow!

[kakulukia]

Here is my detailed result.

Total time: 0.614581 s
File: /Users/andy/projects/paketservice/.direnv/python-3.13/lib/python3.13/site-packages/django_tasks/backends/database/management/commands/db_worker.py
Function: start at line 109

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
   109                                               def start(self) -> None:
   110                                                   self.configure_signals()
   111                                                   ic(self.interval)
   112
   113                                                   logger.info("Starting worker for queues=%s", ",".join(self.queue_names))
   114
   115                                                   if self.startup_delay and self.interval:
   116                                                       time.sleep(random.random())  # Zufällige Startverzögerung
   117
   118                                                   durations = []
   119
   120                                                   # ✅ NEU: Zeilenweises Profiling aktivieren
   121                                                   lp = LineProfiler()
   122                                                   lp.add_function(self.start)  # ✅ Analysiert die gesamte `start()`-Methode
   123                                                   lp.enable()
   124
   125        13       6000.0    461.5      0.0          while self.running:
   126        12      27000.0   2250.0      0.0              start_time = time.time()
   127        12    8831000.0 735916.7      1.4              tasks = DBTaskResult.objects.ready().filter(backend_name=self.backend_name)
   128
   129        12       2000.0    166.7      0.0              if not self.process_all_queues:
   130        12    1629000.0 135750.0      0.3                  tasks = tasks.filter(queue_name__in=self.queue_names)
   131
   132        12          0.0      0.0      0.0              try:
   133        12       5000.0    416.7      0.0                  self.running_task = True
   134
   135        24   11117000.0 463208.3      1.8                  with exclusive_transaction(tasks.db):
   136        12       5000.0    416.7      0.0                      try:
   137        12  502193000.0    4e+07     81.7                          task_result = tasks.get_locked()
   138                                                               except OperationalError as e:
   139                                                                   if "is locked" in e.args[0]:
   140                                                                       task_result = None
   141                                                                   else:
   142                                                                       raise
   143
   144        12       3000.0    250.0      0.0                      if task_result is not None:
   145        12    7573000.0 631083.3      1.2                          task_result.claim()
   146
   147        12          0.0      0.0      0.0                  if task_result is not None:
   148        12   67821000.0    6e+06     11.0                      self.run_task(task_result)
   149
   150                                                       finally:
   151        12       4000.0    333.3      0.0                  self.running_task = False
   152
   153        24     231000.0   9625.0      0.0                  for conn in connections.all(initialized_only=True):
   154        12    7779000.0 648250.0      1.3                      conn.close()
   155
   156        12       3000.0    250.0      0.0              if self.batch and task_result is None:
   157                                                           lp.disable()  # ✅ Profiling beenden
   158                                                           lp.print_stats()  # ✅ Profilergebnisse ausgeben
   159                                                           self.print_sql_queries()  # ✅ SQL-Queries ausgeben
   160                                                           return None
   161
   162        12       4000.0    333.3      0.0              if self.running and not task_result:
   163                                                           time.sleep(self.interval)
   164
   165        12      18000.0   1500.0      0.0              end_time = time.time()
   166        12      12000.0   1000.0      0.0              durations.append(end_time - start_time)
   167        12      10000.0    833.3      0.0              if len(durations) > 100:
   168                                                           durations.pop(0)
   169        12      28000.0   2333.3      0.0              average_duration = sum(durations) / len(durations)
   170        12    7280000.0 606666.7      1.2              ic(average_duration)
   171
   172                                                   lp.disable()
   173                                                   lp.print_stats()  # ✅ Profilergebnisse ausgeben
   174                                                   print_sql_queries()  # ✅ SQL-Queries ausgeben

🔍 SQL-Query-Profiling (sortiert nach Laufzeit):

🔹 12x | ⏳ Gesamtzeit: 0.475000s | ⏱️ Ø 0.039583s
🛠 SELECT "django_tasks_database_dbtaskresult"."id", "django_tasks_database_dbtaskresult"."status", "django_tasks_database_dbtaskresult"."enqueued_at", "django_tasks_database_dbtaskresult"."started_at", "django_tasks_database_dbtaskresult"."finished_at", "django_tasks_database_dbtaskresult"."args_kwargs", "django_tasks_database_dbtaskresult"."priority", "django_tasks_database_dbtaskresult"."task_path", "django_tasks_database_dbtaskresult"."queue_name", "django_tasks_database_dbtaskresult"."backend_name", "django_tasks_database_dbtaskresult"."run_after", "django_tasks_database_dbtaskresult"."return_value", "django_tasks_database_dbtaskresult"."exception_class_path", "django_tasks_database_dbtaskresult"."traceback" FROM "django_tasks_database_dbtaskresult" WHERE ("django_tasks_database_dbtaskresult"."status" = '?'?'?'?'?'?'?')) ORDER BY "django_tasks_database_dbtaskresult"."priority" DESC, "django_tasks_database_dbtaskresult"."run_after" DESC NULLS LAST LIMIT ?

🔹 12x | ⏳ Gesamtzeit: 0.014000s | ⏱️ Ø 0.001167s
🛠 SELECT "movies_package"."id", "movies_package"."created", "movies_package"."modified", "movies_package"."number", "movies_package"."count", "movies_package"."file_size_bytes", "movies_package"."name", "movies_package"."category", "movies_package"."resolution", "movies_package"."quality", "movies_package"."movie_id", "movies_package"."bot_id" FROM "movies_package" WHERE ("movies_package"."bot_id" = ? AND "movies_package"."number" = ?) LIMIT ?

🔹 12x | ⏳ Gesamtzeit: 0.001000s | ⏱️ Ø 0.000083s
🛠 UPDATE "django_tasks_database_dbtaskresult" SET "status" = '?'?'?'?''?''?'?'

🔹 2x | ⏳ Gesamtzeit: 0.001000s | ⏱️ Ø 0.000500s
🛠 UPDATE "movies_package" SET "created" = '?'?'?'?'?'?'?', "resolution" = NULL, "quality" = NULL, "movie_id" = NULL, "bot_id" = ? WHERE "movies_package"."id" = ?

🔹 12x | ⏳ Gesamtzeit: 0.000000s | ⏱️ Ø 0.000000s
🛠 BEGIN EXCLUSIVE

🔹 12x | ⏳ Gesamtzeit: 0.000000s | ⏱️ Ø 0.000000s
🛠 UPDATE "django_tasks_database_dbtaskresult" SET "status" = '?'?'?'?'?'

🔹 12x | ⏳ Gesamtzeit: 0.000000s | ⏱️ Ø 0.000000s
🛠 COMMIT

🔹 12x | ⏳ Gesamtzeit: 0.000000s | ⏱️ Ø 0.000000s
🛠 SELECT "movies_bot"."id", "movies_bot"."created", "movies_bot"."modified", "movies_bot"."name", "movies_bot"."channel_id", "movies_bot"."packs", "movies_bot"."max_speed" FROM "movies_bot" WHERE ("movies_bot"."channel_id" = ? AND "movies_bot"."name" = '?') LIMIT ?

🔹 6x | ⏳ Gesamtzeit: 0.000000s | ⏱️ Ø 0.000000s
🛠 UPDATE "movies_package" SET "created" = '?'?'?'?'?'?'?'?'?'?'?', "movie_id" = NULL, "bot_id" = ? WHERE "movies_package"."id" = ?

🔹 1x | ⏳ Gesamtzeit: 0.000000s | ⏱️ Ø 0.000000s
🛠 INSERT INTO "movies_package" ("created", "modified", "number", "count", "file_size_bytes", "name", "category", "resolution", "quality", "movie_id", "bot_id") VALUES ('?'?'?'?'?'?'?', NULL, NULL, NULL, ?) RETURNING "movies_package"."id"

🔹 3x | ⏳ Gesamtzeit: 0.000000s | ⏱️ Ø 0.000000s
🛠 INSERT INTO "movies_package" ("created", "modified", "number", "count", "file_size_bytes", "name", "category", "resolution", "quality", "movie_id", "bot_id") VALUES ('?'?'?'?'?'?'?'?'?'?'?', NULL, ?) RETURNING "movies_package"."id"

🔥 Gesamtanzahl der SQL-Queries: 96
399136 function calls (393460 primitive calls) in 0.959 seconds

The DBResult query is by far the worst part.

[kakulukia]

In [1]: DBTaskResult.objects.ready().count()
Out[1]: 67103

In [2]: DBTaskResult.objects.finished().count()
Out[2]: 145132

As im nearly at the original count of entries - its dead slow again.
Im no expert in any way, but it looks like locking / getting the next task is a hard job for the DB. As if its locking everything first and only getting one task and releasing the rest. That would explain why its getting slow. But thats just a guess.

Adding indices helps a lot, but im not getting to the original speed with an empty task table. :(

[kakulukia]

The 67k tasks that were waiting for execution brought the time down significantly .. after finishing all the tasks now i can confirm that with indices. Its a night and day difference. And the best thing: you can see that even while the worker is running.

manage.py migrate django_tasks_database 0014 makes it dead slow
manage.py migrate django_tasks_database 0015 makes it orders of magnitude faster again

Bildschirmaufnahme.2025-03-06.um.15.01.46.mov

The moments in the video when its halting is where i ecexuted the migration.

[kakulukia]

I set indices on
0|django_tasks_database_dbtaskresult_run_after_2fa1dfb3|0|c|0
1|django_tasks_database_dbtaskresult_enqueued_at_0d65f00d|0|c|0
2|django_tasks_database_dbtaskresult_priority_5f260db0|0|c|0
3|django_tasks_database_dbtaskresult_status_3cbcbca3|0|c|0

I dont know if all are actually needed .. depends on the type of query that is used to get the tasks.

Hope this helps!

[kakulukia]

Ah BTW, before i forget: I could not use the PR as nulls_last=True is not SQLite compliant.

[kakulukia]

585022 Tasks in the DB and still snappy .. consider this fixed once the indices are in!