Lately (I believe since I made a suitecrm upgrade) i find that when trying to list my cases, the loading of the list takes unbearably long (almost 50 seconds).
The strange thing about it is that:
I only have around 800 case records in the database
I already enabled the process to prune the database at the beginning of the month.
I already enabled the slow query logging, an the threshold is set to 3000 miliseconds and nothing appears in the log regarding slow queries.
What else can I do to try to figure out what is causing this poor performance?
I am using version 7.12.5
One thing I am thinking of is making a fresh install of the same version of suitecrm and then recovering the database and the documents folder… Any hope this will work?
Thanks for your answer. If I set the log level to debug, I get way to much more information that I need, I actually get all queries and execution times while I was trying to catch only the queries that took more than 3 seconds.
What I did is grep “Query Execution Time:” from the content of the log file in debug mode after executing the query and none of the times reported got even close to 1second. Which from my understanding kind of rules out the database as being the issue.
Yes it doesn’t seem like the database is the problem - at least not in terms of sizes. However, if your database is on a different server, you could be having network connectivity problems.
Try a tail -f on the logs, with DEBUG level, to see what happens immediately before the 50 seconds pause, and immediately afterwards. That might give you some clues…
Also, try some variations: different browser; different PC; different logged in user. If there is a difference in any of those scenarios, that will also help you narrow down possible causes.
I have tried what you suggested. I have noticed no difference with different browsers and users.
My database is local so it should not be network performance issue.
I have set debug mode for the logs and while the list is loading the following lines keep repeating all the time till the list is displayed.
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Limit Query:SELECT notes.* FROM notes WHERE notes.id = 'dbe443bc-3775-5b9c-0a64-623dfda02ec2' AND notes.deleted=0 Start: 0 count: 1
Thu May 5 21:33:28 2022 [21319][1][INFO] Query:SELECT notes.* FROM notes WHERE notes.id = 'dbe443bc-3775-5b9c-0a64-623dfda02ec2' AND notes.deleted=0 LIMIT 0,1
Thu May 5 21:33:28 2022 [21319][1][INFO] Query Execution Time:0.00066304206848145
Thu May 5 21:33:28 2022 [21319][1][DEBUG] rebuilding cache for Cases
Thu May 5 21:33:28 2022 [21319][1][INFO] Query:SELECT * FROM fields_meta_data WHERE custom_module='Cases' AND deleted = 0
Thu May 5 21:33:28 2022 [21319][1][INFO] Query Execution Time:0.00056695938110352
Thu May 5 21:33:28 2022 [21319][1][DEBUG] rebuilding cache for Contacts
Thu May 5 21:33:28 2022 [21319][1][INFO] Query:SELECT * FROM fields_meta_data WHERE custom_module='Contacts' AND deleted = 0
Thu May 5 21:33:28 2022 [21319][1][INFO] Query Execution Time:0.00070095062255859
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (assigned_user_id).
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean.load_relationships, failed Loading relationship (assigned_user_id)
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (assigned_user_id).
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean.load_relationships, failed Loading relationship (assigned_user_id)
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (contact).
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Hook called: Notes::after_retrieve
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Hook called: Notes::before_retrieve
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Retrieve Note : SELECT notes.* FROM notes WHERE notes.id = 'dbec53c8-e77e-7ccf-12ef-623dfb5ceb13' AND notes.deleted=0
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Limit Query:SELECT notes.* FROM notes WHERE notes.id = 'dbec53c8-e77e-7ccf-12ef-623dfb5ceb13' AND notes.deleted=0 Start: 0 count: 1
Thu May 5 21:33:28 2022 [21319][1][INFO] Query:SELECT notes.* FROM notes WHERE notes.id = 'dbec53c8-e77e-7ccf-12ef-623dfb5ceb13' AND notes.deleted=0 LIMIT 0,1
Thu May 5 21:33:28 2022 [21319][1][INFO] Query Execution Time:0.00059318542480469
Thu May 5 21:33:28 2022 [21319][1][DEBUG] rebuilding cache for Cases
Thu May 5 21:33:28 2022 [21319][1][INFO] Query:SELECT * FROM fields_meta_data WHERE custom_module='Cases' AND deleted = 0
Thu May 5 21:33:28 2022 [21319][1][INFO] Query Execution Time:0.0005490779876709
Thu May 5 21:33:28 2022 [21319][1][DEBUG] rebuilding cache for Contacts
Thu May 5 21:33:28 2022 [21319][1][INFO] Query:SELECT * FROM fields_meta_data WHERE custom_module='Contacts' AND deleted = 0
Thu May 5 21:33:28 2022 [21319][1][INFO] Query Execution Time:0.00068879127502441
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (assigned_user_id).
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean.load_relationships, failed Loading relationship (assigned_user_id)
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (assigned_user_id).
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean.load_relationships, failed Loading relationship (assigned_user_id)
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (contact).
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Hook called: Notes::after_retrieve
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Hook called: Notes::before_retrieve
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Retrieve Note : SELECT notes.* FROM notes WHERE notes.id = 'dbf02d10-59f7-0d72-0b1a-623dfae39ff8' AND notes.deleted=0
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Limit Query:SELECT notes.* FROM notes WHERE notes.id = 'dbf02d10-59f7-0d72-0b1a-623dfae39ff8' AND notes.deleted=0 Start: 0 count: 1
Thu May 5 21:33:28 2022 [21319][1][INFO] Query:SELECT notes.* FROM notes WHERE notes.id = 'dbf02d10-59f7-0d72-0b1a-623dfae39ff8' AND notes.deleted=0 LIMIT 0,1
Thu May 5 21:33:28 2022 [21319][1][INFO] Query Execution Time:0.00061988830566406
Thu May 5 21:33:28 2022 [21319][1][DEBUG] rebuilding cache for Cases
Thu May 5 21:33:28 2022 [21319][1][INFO] Query:SELECT * FROM fields_meta_data WHERE custom_module='Cases' AND deleted = 0
Thu May 5 21:33:28 2022 [21319][1][INFO] Query Execution Time:0.00071191787719727
Thu May 5 21:33:28 2022 [21319][1][DEBUG] rebuilding cache for Contacts
Thu May 5 21:33:28 2022 [21319][1][INFO] Query:SELECT * FROM fields_meta_data WHERE custom_module='Contacts' AND deleted = 0
Thu May 5 21:33:28 2022 [21319][1][INFO] Query Execution Time:0.00074577331542969
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (assigned_user_id).
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean.load_relationships, failed Loading relationship (assigned_user_id)
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (assigned_user_id).
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean.load_relationships, failed Loading relationship (assigned_user_id)
Thu May 5 21:33:28 2022 [21319][1][DEBUG] SugarBean[Note].load_relationships, Loading relationship (contact).
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Hook called: Notes::after_retrieve
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Hook called: Notes::before_retrieve
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Retrieve Note : SELECT notes.* FROM notes WHERE notes.id = 'dc38587b-8108-4c9d-3fe2-623de2620c45' AND notes.deleted=0
Thu May 5 21:33:28 2022 [21319][1][DEBUG] Limit Query:SELECT notes.* FROM notes WHERE notes.id = 'dc38587b-8108-4c9d-3fe2-623de2620c45' AND notes.deleted=0 Start: 0 count: 1
Thu May 5 21:33:28 2022 [21319][1][INFO] Query:SELECT notes.* FROM notes WHERE notes.id = 'dc38587b-8108-4c9d-3fe2-623de2620c45' AND notes.deleted=0 LIMIT 0,1
It seems to me like the code is executing a query for each record in the list … which could justify it being so slow… ¿Could this be?
Check your logic hooks, and Workflows, in that module.
I think that’s where the overhead is coming from. Possibly it’s even an infinite loop, when something done inside the hook causes a second retrieve, which itself makes the hook fire again, etc.
Unfortunately I don’t know how to do that … any guidance you can provide will be welcomed.
In this instance of suitecrm I only have one custom module which I did build using the Studio and three wolkflows related to that module. There is no custom code or anything of the sort.
I also would like to mention that in the same server I am runnning another instance of suiteCRM which is not having this issues with the lists and it has even more records.
Looking back , I think that this slow response started after I tried activating the inbound email to automatically create more cases and got flooded with bounced error messages… I already cleaned all the created cases but performance has not improved.
I am still facing this performance issue. As mentioned I do not have custom code, just created a module and some workflows… Is there something in particular I should look into to figure out what is slowing down Suitecrm?
You can try disabling Workflows one by one, leaving it for a while and see if any of them proves to be the culprit.
The same goes for Scheduler jobs - namely, the ones mentioning inbound email. try disabling them one by one and see if anything changes regarding the performance problem.
I dissabled all the workflows and all the scheduled jobs and it did not help at all…
I am now trying to migrate to a new instance trying to port all my data and customizations, for that I tried a bitnami docker image of suitecrm 7.12.5.
After migrating the database and copying the custom directory speed was again back to normal.
There must be something in the original code that screwed everything up but I am unable to figure it up.
I ended up migrating to a new dockerized version of suitecrm and migrated my data ther. In the process something got cleaned up (maybe to many upgrades or so) and now speed is back to normal.
