Logs do slow down my shop

[wakabayashi]

I am not sure, how many of you are aware, that the core logs can slow down your shop drastically. I am optimizing my site these days and kind of analyze all chains of code. 

I suddenly noticed, that a huge table (215k rows in my case) of "ps_log" slowed my shop for around 300ms. After truncating this table I have now kind of 500ms instead of 800ms. This is kind of sick 🙃

The reason is mainly this one: https://github.com/thirtybees/thirtybees/blob/main/classes/Hook.php#L564 

[datakick]

Logger::addLog method, when called with $allowDuplicate=false, can be very slow. Method checks if the error log is already present in the table, and insert it only if it is missing. Uniqueness is queried like this:

            'SELECT COUNT(*)
FROM `'._DB_PREFIX_.'log`
WHERE
    `message` = \''.pSQL($this->message).'\'
    AND `severity` = \''.$this->severity.'\'
    AND `error_code` = \''.$this->error_code.'\'
    AND `object_type` = \''.pSQL($this->object_type).'\'
    AND `object_id` = \''.$this->object_id.'\'
'

There is no DB index that could be used, so full table scan is required. That can be very slow once the table increases in size.

This is causing performance problem during every Logger::addLog (or PrestaShopLogger::addLog) call with $allowDuplicate=false, and there are a lot of such calls in core and modules. One of them is in the Hook, as you mentioned. 

Truncating db table regularly helps. Alternatively, creating index on those 5 columns would help as well. For example, creating key on the first 150 chars of message, and all other columns:

alter table tb_log add key(`message`(150), `severity`,`error_code`,`object_type`, `object_id`);

Related to Logger::addLog in Hook -- this points to consistency issue. You have some module that registered hook, but does not provide hook handler. Every time the hook is triggered, thirty bees is trying to call module hook function, and every times it fails to do so -- wasting resources.

Module should have never register this hook in the first place. Since tb 1.2 this is not a problem, because core checks during module installation that the hook handler  exists. If not, warning is thrown during installation time,  and hook is NOT registered. Which means this Logger::addLog would not be called later.

This Logger::addLog is called only for modules that were installed prior 1.2. Or for modules that removed hook handler in some update after installation, but did not unregister hook as well.

You can use my consistency module to detect and fix this: https://store.getdatakick.com/en/modules/consistency

 

[wakabayashi]

@datakick thanks a lot for this detailed answer! I was aware of the table issue, but I guess I understood the message wrong. It's not about an exception handler? It's about registering displayLeftColumn and not having the function hookDisplayLeftColumn() right?

I can tell you, that this issue arises in my cases differently, than you maybe expected. This modules had this hooks registered. But then I removed them. Does the inconsistency check happen during installing/updating process? Cause for some modules I just deleted the function without doing a new installation. Maybe this is a problem? I guess I can just unhook this module under "positions" or calling unregisterHook() ...

Oh I will test your consistency module. 😋 I am already a big fan of the collect logs module. IMO it would be much more helpful, if such warnings would be added to collect logs instead of the normal log. In the normal log you must be Sherlook Holmes to distingue between logs and issues.

[datakick]

2 minutes ago, wakabayashi said:

It's not about an exception handler? It's about registering displayLeftColumn and not having the function hookDisplayLeftColumn() right?

Exactly

2 minutes ago, wakabayashi said:

I can tell you, that this issue arises in my cases differently, than you maybe expected. This modules had this hooks registered. But then I removed them. Does the inconsistency check happen during installing/updating process? Cause for some modules I just deleted the function without doing a new installation. Maybe this is a problem? I guess I can just unhook this module under "positions" or calling unregisterHook() ...

Yes, that would do that. If you manually update the module and remove the function handler, the system will still try to call it

2 minutes ago, wakabayashi said:

I am already a big fan of the collect logs module. IMO it would be much more helpful, if such warnings would be added to collect logs instead of the normal log. In the normal log you must be Sherlook Holmes to distingue between logs and issues.

I agree. I don't like the original Logger much, but at 1.2 there wasn't an alternative.

We can modify this place in Hook to simply trigger PHP warning and let collect logs do its job. Or even better, we can simply unregister the hook, since we already know that the handler doesn't exists. 

 

[wakabayashi]

@datakick I have just installed consitency module and used it a little. Very useful! But I noticed some "issues":

• Carrier with ID 28 is not associated with any shops. This carrier is not showing up for me in BO. Not surprising as the column deleted equals 1.
• Image with ID 4284 is not associated with any shops. This message is correct, but it would be helpful to show the id_product as well. Otherwise a newbie can't fix it IMO.
• Don't forget to add alternative images extension in the image test, once we offer it. A few days ago I have switched my live shop to webp. 😋

[zen]

very interresting, thank you guys for this exchange !

[datakick]

I've just pushed fix for this problem into bleeding edge: https://github.com/thirtybees/thirtybees/commit/554e9967340a34bee0bdf51a4cf957f8f97a865b

I'm also thinking about adding the key to the database. It will make the table bigger, but should help performance significantly.

[the.rampage.rado]

Should we make any changes to our DB?

[datakick]

37 minutes ago, the.rampage.rado said:

Should we make any changes to our DB?

core updater should take care of it for you