Enorme lantence sur affichage table m_objfield

thierry.balla · May 19, 2022, 4:30pm

Request description

Des tests récents ont permis de mettre à jour de très fortes latences sur l’affichage dans l’IHM des données issues de la table m_objfield.
Dans l’IHM, on obtient des erreurs 504 (Gateway Timeout).
En poussant plus loin l’investigation grâce à Dynatrace, on se rend compte que l’appel API est bien couronnée de succès mais dure près de 2 minutes.

Steps to reproduce

This request concerns an up-to-date Simplicité instance
and those are the steps to reproduce it:

1.Aller dans Administration/Business objects
2. Sélectionner Action par exemple
3. Les object fields liés mettent énormément de temps à s’afficher, voire ne s’affichent pas

Technical information

URI : /ui/json/obj?action=search&object=ObjectFieldSystem&inst=panel_ajax_ObjectFieldSystem_obf_object_id&context=19&page=0&inline_documents=infos&inline_thumbnails=true&inline_objects=true&_md=true&_visible=true&totals=true&parent=ObjectInternal&parent_inst=the_ajax_ObjectInternal&parent_field=obf_object_id&parent_rowid=2011&=5_1_34_20220518062559&_ajaxkey=DBVfBkeOuo1GByYdqBC7
Timing :

Ce qui nous frappe c’est les plus de 91K appels à la base. Appels qui multipliés par la latence réseau expliquent ces temps de réponse.

Response time: 1 min 58.2s
Response code: 200

Appels en base de données:

Appels en base de données:
Response time breakdown

Response time: 1.97 min
Processing time: 1.97 min
Calls to databases: 91.7k

Les appels nous apparaissent aussi suspects avec des enchainements de commit et rollbacks.
simplicite_object_fields_api_calls

Instance /health

Ce problème est constaté sur tous nos environnements PROD et NON PROD. Il n'est par contre pas constaté sur les instances hébergées chez Simplicité.


[Platform]
Status=OK
Version=5.1.44
BuiltOn=2022-05-10 18:36
Git=5.1/a51516647c95b8cab51e136ca72a2a5e5c30e27c
Encoding=UTF-8
EndpointIP=172.20.114.183
EndpointURL=http://mla-api-7d7d4c66f4-6qtdk:8080
TimeZone=Europe/Paris
SystemDate=2022-05-19 18:28:42

[Application]
ApplicationVersion=0.10
ContextPath=
ContextURL=https://app-mla.gke.int.gcp.renault.com
ActiveSessions=6
TotalUsers=48
EnabledUsers=43
LastLoginDate=2022-05-19 18:25:00

[Server]
ServerInfo=Apache Tomcat/9.0.62
ServerType=WEB
ServerActiveSessions=6

[OS]
Name=Linux
Architecture=amd64
Version=5.4.170+
DockerImageName=centos7
SystemEncoding=UTF-8

[JavaVM]
Version=17.0.3
Vendor=Eclipse Adoptium
VMName=OpenJDK 64-Bit Server VM
VMVersion=17.0.3+7
ScriptEngine=rhino
ScriptEngineVersion=Rhino 1.7.13 2020 09 02
HeapFree=476465
HeapSize=917504
HeapMaxSize=7131136
TotalFreeSize=6690097

[Cache]
GrantCache=0
GrantCacheMax=0
GrantCacheRatio=0
ObjectCache=108
ObjectCacheMax=10000
ObjectCacheRatio=1
ProcessCache=1
ProcessCacheMax=10000
ProcessCacheRatio=0

[Database]
Vendor=3
ProductName=PostgreSQL
ProductVersion=11.15
DriverName=PostgreSQL JDBC Driver
DriverVersion=42.3.5
DBDate=2022-05-19 18:28:42
DBDateOffset=0
DBPatchLevel=5;P01;94dfa153d22f9e8ecd37b949c00b442c
UsingBLOBs=true

[Healthcheck]
Date=2022-05-19 18:28:42
ElapsedTime=312

Simplicité logs

---paste the content of the **relevant** server-side logs---

Browser logs

---paste content of the **relevant** browser-side logs---

Other relevant information

----E.g. type of deployment, browser vendor and version, etc.----

Nous sommes actuellement mobilisés pour comprendre ces 91K appels ainsi que la différence de comportement entre cet appel sur les instances hébergées chez Simplicite et le même appel sur nos instances.

Bien cordialement,
Thierry BALLA

david · May 19, 2022, 4:56pm

Ce symptôme ne nous dit rien.

Il doit y peut être avoir une subtilité au niveau de la configuration de votre infrastructure qui fait que des requêtes “longues” SQL partent peut être en “retry” à l’infini ou dans le genre…

Ou alors vous avez créé une boucle infinie applicative au niveau de votre code… En tout cas rien au niveau d’un Simplicité “out of the box” ne pourrait justifier que l’affichage d’une page induise des requêtes SQL qui partent en boucle.

@Francois des idées ?

Benoit · May 19, 2022, 5:14pm

Bonsoir @david,

Merci pour ta réponse.

En complément, l’installation des modules sur le Sim marche parfaitement.

Le même chargement ne dépasse pas les 3 secondes.

Francois · May 20, 2022, 8:21am

Avez vous modifié l’objet ObjectFieldSystem ou la table, les indexes… ?

ajouté des champs, du code ou héritage ?
il faut regarder que vous avez bien tous les indexes sur les foreign keys de cette table.

Activez les traces SQL pour récupérer la requête en question et passer là dans un explain plan.

thierry.balla · May 20, 2022, 8:36am

Merci de ton retour David,
Si je prends une requête plus normale, par exemple le search sur les items:

ui/json/obj?action=get&object=MlaAftersaleItem&inst=the_ajax_MlaAftersaleItem&context=5&inline_documents=infos&inline_objects=true&_md=true&social=true&=5_1_34_20220520052002&_ajaxkey=Tj2J8uCAOAhbeBNlf0qH

Si on regarde le breakdown

Elle a pris 44 ms.
Il y a la requête en elle même 14.3 ms
Il s’en suivent 9 rollbacks 4.21 ms
Puis 10 commits 1.7 ms
Ensuite une requête sur les labels 1.22 ms
5 requêtes pour insérer une données dans m_object_usage
1 requête sur m_user 1.13 ms
1 requête sur social_post 2.12 ms

On a quand même cette séquence étrange de rollbacks et de commits qui nous interpelle.

Benoit · May 20, 2022, 8:52am

Bonjour @Francois,

Voici les indexes de la table m_objfield (PROD) :

indexname	indexdef
m_objfield_pkey	CREATE UNIQUE INDEX m_objfield_pkey ON public.m_objfield USING btree (row_id)
m_objfield_fk0	CREATE INDEX m_objfield_fk0 ON public.m_objfield USING btree (row_module_id)
m_objfield_fk1	CREATE INDEX m_objfield_fk1 ON public.m_objfield USING btree (obf_object_id)
m_objfield_fk2	CREATE INDEX m_objfield_fk2 ON public.m_objfield USING btree (obf_field_id)
m_objfield_fk3	CREATE INDEX m_objfield_fk3 ON public.m_objfield USING btree (obf_ref_field_id)
m_objfield_fk4	CREATE INDEX m_objfield_fk4 ON public.m_objfield USING btree (obf_ref_object_id)
m_objfield_fk5	CREATE INDEX m_objfield_fk5 ON public.m_objfield USING btree (obf_area_id)
m_objfield_obf_card_idx	CREATE INDEX m_objfield_obf_card_idx ON public.m_objfield USING btree (obf_card)
m_objfield_obf_object_id_fk	CREATE INDEX m_objfield_obf_object_id_fk ON public.m_objfield USING btree (obf_object_id)
m_objfield_obf_field_id_fk	CREATE INDEX m_objfield_obf_field_id_fk ON public.m_objfield USING btree (obf_field_id)
m_objfield_obf_ref_field_id_fk	CREATE INDEX m_objfield_obf_ref_field_id_fk ON public.m_objfield USING btree (obf_ref_field_id)
m_objfield_obf_ref_object_id_fk	CREATE INDEX m_objfield_obf_ref_object_id_fk ON public.m_objfield USING btree (obf_ref_object_id)
m_objfield_obf_area_id_fk	CREATE INDEX m_objfield_obf_area_id_fk ON public.m_objfield USING btree (obf_area_id)
m_objfield_row_module_id_fk	CREATE INDEX m_objfield_row_module_id_fk ON public.m_objfield USING btree (row_module_id)
m_objfield_uk	CREATE UNIQUE INDEX m_objfield_uk ON public.m_objfield USING btree (obf_object_id, obf_field_id, obf_order)

Benoit · May 20, 2022, 8:56am

Je n’ai rien vu de particulier en comparant l’objet à celui d’une instance SIM.

Voici ci joint l’export de l’objet depuis notre PROD :
ObjectFieldSystem_prod.xml (63.1 KB)

Francois · May 20, 2022, 9:09am

Les indexes sont ok (même si redondant suite à un autre post, on a revu ça pour ne plus regénérer les indexes des tables système avec un autre nom.

Ceux ci sont donc en double, on peut les supprimer. Mais ça n’impacte pas à priori la lecture, juste l’écriture qui est un peu plus longue pour les écrire :

m_objfield_obf_card_idx	CREATE INDEX m_objfield_obf_card_idx ON public.m_objfield USING btree (obf_card)
m_objfield_obf_object_id_fk	CREATE INDEX m_objfield_obf_object_id_fk ON public.m_objfield USING btree (obf_object_id)
m_objfield_obf_field_id_fk	CREATE INDEX m_objfield_obf_field_id_fk ON public.m_objfield USING btree (obf_field_id)
m_objfield_obf_ref_field_id_fk	CREATE INDEX m_objfield_obf_ref_field_id_fk ON public.m_objfield USING btree (obf_ref_field_id)
m_objfield_obf_ref_object_id_fk	CREATE INDEX m_objfield_obf_ref_object_id_fk ON public.m_objfield USING btree (obf_ref_object_id)
m_objfield_obf_area_id_fk	CREATE INDEX m_objfield_obf_area_id_fk ON public.m_objfield USING btree (obf_area_id)
m_objfield_row_module_id_fk	CREATE INDEX m_objfield_row_module_id_fk ON public.m_objfield

On parle d’un autre sujet.
Nous n’avons pas d’expertise particulière sur PGSQL et la gestion des rollback.
Il faut regarder en détail les requêtes qui posent problème par un DBA, reconstruire les indexes.
Savoir à quel moment le problème est apparu, suite à quelles actions ?

Pour réduire les requetes social ou usage… il faut revoir le paramétrage des objets (use social, timestamp…), ce qui n’est pas le propos à priori.

thierry.balla · May 20, 2022, 9:32am

@Francois
Je donnais juste le détail d’une autre rrequête “normale” pour exprimer le fait que même là, bien que la requête ne dure que quelques ms, on voit quand même une séquence de 9 rollbacks et 10 commits. Ce qui est quand même surprenant sur un “select”.

cdt