Project

General

Profile

Fehler #113

Performance Order Controller

Added by Werner Hahn almost 9 years ago. Updated almost 9 years ago.

Status:
Erledigt
Priority:
Normal
Assignee:
-
Target version:
-
Start date:
12/03/2015
Due date:
% Done:

0%

Estimated time:

Description

Wir haben hier das Problem, dass das Einfügen einer Positionszeile zu lange dauert und je mehr Menschen mit der kivi arbeiten es noch länger dauert. In den Anhängen hab ich zwei Logs.
1.er log. Person gibt alleine Positionen ein ca 20-30
2.er log. Zweite Person ruft immer wieder Kontoauszug verbuchen auf. 1. Person gibt den gleichen Auftrag erneut ein


Files

kivi1.log (3.97 MB) kivi1.log Werner Hahn, 12/03/2015 01:19 PM
kivi2.log (2.92 MB) kivi2.log Werner Hahn, 12/03/2015 01:19 PM
kivitendo-debug1.log (188 KB) kivitendo-debug1.log Werner Hahn, 12/18/2015 05:05 PM
kivitendo-debug2.log (423 KB) kivitendo-debug2.log Werner Hahn, 12/18/2015 05:05 PM
kivitendo-debug3.log (474 KB) kivitendo-debug3.log Werner Hahn, 12/18/2015 05:06 PM
action_add_item.log (406 KB) action_add_item.log nur add_item Bernd Bleßmann, 12/18/2015 06:30 PM
df1_add_item_time.txt (509 Bytes) df1_add_item_time.txt Werner Hahn, 01/21/2016 10:51 AM
df2_add_item_time.txt (893 Bytes) df2_add_item_time.txt Werner Hahn, 01/21/2016 10:51 AM
df3_add_item_time.txt (814 Bytes) df3_add_item_time.txt Werner Hahn, 01/21/2016 10:51 AM
df3.log.bz2 (25.3 KB) df3.log.bz2 Werner Hahn, 01/21/2016 10:51 AM
extract_requests.pl (1.75 KB) extract_requests.pl Werner Hahn, 01/21/2016 10:51 AM

History

#1

Updated by Bernd Bleßmann almost 9 years ago

Hallo Werner,

Wir haben hier das Problem, dass das Einfügen einer Positionszeile zu lange dauert und je mehr Menschen mit der kivi arbeiten es noch länger dauert. In den Anhängen hab ich zwei Logs.

welchen Stand des Controllers verwendet ihr? Ist der Patch, den ich für Euch erstellt hatte, eingespielt oder ist das ohne diesen?

Sorry - wie Kontoauszug verbuchen funktioniert, weiß ich nicht und logs mit 20000 bzw. 30000 Zeilen durchzusehen finde ich jetzt ein bisschen heftig. Kannst Du Deine Interpretation dazu mal zusammenfassen? Passiert das auch in anderen Szenarien?

1.er log. Person gibt alleine Positionen ein ca 20-30
2.er log. Zweite Person ruft immer wieder Kontoauszug verbuchen auf. 1. Person gibt den gleichen Auftrag erneut ein

Viele Grüße
Bernd

#2

Updated by G. Richardson almost 9 years ago

Werner Hahn schrieb:

Wir haben hier das Problem, dass das Einfügen einer Positionszeile zu lange dauert und je mehr Menschen mit der kivi arbeiten es noch länger dauert. In den Anhängen hab ich zwei Logs.

Hast du auch alle Debug-Einstellungen ausgeschaltet? Da taucht z.B. immer sowas wie dump_query auf, du hast wohl mindestens global_level = QUERY aktiv. Nur so eine Idee.

Die interessanten Queries, die man sich anschauen sollte, und die von Rose generiert werden, tauchen dort eh nicht auf.

#3

Updated by Werner Hahn almost 9 years ago

Hallo
ich hatte das gestern mit Jan besprochen, der wollte die Debugmeldungen haben.
Das Problem genau ist, dass wenn ich enter drücke es ,zwar nicht lange, aber zu lange dauert dass es möglich ist die nächste nummer einzugeben ohne sich zu verhaspeln, d.h. oft wird dann angefangen die nächste nummer einzugeben und die erste stelle wird abgeschnitten.
Bisher ist es möglich positionen ohne pause einzugeben 1.artikelnummer->enter->enter->2.Artikelnummer->enter->enter3.usw ohne Pause jetzt muss ich einen tick Pause machen. Je mehr Leute mit kivitendo arbeiten je größer wird die Pause.
Debug ist auf
global_level = TRACE QUERY REQUEST_TIMER
vielleicht ist etwas anderes hilfreicher.
vielleicht kann man auch das javascript aus der basic.html in einen kivi namespace auslagern, sodass der browser das cached?
so ist es auf jedenfall noch nicht zufriedenstellend doppelt so lange wie bisher und führt zu fehleingaben

#4

Updated by G. Richardson almost 9 years ago

Also die zentrale Datenbankabfrage ist ja die Suche nach dem Artikel anhand der Artikelnummer oder Beschreibung. Ihr habt ja nicht so viele Artikel, anders als bei den Kunden, aber die Artikelsuche würde ich mir als erstes anschauen. Die ist schon mal überhaupt nicht optimiert und kann auch keine Datenbankindizes nutzen. Du lädst in dem Schritt ja glaube ich auch noch ein paar andere Infos, ich hab was von Preisgruppen gehört, führe doch mal Folgendes in der console aus, da sollten dann die von Rose generierten SQL-Statements rausfallen. Und ersetze das "MYPARTNUMBER" durch eine Beispielartikelnummer aus eurem Bestand.


$Rose::DB::Object::Manager::Debug = 1;
$Rose::DB::Object::Debug = 1;
use SL::Controller::Part;
my $cont = SL::Controller::Part->new;
$::form->{filter}{'all:substr:multi::ilike'} = 'MYPARTNUMBER';
$::form->{prefer_exact} = 1;
$::form->{obsolete} = 0;
$cont->action_ajax_autocomplete();

Wenn die Abfrage sehr imperformant und das der Grund ist, gibt es für euren Anwendungsfall da noch Optimierungspotential.

#5

Updated by Werner Hahn almost 9 years ago

Die Artikelsuche ist glaub ich nicht das Problem, auch wenns schön wäre wenn die schneller geht und ab der ersten ziffer schon sofort Vorschläge hat (wie bei google). Wenn da noch was möglich ist freun wir uns.
LOG: 1. Paar Artikelnr '11' 2. u.3. Artikelnr '11215' (genau) 4. Artikelnr '1' 5. Artikelnr '11215' (genau)
Bei 1 und 4 dauerte es schon so 0-3 sec bis das fertig war
2015-12-04 15:43:04.059 2461 [2443] sub0: \ Form::create_http_response in SL/Form.pm:418 called from SL/Controller/Base.pm:131
2015-12-04 15:43:04.060 2461 [2443] sub0: / Form::create_http_response in SL/Form.pm:450
2015-12-04 15:44:22.175 2461 [2443] sub0: \ Form::create_http_response in SL/Form.pm:418 called from SL/Controller/Base.pm:131
2015-12-04 15:44:22.175 2461 [2443] sub0: / Form::create_http_response in SL/Form.pm:450
2015-12-04 15:45:33.892 2461 [2443] sub0: \ Form::create_http_response in SL/Form.pm:418 called from SL/Controller/Base.pm:131
2015-12-04 15:45:33.892 2461 [2443] sub0: / Form::create_http_response in SL/Form.pm:450
2015-12-04 15:46:48.946 2461 [2443] sub0: \ Form::create_http_response in SL/Form.pm:418 called from SL/Controller/Base.pm:131
2015-12-04 15:46:48.947 2461 [2443] sub0: / Form::create_http_response in SL/Form.pm:450
2015-12-04 15:47:39.090 2461 [2443] sub0: \ Form::create_http_response in SL/Form.pm:418 called from SL/Controller/Base.pm:131
2015-12-04 15:47:39.090 2461 [2443] sub0: / Form::create_http_response in SL/Form.pm:450

Bei Bernd seinem orginal ist es noch deutlicher wenn versucht wird flüssig ohne pause die positionen einzugeben auch wenn ich nicht so schnell tippe

#6

Updated by Jan Büren almost 9 years ago

Die Postgres-Werte sind auch annähernd gut an den RAM optimiert?

shared_buffers und effective_cache_size

https://wiki.postgresql.org/wiki/Tuning_Your_PostgreSQL_Server

Ferner sind auch mehr als 2 Kerne für die Maschinen zugewiesen und prinzipiell wird weder beim Wirts- noch beim Gastsystem in SWAP ausgelagert?

Wie schnell dreht eine einzelne Platte, wie schnell das RAID?

Hier Werte für SSD-Platten:

 $ hdparm -Tt /dev/sda
/dev/sda:
 Timing cached reads:   33328 MB in  2.00 seconds = 16682.56 MB/sec
 Timing buffered disk reads: 1554 MB in  3.00 seconds = 517.91 MB/sec

Wie schnell dreht das RAID10?

Unser RAID1 schafft noch 3/4 der SSD-Performance:


 time dd of=testfile if=/dev/zero bs=1M count=10000000800
^C11032+0 Datensätze ein
11032+0 Datensätze aus
11567890432 Bytes (12 GB) kopiert, 33,8864 s, 341 MB/s

Holt Postgres schon das Meiste aus dem RAM raus oder ist das noch konservativ eingestellt?

Bei 8GB RAM kann man sicherlich so verteilen:

shared_buffers = 2GB
effective_cache_size = 4GB

Die Standard-Werte von Debian sind hier sehr konservativ.

Falls der Server unter Last auslagert, kann man dies sehr gut mit free feststellen. Ferner kann top nochmal nach Hauptspeicher-Auslastung sortiert werden.

Meine Standard-Checks sind hier

$ free -m
$ top (gefolgt mit großem M)
#7

Updated by Jan Büren almost 9 years ago

Vielleicht denke ich zu old school. Heutzutage hat man doch die:

sessionStorage and localStorage capabilities of HTML 5.

Die Tabelle parts kann auch gerne im Browser-Cache landen ...

#8

Updated by Sven Schöling almost 9 years ago

Moin Werner,

wie am Telefon besprochen mache bitte die logs mal mit den Optionen:

[devel]
global = REQUEST REQUEST_TIMER

das loggt den jeweiligen Request und die Zeit die die brauchen, dadurch lässt sich sehr viel besser nachvollziehen welche Requests lange dauern und/oder andere blocken.

#9

Updated by Werner Hahn almost 9 years ago

Hab jetzt die Logs erstellt.
Log1 ich gebe alleine eine Rechnung ein
Log2 eine Mitarbeiterin gibt alleine eine Rechnung ein
Log3 eine Mitarbeiterin gibt eine Rechnung ein auf zwei anderen Clients wird immer wieder Kontosuzugverbuchen angestossen

Wenn man alleine arbeitet kann man sich durchaus an den Rythmus von Kivitendo gewöhnen
Bei Log3 hats alles deutlich verzögert nicht immer aber es ist schwierig einen flüssigen Rythmus zu finden und es ist nicht möglich blind zu tippen.
Werner

#10

Updated by Bernd Bleßmann almost 9 years ago

Hi Werner,

Werner Hahn schrieb:

Hab jetzt die Logs erstellt.
Log1 ich gebe alleine eine Rechnung ein
Log2 eine Mitarbeiterin gibt alleine eine Rechnung ein
Log3 eine Mitarbeiterin gibt eine Rechnung ein auf zwei anderen Clients wird immer wieder Kontosuzugverbuchen angestossen

Ich habe mal für log3 die relevanten Requests mit Zeiten extrahiert - nur der Übersicht halber. Für die Analyse muss man natürlich sehen, was sonst noch so los ist. Relevant: damit meine ich hier die "controller: Order, action: add_item", denn das sind die, die den Artikel hinzufügen und danach den Focus wieder auf das Eingabefeld das Partpickers setzen.

Hier sind die Zeiten für diese Requests, sortiert:
0.32723
0.33684
0.386846
0.389577
0.389788
0.404126
0.410691
0.481287
0.495391
0.500738
0.504685
0.514757
0.579243
0.620899
0.624994
0.651551
0.654329
0.680844
0.706547
0.719991
0.741116
0.752883
0.798339
0.897373
1.466361

#11

Updated by Werner Hahn almost 9 years ago

Bernd und ich haben jetzt nochmal deren Installation auf kiebitz getestet, und die Zeiten dort sind deutlich besser. Der Testaufbau war ähnlich aufgebaut Bei Test3 haben 3 Leute gleichzeitig Rechnungen getippt.
Ich hab nochmal Bernds extract_request drangehängt. Es ist schon deutlich bei df1 wo nur einer eine rechnung eingibt. Also muss ich mich woanders hier auf die Suche machen.(Netzwerk, Proxmox und VM, Postgres, Apache)

Also available in: Atom PDF