exzessive versandkosten berechnung

wontfix · 17. Juni 2016 um 07:33

wenn ich diese funktion richtig lese
shopware/sAdmin.php at 5.1 · shopware/shopware · GitHub

macht es bei jeden aufruf, ohne wenn und aber:

aktive benutzer versankosten berechnungen ins $sql_select addieren
$sql_select ins $sql addieren
$sql in datenbank ausführen

also wäre folgendes eine plugin was logt wie oft die versandkosten berechnet wird:

class Shopware_Plugins_Core_FoobarLogger_Bootstrap
extends Shopware_Components_Plugin_Bootstrap
{
    public function install ()
    {
        $this->subscribeEvent(
            'sAdmin::sGetDispatchBasket::after',
            'onDispatchBasket'
        );
        return true;
    }
    public function onDispatchBasket (Enlight_Event_EventArgs $args)
    {
        Shopware()->PluginLogger()->info("sAdmin::sGetDispatchBasket ausgeführt");
    }
}

wenn man dann (auch leere) warenkorb ausruft, sieht es in unsere aktuellen shopware shop so aus:

[2016-06-16 13:16:30] plugin.INFO: sAdmin::sGetDispatchBasket ausgeführt [] {"uid":"35400d4"}
[2016-06-16 13:16:30] plugin.INFO: sAdmin::sGetDispatchBasket ausgeführt [] {"uid":"35400d4"}
[2016-06-16 13:16:30] plugin.INFO: sAdmin::sGetDispatchBasket ausgeführt [] {"uid":"35400d4"}
[2016-06-16 13:16:30] plugin.INFO: sAdmin::sGetDispatchBasket ausgeführt [] {"uid":"35400d4"}
[2016-06-16 13:16:30] plugin.INFO: sAdmin::sGetDispatchBasket ausgeführt [] {"uid":"35400d4"}

und wenn ich alle plugins deaktiviere, bzw. mit vanilla shopware probiere, kommt es immer noch 3 mal:

[2016-06-16 13:18:56] plugin.INFO: sAdmin::sGetDispatchBasket ausgeführt [] {"uid":"ecf70c8"}
[2016-06-16 13:18:56] plugin.INFO: sAdmin::sGetDispatchBasket ausgeführt [] {"uid":"ecf70c8"}
[2016-06-16 13:18:56] plugin.INFO: sAdmin::sGetDispatchBasket ausgeführt [] {"uid":"ecf70c8"}

habe mit trial-and-error herausgefunden das plugin SwagTrustedShopsExcellence führt sAdmin::sGetDispatchBasket 2 mal aus…

dazu kommt noch das “ins warenkorb addieren” auch sAdmin::sGetDispatchBasket mehrmals ausführt, obwohl es nicht mal versandkosten anzeigt…

das problem ist das unsere versandkosten berechnungen - was shopware vorschreibt als sql zu schreiben - sehr komplex sind, und wenn diese merhmals per request immer neu berechnet wird… suboptimal!

daher, wundere ich:

wieso berechnet vanilla shopware versandkosten mehr als einmal pro request?
was macht SwagTrustedShopsExcellence 2 mal mit warenkorb?
was macht SwagTrustedShopsExcellence überhaupt mit warenkorb wenn noch keine bestellung?
wieso berechnet “ins warenkorb addieren” versandkosten?
sind die nächsten sql query results pro request wenigstens gecached?

ich versuche das punkt mit sql query result cache zu bestätigen, aber anscheinend kann man mit mysql nur per session profilen, und noch keine ahnung wo shopware mysql session anfängt oder aufhört. tips?

ps. wir haben in unsere plugins - die warenkorb brauchen - von $controller->getBasket() ins Shopware()->Modules()->Basket()->sGetBasket() getauscht. damit bekommt man anscheinend warenkorb inhalt ohne versandkosten berechnung.

wontfix · 17. Juni 2016 um 08:56

um herauszufinden ob mysql die query results von cache liefert, hab mal diesen hässlichen häck in vanilla shopware addiert:

index e9665f7..5498d8e 100644
--- a/engine/Shopware/Core/sAdmin.php
+++ b/engine/Shopware/Core/sAdmin.php
@@ -3479,6 +3479,9 @@ class sAdmin
 
         $userId = $this->session->offsetGet('sUserId');
         $sessionId = $this->session->offsetGet('sessionId');
+
+ $this->db->query("SET profiling = 1;");
+
         $basket = $this->db->fetchRow(
             $sql,
             array(
@@ -3486,6 +3489,25 @@ class sAdmin
                 empty($sessionId) ? session_id() : $sessionId
             )
         );
+
+ Shopware()->PluginLogger()->info("sAdmin::sGetDispatchBasket ausgeführt");
+
+ $this->db->query("SET profiling = 0;");
+ $myprofiles = $this->db->fetchAll("SHOW PROFILES;");
+ foreach ($myprofiles as $myprofile) {
+ Shopware()->PluginLogger()->info(
+ $myprofile["Query_ID"]." ".substr($myprofile["Query"], 0, 50)."…"
+ );
+ $daq = "SHOW PROFILE FOR QUERY ".$myprofile["Query_ID"];
+ $daprofile = $this->db->fetchAll($daq);
+ Shopware()->PluginLogger()->info($daq);
+ foreach ($daprofile as $meh) {
+ Shopware()->PluginLogger()->info(print_r($meh, true));
+ }
+ }
+
+ Shopware()->PluginLogger()->info("-----------------------------------------------------------------");
+
         if ($basket === false) {
             return false;
         }

und bekomme damit folgenden log bei aufruf von warenkorb (/checkout/cart)

[2016-06-17 10:32:09] plugin.INFO: 3 SELECT MIN(d.instock>=b.quantity) … [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: SHOW PROFILE FOR QUERY 3 [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => starting [Duration] => 0.000008 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => Waiting for query cache lock [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => checking query cache for query [Duration] => 0.000082 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => checking permissions [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => checking permissions [Duration] => 0.000001 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => checking permissions [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => checking permissions [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => checking permissions [Duration] => 0.000001 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => checking permissions [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => checking permissions [Duration] => 0.000001 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => checking permissions [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => Opening tables [Duration] => 0.000020 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => System lock [Duration] => 0.000004 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => Waiting for query cache lock [Duration] => 0.000035 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => init [Duration] => 0.000044 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => optimizing [Duration] => 0.000033 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => statistics [Duration] => 0.000050 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => preparing [Duration] => 0.000016 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => Creating tmp table [Duration] => 0.000023 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => executing [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => Copying to tmp table [Duration] => 0.000060 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => Sorting result [Duration] => 0.000010 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => Sending data [Duration] => 0.000010 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => end [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => removing tmp table [Duration] => 0.000006 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => end [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => query end [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => closing tables [Duration] => 0.000006 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => freeing items [Duration] => 0.000007 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => Waiting for query cache lock [Duration] => 0.000001 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => freeing items [Duration] => 0.000259 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => Waiting for query cache lock [Duration] => 0.000004 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => freeing items [Duration] => 0.000001 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => storing result in query cache [Duration] => 0.000002 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => logging slow query [Duration] => 0.000001 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: Array ( [Status] => cleaning up [Duration] => 0.000021 ) [] {"uid":"ca1f204"}
[2016-06-17 10:32:09] plugin.INFO: ----------------------------------------------------------------- [] {"uid":"ca1f204"}

und wenn ich diesen blog post - https://www.psce.com/blog/2012/04/03/was-a-query-served-from-mysql-query-cache/ - richtig verstehe, müssten wir da jetzt irgendwo “sending cached result” finden. ist aber nicht zu finden…

hmm, ist diese vielleicht eine server konfiguration problem, und es sollte eigentlich mysql cache benutzen?
(weil da steht bei jeden query “storing result in query cache”)

wontfix · 17. Juni 2016 um 09:15

sieht aus das mysql query caching ist an in standard debian/jessie64

mysql> show profiles;
Empty set (0.00 sec)

mysql> set profiling = 1;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from s_blog_media;
+----+---------+----------+---------+
| id | blog_id | media_id | preview |
+----+---------+----------+---------+
| 4 | 1 | 331911 | 1 |
| 5 | 2 | 331912 | 1 |
+----+---------+----------+---------+
2 rows in set (0.00 sec)

mysql> select * from s_blog_media;
+----+---------+----------+---------+
| id | blog_id | media_id | preview |
+----+---------+----------+---------+
| 4 | 1 | 331911 | 1 |
| 5 | 2 | 331912 | 1 |
+----+---------+----------+---------+
2 rows in set (0.00 sec)

mysql> show profiles;
+----------+------------+----------------------------+
| Query_ID | Duration | Query |
+----------+------------+----------------------------+
| 1 | 0.00357125 | select * from s_blog_media |
| 2 | 0.00008875 | select * from s_blog_media |
+----------+------------+----------------------------+
2 rows in set (0.00 sec)

mysql> show profile for query 1;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000037 |
| Waiting for query cache lock | 0.000007 |
| checking query cache for query | 0.000058 |
| checking permissions | 0.000011 |
| Opening tables | 0.000044 |
| System lock | 0.000013 |
| Waiting for query cache lock | 0.000072 |
| init | 0.000026 |
| optimizing | 0.000008 |
| statistics | 0.000013 |
| preparing | 0.000013 |
| executing | 0.000004 |
| Sending data | 0.003085 |
| end | 0.000023 |
| query end | 0.000009 |
| closing tables | 0.000017 |
| freeing items | 0.000061 |
| Waiting for query cache lock | 0.000008 |
| freeing items | 0.000042 |
| Waiting for query cache lock | 0.000004 |
| freeing items | 0.000003 |
| storing result in query cache | 0.000006 |
| logging slow query | 0.000004 |
| cleaning up | 0.000006 |
+--------------------------------+----------+
24 rows in set (0.00 sec)

mysql> show profile for query 2;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000035 |
| Waiting for query cache lock | 0.000005 |
| checking query cache for query | 0.000012 |
| checking privileges on cached | 0.000004 |
| checking permissions | 0.000013 |
| sending cached result to clien | 0.000013 |
| logging slow query | 0.000003 |
| cleaning up | 0.000004 |
+--------------------------------+----------+
8 rows in set (0.00 sec)

wieso werden die shopware versandkosten berechnung queries nicht von cache geliefert?

aber, auch wenn die von mysql cache kommen würden, wollen wir in zukunft unsere frachtkosten in php rechnen - weil komplexe sql ist einfach unlesbar - und da wird wohl keine caching helfen…

also bleibt die ursprüngliche frage, wieso werden die versandkosten so oft berechnet?
bug oder feature?

Thema		Antworten	Aufrufe
Warenkorb Versandkosten modifizieren Programmierung	5	875	19. August 2016
Eigene Versandkostenberechnung Shopware 3.5 installation--gettin	1	506	31. Juli 2013
Mit welchem Event Versandkostenaufschläge per Plugin realisieren? Programmierung	1	283	10. März 2019
Versandkosten im Warenkorb werden nicht berechnet Shopware 3.5 resolved-topics	4	2033	20. September 2013
Zugriff auf Versandkosten im Warenkorb Shopware 3.5 programming	5	3133	5. August 2014

exzessive versandkosten berechnung

Verwandte Themen