Lausige Performance von Multithreaded Java-Agenten.

    Hallo miteinander,


    einen habe ich hier noch, über den ich noch nicht so recht drüberkucke:


    Gegeben ist ein Java-Agent, der sich über eine View eine Reihe von UniversalIDs zieht und damit eine Hashtable füllt.


    Wenn eine Hashtable eine gewisse Anzahl von UNIDs enthält, wird mit dieser Hashtable und einer neuen NotesSession ein Worker-Thread gestartet, der dann die eigentliche Arbeit über dieser Teilmenge von Dokumenten übernimmt. Nach dem Start eines Workers wird eine neue Hashtable mit wiederum 2000 UNIDs gefüllt und der nächste Worker angestoßen, bis die komplette View abgearbeitet ist. Auf diese Weise werden ca. 20 Threads gestartet, die dann 2000 Dokumente pro Thread abarbeiten sollen.


    Das Abholen der Unids geht rasend schnell.
    800 UNIDs pro Sekunde sind kein Problem. Der Server jammert dort dann etwas von 20.000 Transactions/Minute aber das soll so sein. ;)


    Das eigentliche Bearbeiten der Teilmengen in den Workern jedoch enttäuscht ungemein. Der Client, auf dem der Agent läuft, hat eine CPU-Auslastung von 20% und einen Netzwerktraffic von noch nicht mal 100k/sec.


    Der Server (Unix) hat während dem Lauf der Worker einen Load von 1 und einen Netz-IO, der gerade mal einer 10MBit Netzwerkkarte gerecht wird. Die Durchsätze im Nicht-Notes-Bereich erreichen jedoch problemlos 10 MBYTES/sec.


    Das SCSI-Raid zeigt einen Disk-IO von nicht mal 3 MB/sec an. Gemessen wurde mit Bonnie jedoch auf diesem Server ein Disk-IO von 50MB/sec. Entsprechend ist auch die im wait() verbrachte Zeit auf dem Server recht niedrig.


    Der Server hat während dem reinen Worker-Lauf nur noch ca. 3000 Transactions / Minute.


    Beim Profiling des Agenten ergab es sich, daß die in den Workerthreads aufgerufene Funktion getDocumentByUnid() mehr als 95% der Zeit verbraucht. Wenn man einen einzelnen Worker-Thread im Debugger von Eclipse durchsteppt, bekommt man auch durchaus Wartezeiten von 10 Sekunden und mehr, wenn diese Funktion angetriggert wird und andere Threads hingegen "normal" laufen.


    getDocumentByUnid() ist normalerweise als rasend schnell bekannt, da sie direkt über die DocID das entsprechende Dokument aus der Datenbank beziehen kann?


    Wieso braucht getDocumentByUnid() jedoch in einer Multithreaded-Anwendung auf einmal so lange? Und wieso wird hierbei der Server und der Client nicht mehr belastet? Kann man irgendwelche Einstellungen vornehmen, die diese Funktionen etwas mehr aufpeppen, wenn sie multithreaded laufen? Oder liegt da über der API ein dermaßen breiter und wenig granularer Lock, daß nichts geht, wenn eine Notes-API-Funktion aufgerufen wird?



    a--

    Hi,


    vielleicht hat die (default) Ansicht ein Problem oder der Index ist fehlerhaft. Laß einfach einmal die Ansichtsinizees neu aufbauen bzw. erstelle einmal einen Volltextindex.

    Für jedes Problem gibt es eine einfache Lösung, die es noch schlimmer macht.

    Hallo auch,


    recht herzlichen Dank für die Antwort.
    Werden denn UniversalIDs auch in Ansichten gehalten, so daß man diese dann "refreshen" muß, um mit getDocumentByUnid() darauf zuzugreifen? Wäre mir neu.


    Zu den NotesThreads: Jeder Worker initialisiert einen eigenen NotesThread und startet eine eigene Session auf dem Server. Man sieht dann auch schön, im Notes-Log, daß sich nach dem Ende der Worker-Sessions mal eben 20 User auf einen Schlag abmelden.


    Code
    // Neuen Notes-Thread aufmachen...
NotesThread.sinitThread();
SESSION=NotesFactory.createSession();


    Das hätte ich auch zuerst vermutet, daß über dem einen NotesThread ein fetter Lock liegt.


    Interessanterweise ergibt das Bearbeiten von zwei gleich großen Teilmengen der ca. 40.000 Dokumente enthaltenden View an zwei verschiedenen Rechnern eine um den Faktor 2 verringerte Laufzeit, so daß man den Flaschenhals ohnehin auf dem Client vermutet hätte. Das war überhaupt erst der Anlass für den Ansatz, um mit Multithreading die Laufzeit verkürzen zu wollen. 20 Threads ergeben aber ebenfalls nur eine Verkürzung der Laufzeit um den Faktor 1,5 bis 1,7 und nicht 10, wie ich ursprünglich mindestens erwartet hätte.


    a--

    Nein genau den meinte ich. Eine ganze Menge der Punkte haben auch mit Java Agenten selbst zu tun, denn spätestens wenn du per sInitThread einen neuen Thread aufmachst dann greifst du genau so zu und damit gelten all diese Punkte

    Genau - und dort in dem Artikel steht auch:


    Zitat


    Within a session, Domino Objects are shared, synchronized, and recycled across threads. Using a different session on each thread loses these capabilities; you must explicitly manage synchronization and recycle on a per-thread basis.


    Einstellungen - soweit dort in den beiden Artikeln aufgeführt - betreffen ausdrücklich DIIOP und die Webservices auf dem Server. Diese sind jedoch nicht aktiviert. Welche nicht-DIIOP betreffenden Einstellungen konkret meintest Du, sollte ich überprüfen?


    Da alle Workerthreads jedoch eine eindeutig abgegrenzte Teilmengen bearbeiten, sollte man doch annehmen, daß die Synchronisierung für die Funktionen aufgehoben ist und man den vollen Durchsatz erhält.


    Insbesondere für das getDocumentByUnid() scheint dies nicht zu gelten.




    a--

    Natürlich gilt das nicht, denn wenn du dir ein Dokument holst und gleichzeitig eines veränderst müssen z.b. entsprechende Ansichten aktualisiert werden und auch das kostet Zeit.


    Und vor allem wenn du mehrere Threads verwendest kann sich das ganz schön hochschaukeln.


    Und wie schon gesagt: Wenn du per sInitThread einen neuen Thread aufmachst, dann tust du das über die Domino Java Klassen, d.h. dieser greift nicht mehr direkt auf den Server zu sondern über die entsprechenden externen Klassen und damit gelten auch alle Regeln für den lokalen Notes Zugriff in diesem Artikel.

    Zitat


    Natürlich gilt das nicht, denn wenn du dir ein Dokument holst und gleichzeitig eines veränderst müssen z.b. entsprechende Ansichten aktualisiert werden und auch das kostet Zeit.
    Und vor allem wenn du mehrere Threads verwendest kann sich das ganz schön hochschaukeln.


    Dem widerspricht aber die Beobachtung, daß zwei unterschiedliche PCs, die hälftige Teilmengen bearbeiten, die halbe Zeit brauchen.


    Ich hätte mich obendrein noch viel mehr gewundert, wenn ein Index mit einer so hervorragenden Dispersion der Werte, wie eine DocID sie darstellt, so herbe Probleme hätte. Aber dies ist nicht der Fall.


    Nebenbei würden wir bei einer Index-Aktualisierung obendrein einen höheren Server-Load beobachten. Auch das ist nicht der Fall. Ebensowenig wie IO-Waits auf dem Disk-System.


    Obendrein wird nur eine sehr geringe veränderte Teilmenge der Dokumente überhaupt gespeichert. Der Flaschenhals ist aber getDocumentByUnid() mit ca. 95% der Laufzeit - und das schreibt - hoffentlich außer in irgendwelchen RAM-Buffern - nix ;)


    Zitat

    schon gesagt: Wenn du per sInitThread einen neuen Thread aufmachst, dann tust du das über die Domino Java Klassen, d.h. dieser greift nicht mehr direkt auf den Server zu sondern über die entsprechenden externen Klassen und damit gelten auch alle Regeln für den lokalen Notes Zugriff in diesem Artikel.


    Aber da simmer wieder beieinander. :)


    Welche Einstellungen auf dem Client kann man vornehmen, um diese Begrenzungen aufzubohren?


    Ich mag es nur schwer glauben, daß die Client C-API, über die wir letztendlich reden, dort einen dermaßen fetten Lock über dem native Call sitzen hat oder daß es gar nur einen statischen Buffer für Dokumente gibt, der dann über die Threads hinweg synchronisiert werden muß.


    Obendrein ist dieses Verhalten von Multithreaded-Java-Agenten und dem dicken Performance-Malus beim Multithreading sowohl in R5 als auch in R7 zu beobachten.


    a--

    Nein das widerspricht sich bei weitem nicht:


    Wenn mehrere Threads auf einem Client was verändert, dann aktualisiert dieser Client die Ansichtsindizes und macht das eventuell doppelt.


    Machen es zwei verschiedene Clients mit einem Thread, dann werden die Indizes auch nur jeweils einmal aktualisiert.


    Ist dir noch nie aufgefallen, daß ein manuelles Aufbauen des Ansichtsindexes dem Server gar nicht wirklich viel ausmacht, denn die Arbeit macht der Client und nicht der Server

    Sigh - ich drücke mich wohl manchmal sehr missverständlich aus.


    Da hätte ich gleich von Anfang an mehr auf das Zahlenverhältnis zwischen Read und Write hinweisen müssen ( und es ist ja hoffentlich unstrittig, daß nur Writes die Indizes verändern).


    Hier mal ein Snippet des Logs des soeben laufenden Tests:


    Code
    2007-02-15 04:40:54.515  INFO1 : 18 Docs / sec. (3 von 50059 gespeichert) bei 36 Threads
2007-02-15 04:41:24.451  INFO1 : 18 Docs / sec. (10 von 50772 gespeichert) bei 36 Threads
2007-02-15 04:41:54.387  INFO1 : 18 Docs / sec. (19 von 51529 gespeichert) bei 36 Threads


    Die 18 Dokumente / sec. sind inklusive der Zeit zu interpretieren, die es braucht, die Hashtables und Threads zu initialisieren.


    Bei der Single-Threaded-Version waren es etwa 12 Dokumente pro Sekunde.


    720 Dokumente in 30 Sekunden sind also runde 24 Dokumente pro Sekunde. Da hätte ich schon eine Zehnerpotenz mehr erwartet.


    Zu den gespeicherten Dokumenten: Es sind also gerade mal 0,3 Promille der Grundmenge gespeichert worden.


    Und diese 0,3 Promille der Grundmenge aller Dokumente sollen dafür verantwortlich sein, daß in einem Thread ein getDocumentByUnid() mehrere Sekunden dauert und daß alle 36 Threads gerade mal 24 Dokumente pro Sekunde schaffen, wo sonst ein getDocumentByUnid() in einer hunderstel Sekunde durch ist?


    Das ist ja noch viel schlimmer als zunächst befürchtet. Was, wenn dieser Agent im kleinen einstelligen Prozentbereich Dokumente verändern muß?


    Die Dokumente selbst, die in diesem Agenten bearbeitet werden, sind obendrein nicht sehr groß. Bei einem anderen Agenten mit etwa 5 mal mehr Feldern dieser Dokumentenklasse kommt der Agent auf noch nicht mal 10 Dokumente pro Sekunde.


    Und Einstellungsmöglichkeiten sind somit erst gleich garnicht zu erwarten, wenn ich den bisherigen Thread hier in der Retrospektive so lese?



    a--

    ... googlen hilft ...


    Andrew Pollack kommt zu einem noch verheerenderen Ergebnis bei der Verwendung von Multithreading mit separaten Sessions verglichen mit einer Session:


    Multithreading-Artikel von Andrew Pollack




    Ich lass' das jetzt einfach mal so stehen und versuche es morgen mit einer shared-Session über alle Threads.



    a--

    Nur noch der Vollständigkeit halber:


    Eine Session die von allen Threads verwendet wird, bringt hier bei dem Agenten nicht den massiven Geschwindigkeitsvorteil, den Pollack gemessen hat.



    Die CPU- und Netzlast auf dem Client und dem Server ist auch bei diesem Test im niedrigen einstelligen Prozentbereich, so als ob die Threads innerhalb der C-API wirklich nur auf ihre gegenseitige Synchronisierung warteten.


    Augenblicklich läuft dieser Agent ca. eine Stunde. Wie kann dieser Agent denn noch auf mindestens 200 Docs / sec. beschleunigt werden?


    a--

    Es gibt ja die Einschränkung, daß innerhalb einer Datenbank auch immer nur ein Agent zur gleichen Zeit laufen kann.
    Vermutlich wird dies bei den Threads genauso sein. Denn das Beispiel von Andrew Pollack greift ja auf zwei unterschiedliche Datenbanken laut Beschreibung zu.

    Zitat


    Es gibt ja die Einschränkung, daß innerhalb einer Datenbank auch immer nur ein Agent zur gleichen Zeit laufen kann.


    Seit wann denn das? Mir ist nur bekannt, daß man die Anzahl der gleichzeitig laufenden Agenten und deren Laufzeit beschränken kann. Aber das bezieht sich auch mehr auf das Serverdokument und nicht auf den Client.


    Wir haben durchaus mehrere Agenten gleichzeitig auf der gleichen Datenbank und auch auf dem gleichen Server laufen. Ansonsten hätten wir auch ein kleines Zeitproblem, wenn das der Fall wäre.


    Zitat


    Vermutlich wird dies bei den Threads genauso sein. Denn das Beispiel von Andrew Pollack greift ja auf zwei unterschiedliche Datenbanken laut Beschreibung zu.


    ... und läuft genauso in einen Synchronize der C-API wie hier. Seine Feststellung zumindest im Bereich der nichts weiter berechnenden Collection-Zugriffe ist noch graviender:


    Zitat


    Maybe even more interesting, is that while there was virtually no difference when doing this on one thread at a time -- in fact it was faster IN TOTAL to do it sequentially than on distinct threads.


    Aber diese Aussage kann ich hier gottseidank auch nicht nachvollziehen.


    Multithreading bringt zumindest an den Stellen einen Vorteil in der Größenordnung von knapp 100%, wenn man Berechnungen in den Agenten drin hat, die nicht auf die Notes-Daten zugreifen müssen. Wowereit! :)


    Denn die Zugriffe auf Notes-Daten besitzen offenbar ein in der API hart kodiertes Limit der gleichzeitigen Zugriffe, das auch schon in R5 vorhanden war und das auch noch in R7 vorhanden sein muß und das auch wohl nicht so einfach zu beseitigen ist, denn sonst wäre dies mit Sicherheit schon geschehen.


    Hat irgendwer mal zu dem Thema einen PMR eröffnet und mag die Aussage von IBM hier mal posten?


    a--


    P.S.: In Notes-Script lief der Agent damals 6 Stunden. In Java Singlethreaded zwei Stunden und mit Multithreading eine Stunde. Erwartet wären maximal 10 Minuten. Aber das wird sich offenbar zumindest mit R7 nicht darstellen lassen.

    Du redest von mehreren aktivierten Agenten auf der gleichen Datenbank.
    Ich rede aber von mehreren laufenden Agenten auf der gleichen Datenbank.


    Wenn diese vom gleichen Task ausgeführt werden müssen, dann geht das nicht.


    Such mal z.b. im LDD Forum nach "multiple agents database". Dorf findest du dann einige Antworten von Julie Kadashevich die genau das bestätigen.


    Z.b.:


    Zitat


    If all your agents reside in the same database they will not be scheduled to be executed at the same time.


    Und die Aussage kann ich aufgrund eigener Beobachtungen auch voll bestätigen


    Das das auch bei Multithreaded Java Agents zutreffen könnte ist nur eine Vermutung meinerseits.

    Probier's doch mal aus und nimm zwei Agenten, die irgend etwas ins Notes-Log schreiben:


    tell amgr run "database.nsf" 'agent1'
    tell amgr run "database.nsf" 'agent2'


    Und schau' Dir das Notes-Log an.


    Hier auf dem Testserver printen gerade zwei unterschiedliche Agenten ihre Status in das Log. Der eine bearbeitet die Dokumentenklasse UKO und der andere die Dokumentenklasse SKO:


    Zitat

    16.02.2007 02:58:14 PM Agent Manager: Agent error: 2007-02-16 02:58:15.333 INFO1 : THREAD Nr 7 UKO in BB3 fertig - Dauer: 546.947


    16.02.2007 02:58:16 PM 0 Transactions/Minute, 8 Notes Users
    > 16.02.2007 02:58:18 PM Agent Manager: Agent error: 2007-02-16 02:58:19.799 INFO1 : THREAD Nr 9 UKO in BB3 fertig - Dauer: 547.662
    16.02.2007 02:58:20 PM Agent Manager: Agent printing: 2007-02-16 02:58:21.207 sko_in_BB3 : 2500 von 31874 Dokumenten ( 29374 fehlen ETA : 1,95 h ) 0 saved 2500 not saved


    Beide Agenten laufen in der selben Datenbank auf dem selben Server. Ich schwör's :)


    Mag sein, daß das in einer Pre-R7 nicht funktionierte. Was in R7 auch noch nicht funktioniert, ist die Anzeige der Transactions/Minute, wenn Serveragenten laufen. Die wurden in R5 auch schon nicht angezeigt.


    In R5 zumindest führte das Starten von Java-Agenten die mit JDBC an einer Postgres-DB Abgleiche fahren, zuverlässig zu einem Crash des Servers. Äh - wir reden doch noch von Java-Agenten?


    Und von der Julie habe ich auch schon lange nichts mehr gelesen. Ist die überhaupt noch bei dem Verein?



    a--

    Nur der Vollständigkeit halber: Auf dem Server (Dual P3 1Ghz mit 4GB RAM) sieht die Anzahl der Dokumente pro Sekunde schon viel erfrischender aus. Einige Threads sind schon mir ihrer Teilmenge von 2000 Dokumenten durch - die anderen laufen noch:



    Jetzt fehlt nur noch der Geschwindigkeitsfaktor 3 und ich bin schon fast zufrieden. :)



    a--

    Das tell amgr run verhält sich da meines Wissens nach auch anders. Aber versuch das mal mit periodischen die zum gleichen Zeipunkt in der gleichen DB laufen sollen. Da wird dann erst der eine dann der andere ausgeführt