langsame evtl. synchrone Auslieferung am Client

Apr 17, 2013 at 11:47 AM
Hallo Thomas.


Wir nutzen die CCR und XcoAppSpace immer noch fleißig.

In einem neuen Projekt ist mir aufgefallen, das die Antworten vom Server am Client sehr langsam ankommen.

Am Server selbst hingegen geht alles sehr schnell und auch asynchron von statten.

verschiedene Sachen habe ich am geprüft:

1) wir haben 'SyncContext.UseCurrentSyncContext' am Client nicht aktiv
2) am Server '.Space.RunWorker<PWorker, WorkerImplementation>(...)' der Serice Implementierung mit einem eigen konfigurierten 'DispatcherQueue' laufen lassen
3) möglichkeit 2) auf Client Seite scheint es nicht zu geben, '_space.DefaultDispatcher = new Dispatcher()' geht auch nicht das es kein 'Set' gibt
4) analog den Receive mit eigenen dp abzuhandel (https://xcoappspace.codeplex.com/wikipage?title=AppSpaceExtensions) hilft jedoch auch nicht diesen entsprechend zu konfigurieren:
new DispatcherQueue("HighQue", new Dispatcher(6, ThreadPriority.Highest, DispatcherOptions.UseProcessorAffinity, ApartmentState.MTA, "SystemHigh"));
Nachfolgend noch ein paar Console.WriteLine Ausgaben, welche über den Zeitstempel meine Aussagen/Annahmen verdeutlichen sollen.

Als XcoAppSpace Version verwenden wir 1.4.0.0 pre Build von Euch.


Gruß Roberto


SERVER SERVICE START

Hier werden die benötigten Daten (Market, ProductGroup, Underlying, ...), welche später vom Client abgeholt werden, lokal in ein 'ConcurrentDictionary' geladen.
Es wird eine eigene 'DispatcherQueue' verwendet.
Wie man sieht erfolgt das Laden parallel und sehr schnell.

11:38:07-2253122 START GetDataFromDb: 'htt.dbentities.Market' using connection: 71e72ca0-2870-410a-90f1-74b22b34e887
11:38:07-2263123 START GetDataFromDb: 'htt.dbentities.ProductType' using connection: 504fc42b-2b1b-4cb8-84d2-71a388b48990
11:38:07-2253122 START GetDataFromDb: 'htt.dbentities.ProductGroup' using connection: 66ec0629-461f-4b76-8992-da8b66f9788e
11:38:07-2303125 START GetDataFromDb: 'htt.dbentities.Underlying' using connection: 888dcdd3-e5b3-48c9-856f-acc031cbdd03
11:38:07-2343128 START GetDataFromDb: 'htt.dbentities.UnderlyingForMarket' using connection: ca93eeea-5caa-41cf-9376-9d992a691f66
11:38:07-2383130 START GetDataFromDb: 'htt.dbentities.ParamSet' using connection: 2acfcb5a-78d4-4823-b563-015370e1fad7
11:38:07-2773152 DONE GetDataFromDb: 'htt.dbentities.ProductGroup' used connection: 66ec0629-461f-4b76-8992-da8b66f9788e
11:38:07-2773152 DONE GetDataFromDb: 'htt.dbentities.ProductType' used connection: 504fc42b-2b1b-4cb8-84d2-71a388b48990
11:38:07-2773152 DONE GetDataFromDb: 'htt.dbentities.Market' used connection: 71e72ca0-2870-410a-90f1-74b22b34e887
11:38:07-2783153 DONE GetDataFromDb: 'htt.dbentities.UnderlyingForMarket' used connection: ca93eeea-5caa-41cf-9376-9d992a691f66
11:38:07-2783153 START GetDataFromDb: 'htt.dbentities.ParamDateBucket' using connection: 2267852d-bc23-4181-bb65-4e265054c6ad
11:38:07-2793153 DONE GetDataFromDb: 'htt.dbentities.Underlying' used connection: 888dcdd3-e5b3-48c9-856f-acc031cbdd03
11:38:07-2793153 START GetDataFromDb: 'htt.dbentities.ParamDeltaBucket' using connection: 66ec0629-461f-4b76-8992-da8b66f9788e
11:38:07-2793153 DONE GetDataFromDb: 'htt.dbentities.ParamSet' used connection: 2acfcb5a-78d4-4823-b563-015370e1fad7
11:38:07-2793153 START GetDataFromDb: 'htt.dbentities.ParamSpanBucket' using connection: 504fc42b-2b1b-4cb8-84d2-71a388b48990
11:38:07-2863157 START GetDataFromDb: 'htt.dbentities.ParamTimeBucket' using connection: 71e72ca0-2870-410a-90f1-74b22b34e887
11:38:07-2883158 START GetDataFromDb: 'htt.dbentities.ParamDateValue' using connection: ca93eeea-5caa-41cf-9376-9d992a691f66
11:38:07-2883158 START GetDataFromDb: 'htt.dbentities.ParamDeltaValue' using connection: 888dcdd3-e5b3-48c9-856f-acc031cbdd03
11:38:07-3053168 DONE GetDataFromDb: 'htt.dbentities.ParamDeltaBucket' used connection: 66ec0629-461f-4b76-8992-da8b66f9788e
11:38:07-3063169 DONE GetDataFromDb: 'htt.dbentities.ParamDateBucket' used connection: 2267852d-bc23-4181-bb65-4e265054c6ad
11:38:07-4523252 START GetDataFromDb: 'htt.dbentities.ParamSpanValue' using connection: 2acfcb5a-78d4-4823-b563-015370e1fad7
11:38:07-4523252 START GetDataFromDb: 'htt.dbentities.ParamTimeValue' using connection: 60adc811-c199-440a-a9b1-ae040bcbab7d
11:38:07-4753265 DONE GetDataFromDb: 'htt.dbentities.ParamSpanValue' used connection: 2acfcb5a-78d4-4823-b563-015370e1fad7
11:38:07-4763266 DONE GetDataFromDb: 'htt.dbentities.ParamDeltaValue' used connection: 888dcdd3-e5b3-48c9-856f-acc031cbdd03
11:38:07-4773267 DONE GetDataFromDb: 'htt.dbentities.ParamTimeValue' used connection: 60adc811-c199-440a-a9b1-ae040bcbab7d
11:38:07-4773267 DONE GetDataFromDb: 'htt.dbentities.ParamDateValue' used connection: ca93eeea-5caa-41cf-9376-9d992a691f66
11:38:07-4793268 DONE GetDataFromDb: 'htt.dbentities.ParamSpanBucket' used connection: 504fc42b-2b1b-4cb8-84d2-71a388b48990
11:38:07-4793268 DONE GetDataFromDb: 'htt.dbentities.ParamTimeBucket' used connection: 71e72ca0-2870-410a-90f1-74b22b34e887
11:38:07-6523367 START GetDataFromDb: 'htt.dbentities.Cockpit' using connection: 65b074eb-1a5d-4190-9047-b2858113924b
11:38:07-7793439 DONE GetDataFromDb: 'htt.dbentities.Cockpit' used connection: 65b074eb-1a5d-4190-9047-b2858113924b


SERVER SERVICE CLIENT REQUEST + RESPONSE

Hier werden die Daten vom Client am Server empfangen und beantwortet.
Auch dies erfolgt parallel und sehr zeitnah.


RECEIVING REQUEST FROM CLIENT AT SERVER = ListRequest
SEND RESPONSE FROM SERVER TO CLIENT = ProcessPublishData

11:38:21-5061291 ListRequest 'ProductType' received
11:38:21-5061291 ListRequest 'Underlying' received
11:38:21-5061291 ListRequest 'ProductGroup' received
11:38:21-5071291 ListRequest 'Market' received
11:38:21-5081292 ListRequest 'UnderlyingForMarket' received
11:38:21-5091292 ListRequest 'ParamSet' received
11:38:21-5181297 ProcessPublishData 'ParamSet' done
11:38:21-5181297 ProcessPublishData 'Market' done
11:38:21-5181297 ProcessPublishData 'ProductType' done
11:38:21-5181297 ProcessPublishData 'ProductGroup' done
11:38:21-5181297 ListRequest 'ParamDateBucket' received
11:38:21-5181297 ProcessPublishData 'Underlying' done
11:38:21-5181297 ProcessPublishData 'UnderlyingForMarket' done
11:38:21-5181297 ListRequest 'ParamDeltaBucket' received
11:38:21-5181297 ListRequest 'ParamTimeBucket' received
11:38:21-5181297 ListRequest 'ParamSpanBucket' received
11:38:21-5201299 ProcessPublishData 'ParamSpanBucket' done
11:38:21-5201299 ProcessPublishData 'ParamTimeBucket' done
11:38:21-5201299 ProcRequestDataItem ProductType done
11:38:21-5201299 ProcessPublishData 'ParamDeltaBucket' done
11:38:21-5381309 ListRequest 'ParamDateValue' received
11:38:21-5391309 ListRequest 'ParamDeltaValue' received
11:38:21-5391309 ProcessPublishData 'ParamDateValue' done
11:38:21-5401310 ProcessPublishData 'ParamDeltaValue' done
11:38:21-5401310 ListRequest 'ParamSpanValue' received
11:38:21-5411311 ListRequest 'ParamTimeValue' received
11:38:21-5421311 ProcessPublishData 'ParamSpanValue' done
11:38:21-5421311 ProcessPublishData 'ParamTimeValue' done
11:38:21-5471314 ListRequest 'Cockpit' received
11:38:21-5481315 ProcessPublishData 'Cockpit' done

RECEIVING RESPONSE FROM SERVER AT CLIENT

Hieraus resultiert meine Anfrage.

Ersten Antworten treffen relativ schnell ein, die folgenden im 1 - 2 Sekunden Takt.
Die Ausgabe der Debug Nachricht erfolgt direkt nach erhalten der Nachricht (.Receive(port,handler)) in einer Methode.
Auch wenn ich nachgelagerte Schritte in der Methode entferne, tröpfeln die Resultate langsam ein.

Was ist hier los, ich bin überfragt...


11:38:22-0241587 DataItem Update Market received from server
11:38:22-3391767 DataItem Update ProductGroup received from server
11:38:22-8392053 DataItem Update ProductType received from server
11:38:23-3422341 DataItem Update Underlying received from server
11:38:23-8432627 DataItem Update UnderlyingForMarket received from server
11:38:24-8413198 DataItem Update ParamSet received from server
11:38:25-8403770 DataItem Update ParamDateBucket received from server
11:38:26-8414342 DataItem Update ParamDeltaBucket received from server
11:38:27-8464917 DataItem Update ParamSpanBucket received from server
11:38:28-9375541 DataItem Update ParamTimeBucket received from server
11:38:29-8406058 DataItem Update ParamDateValue received from server
11:38:30-8386628 DataItem Update ParamDeltaValue received from server
11:38:31-8407202 DataItem Update ParamSpanValue received from server
11:38:32-8487778 DataItem Update ParamTimeValue received from server
11:38:33-8438347 DataItem Update Cockpit received from server
Coordinator
Apr 19, 2013 at 8:08 AM
Hallo Roberto,

Es freut mich zu hören, dass ihr den AppSpace noch verwendet!

Zu eurem Problem kann ich derzeit fürchte ich nur Vermutungen anstellen, hier ein paar Gedanken dazu:
  • Da du sagst, dass sowohl der Worker am Server als auch das Receive am Client in einem eigenen Dispatcher laufen, würde ich die lokale Auslastung des Rechners als Problem mal weitgehend ausschließen
  • Wie groß sind in etwa die versendeten Nachrichten? Wenn es sich um größere Datenmengen handelt, könnte das, auch abhängig von der zur Verfügung stehenden Bandbreite, die Verzögerung erklären. Über space.Info.CommunicationEvents lässt sich hierfür z.B. eine Log Ausgabe bei Senden/Empfangen einbauen, um die Größe des byte-Arrays auszugeben.
  • Der Empfang könnte auch dadurch verzögert werden, dass der Kanal durch das Senden/Empfangen anderer Nachrichten blockiert ist, z.B. wenn der Client selbst ständig Nachrichten sendet, könnte sich der Empfang von Nachrichten dadurch verzögern. D.h. gibt es irgendeine andere Kommunikation, die läuft während der Client auf diese Nachrichten wartet?
  • Verwendet ihr eine spezielle Transport-Konfiguration, oder den Default (TCP Transport, Binary Serializer)?
  • Lässt sich das Problem in einer kleinen Test-Solution isolieren? Wenn ja dann schicke mir diese gern zu und ich sehe sie mir an.
  • Einschalten des Loggings könnte eventuell helfen, das Problem genauer zu analysieren (siehe https://xcoappspace.codeplex.com/wikipage?title=LoggingFeature - zum Logging in ein File noch einen TextWriterTraceListener hinzufügen) - vor allem auch dann, wenn eine Isolation des Problems in einer Test-Solution nicht möglich sein sollte.
Ich hoffe ich konnte dir ein paar hilfreiche Hinweise geben!

MfG
Thomas
Apr 19, 2013 at 10:15 AM
Edited Apr 19, 2013 at 10:21 AM
Hallo Thomas.


Haja ist ja auch ein cooles Ding. Und da ich die CCR eh prächtig finde passt das sehr gut. (ich muss noch mit .net 3.5 arbeiten entsprechend kann ich TPL nicht nutzen, was nicht schlimm ist!)

Unten nachstehend kursiv meine Kommentare.
  • Da du sagst, dass sowohl der Worker am Server als auch das Receive am Client in einem eigenen Dispatcher laufen, würde ich die lokale Auslastung des Rechners als Problem mal weitgehend ausschließen
    Nein der hat Reserven und sollte nicht das Problem sein.
  • Wie groß sind in etwa die versendeten Nachrichten? Wenn es sich um größere Datenmengen handelt, könnte das, auch abhängig von der zur Verfügung stehenden Bandbreite, die Verzögerung erklären. Über space.Info.CommunicationEvents lässt sich hierfür z.B. eine Log Ausgabe bei Senden/Empfangen einbauen, um die Größe des byte-Arrays auszugeben.
    _Aktuell noch recht kleine Datenmengen. Es sind sind BindingLists<T> mit EntityObject Objekten aus einer MS SQL Datebank. Aber aktuell sind wenig Daten enthalten. Ca. 10-15 Zeilen pro Entity (Market, ProductGroup, ParamSet, ProductTyp, Underlying, ParamTimeBucket, ParamDeltaBucket, ParamSpanBucket, ParamDateBucket, ParamDateValue, ParamSpanValue, ParamDeltaValue, ParamTimeValue, Cockpit = 14 Stück).
    Die Ausgabe gibt hier für die BindingLists 2048 byte aus. Beim Übertragen von Änderungen zurück zum Server sind es 8192 byte._
  • Der Empfang könnte auch dadurch verzögert werden, dass der Kanal durch das Senden/Empfangen anderer Nachrichten blockiert ist, z.B. wenn der Client selbst ständig Nachrichten sendet, könnte sich der Empfang von Nachrichten dadurch verzögern. D.h. gibt es irgendeine andere Kommunikation, die läuft während der Client auf diese Nachrichten wartet?
    Nein das ist die erste Kommunikation. Da passiert noch nicht so viel. Meine Überlegung eben war, das die verschiedenen Worker evtl. erst warm werden müssen. Quasi einmal etwas übertragen haben müssen damit sie fortan zügiger arbeiten. Entsprechend habe ich eine Möglichkeit (nur zum Testen) eingebaut die Daten neu laden zu lassen. Hier nun werden die Daten sehr zeitnah übertragen. Jedoch irgendwie auch nicht immer.
  • Verwendet ihr eine spezielle Transport-Konfiguration, oder den Default (TCP Transport, Binary Serializer)?
    Nein. Default TCP/ BinSer wird verwendet
  • Lässt sich das Problem in einer kleinen Test-Solution isolieren? Wenn ja dann schicke mir diese gern zu und ich sehe sie mir an.
    Schwierig diesen Teil raus zu lösen.
  • Einschalten des Loggings könnte eventuell helfen, das Problem genauer zu analysieren (siehe https://xcoappspace.codeplex.com/wikipage?title=LoggingFeature - zum Logging in ein File noch einen TextWriterTraceListener hinzufügen) - vor allem auch dann, wenn eine Isolation des Problems in einer Test-Solution nicht möglich sein sollte.
    Hatte ich schon gemacht. Keine Probleme welche hierdurch erkannt wurden.
Gruß Roberto
Apr 19, 2013 at 2:38 PM
Edited Apr 19, 2013 at 3:54 PM
Ab und an, scheint irgendetwas ein Fehler auszulösen was folgendes auswirft:

Eine Ausnahme (erste Chance) des Typs "System.Net.Sockets.SocketException" ist in System.dll aufgetreten.
XcoAppSpaces.Transport.Sockets Error: 0 : Error sending Message to Address: wks1:62700
System.Net.Sockets.SocketException: Es konnte keine Verbindung hergestellt werden, da der Zielcomputer die Verbindung verweigerte -5.--4.-7.--7:627--
bei System.Net.Sockets.Socket.Connect(IPAddress[] addresses, Int32 port)
bei System.Net.Sockets.TcpClient.Connect(IPAddress[] ipAddresses, Int32 port)
bei XcoAppSpaces.Transport.Sockets.TCPClient.GetTcpClient(String remoteAddress) in d:\Development\Uni\XcoAppSpaces\source.implementation\XcoAppSpaces.Transport.Sockets\XcoAppSpaces.Transport.Sockets\TCPClient.cs:Zeile 101.
bei XcoAppSpaces.Transport.Sockets.TCPClient..ctor(TCPServer server, String remoteAddress, SecuritySettings securitySettings, IXcoLogger log) in d:\Development\Uni\XcoAppSpaces\source.implementation\XcoAppSpaces.Transport.Sockets\XcoAppSpaces.Transport.Sockets\TCPClient.cs:Zeile 57.
bei XcoAppSpaces.Transport.Sockets.XcoTCPTransportService.CreateSender(String remoteAddress) in d:\Development\Uni\XcoAppSpaces\source.implementation\XcoAppSpaces.Transport.Sockets\XcoAppSpaces.Transport.Sockets\XcoTCPTransportService.cs:Zeile 284.
bei XcoAppSpaces.Transport.Sockets.XcoTCPTransportService.ReCreateSender(String remoteAddress, TCPClient oldSender) in d:\Development\Uni\XcoAppSpaces\source.implementation\XcoAppSpaces.Transport.Sockets\XcoAppSpaces.Transport.Sockets\XcoTCPTransportService.cs:Zeile 322.
bei XcoAppSpaces.Transport.Sockets.XcoTCPTransportService.Send(XcoMessage msg, String remoteAddress) in d:\Development\Uni\XcoAppSpaces\source.implementation\XcoAppSpaces.Transport.Sockets\XcoAppSpaces.Transport.Sockets\XcoTCPTransportService.cs:Zeile 255.
Eine Ausnahme (erste Chance) des Typs "XcoAppSpaces.Contracts.Exceptions.XcoCommunicationException" ist in XcoAppSpaces.dll aufgetreten.
Eine Ausnahme (erste Chance) des Typs "System.Net.Sockets.SocketException" ist in System.dll aufgetreten.
XcoAppSpaces.Transport.Sockets Error: 0 : Error sending Message to Address: wks1:62700

[wks1 ist mein Rechner, die Anschließende IP (teile entfernt...) ist mir jedoch unbekannt, diese ist auch nicht konfiguriert.(nicht mehr aktuell die IP ist doch eine lokale (Hamachi Netzwerk))]
Das Problem steht aber nicht direkt im Zusammenhang mit oben. Es tritt auf, wenn der Client neu gestartet wurde, der Server also noch aktiv blieb und sich dann ein Client neu verbindet. Offenbar wenn der Client kein 'Unsubscribe' gemacht hat. Was passieren kann wenn der Client Abstürzt oder wie in meinem Fall ich den Debugger beende.
Coordinator
Apr 22, 2013 at 10:09 AM
Hallo Roberto,

Wenn ein Client abstürzt und es wurde kein Unsubscribe ausgeführt, dann tritt beim nächsten Mal wenn der Server eine Nachricht an den Client schicken will ein solcher Fehler auf. In diesem Fall wird dann für den entsprechenden Port ein automatisches Unsubscribe am Server gemacht. Der Fehler sollte also nach dem Absturz des Clients nur einmal im Log zu sehen sein.

Zu den Kommentaren weiter oben:
  • Die Übertragungsgeschwindigkeit sollte eigentlich immer gleich sein, auch wenn gerade erst die Verbindung zum Worker hergestellt wurde. Intern wird eine TCP Verbindung offen gehalten, die in beide Richtungen verwendet wird.
  • D.h. im Log sollte nur ein einziges Mal zu sehen sein, dass eine neue TCP Verbindung geöffnet wird, und keine "Error sending Message to Address ..." Einträge - sollte die Verbindung öfters neu geöffnet werden, könnte das auf Probleme hinweisen.
MfG
Thomas