What impacts the delay between message receipt and handling in handler?

Architecture & Design
1

Good day guys,

I was wondering if there is some configuration option I’m overlooking that has an impact on the delay between the receipt of the message from RabbitMQ by NServiceBus and the actual handling of the message (command) in the IHandleMessages<> handler.

I’m seeing a consistent delay when comparing the NServiceBus logfile and the logfile of the handler. It does vary a bit between client and server but in a given session it’s always constant. Now I’m running through all the options that I can find but there’s no real pointer for me out in the wild.

The thing is I’m running a workflow solution that uses NServiceBus to do all the messaging between the workflow server (based on MS WF) and 50/60 clients. The server runs on NServiceBus 7.6.0 but all client still use NServiceBus 5.2.26. I decided to write a small test client that also runs on NServiceBus 7.6.0 but that also shows the delay albeit a smaller one. But the delay between individual commands is constant at 6.5 seconds in the test client. So the message is retrieved by NSB from the queue and 6.5 seconds the IHandleMessages<> handler is invoked.

I’ve tried a couple of things (direct routing vs conventional routing, making sure license files where distributed properly for example). The only thing I’m able to come up right now is flat out making a new test server of the workflow server I’m using that is only able to accept 1 command, generating a reply and nothing more and see if that makes a difference.

I know there’s not much information to go on. I could give more code and log files but maybe there’s just this one thing that I’m overlooking on which everybody plainly reply “yeah, you just forgot to configure such and so”. Configuration wise the solution runs on Windows Server 2016, RabbitMQ 3.7.21 and NServiceBus 7.6.0. Clients run on Windows 10 machines using NServiceBus 5.2.26 but the test client uses NServiceBus 7.6.0.

Thanks in advance!

2

I’ve also posted the question on Stackoverflow with logs and code.

3

Test client log:

25-01-2022T14:44:50.4630: Client started. Press any key to send message ..
25-01-2022T14:44:56.8236: Sending GetVersionCommand ..
25-01-2022T14:44:56.8796: GetVersionCommand sent!
25-01-2022T14:45:08.9191: GetVersionReply reply received ..

NServiceBus logfile:

2022-01-25 14:44:56.972 DEBUG Processing message type: HyFlo.Service.Messages.Commands.Info.GetVersionCommand
Message headers:
CorrelationId : 0c6a1541-0a7c-4345-828e-463bf9166667
NServiceBus.MessageId : 47f1681d-afef-4e26-a36b-ae2800e29418
NServiceBus.MessageIntent : Send
NServiceBus.ConversationId : 8b54fcfe-b991-4c9c-8c0b-ae2800e2941a
NServiceBus.CorrelationId : 47f1681d-afef-4e26-a36b-ae2800e29418
NServiceBus.TimeToBeReceived : 00:10:00
NServiceBus.ReplyToAddress : Hyflo.Client.Test
NServiceBus.OriginatingMachine : DYP297
NServiceBus.OriginatingEndpoint : Hyflo.Client.Test
$.diagnostics.originating.hostid : 3a3bbd6661214b655aa6dbcd95d112a2
NServiceBus.ContentType : text/xml
NServiceBus.EnclosedMessageTypes : HyFlo.Service.Messages.Commands.Info.GetVersionCommand, HyFlo.Service.Messages, Version=4.10.3.26734, Culture=neutral, PublicKeyToken=null;HyFlo.Types.Interfaces.IInfoCommand, HyFlo.Types, Version=4.10.8.20782, Culture=neutral, PublicKeyToken=null
NServiceBus.Version : 7.6.0
NServiceBus.TimeSent : 2022-01-25 13:44:56:844666 Z
NServiceBus.NonDurableMessage : False
Handlers to invoke:
HyFlo.Service.CommandHandlers.Info.GetVersionHandler

2022-01-25 14:45:08.848 DEBUG Serializing message 'HyFlo.Service.Messages.InternalMessages.Info.GetVersionReply, HyFlo.Service.Messages, Version=4.10.3.26734, Culture=neutral, PublicKeyToken=null' with id '39b4a27d-eccd-42fd-9ae8-ae2800e2a22b', ToString() of the message yields: HyFlo.Service.Messages.InternalMessages.Info.GetVersionReply
2022-01-25 14:45:08.848 DEBUG HyFlo.Service.Messages.InternalMessages.HyfloReply identified as message type by NServiceBus Marker Interfaces convention.
2022-01-25 14:45:08.848 DEBUG Destination: Hyflo.Client.Test
Message headers:
CorrelationId : 0c6a1541-0a7c-4345-828e-463bf9166667
NServiceBus.MessageId : 39b4a27d-eccd-42fd-9ae8-ae2800e2a22b
NServiceBus.MessageIntent : Reply
NServiceBus.RelatedTo : 47f1681d-afef-4e26-a36b-ae2800e29418
NServiceBus.ConversationId : 8b54fcfe-b991-4c9c-8c0b-ae2800e2941a
NServiceBus.CorrelationId : 47f1681d-afef-4e26-a36b-ae2800e29418
NServiceBus.TimeToBeReceived : 00:10:00
NServiceBus.ReplyToAddress : hyflo.service
NServiceBus.OriginatingMachine : HSWV0601
NServiceBus.OriginatingEndpoint : hyflo.service
$.diagnostics.originating.hostid : 2a5a733a131925ae27cfd3bbc73e152c
NServiceBus.ContentType : text/xml
NServiceBus.EnclosedMessageTypes : HyFlo.Service.Messages.InternalMessages.Info.GetVersionReply, HyFlo.Service.Messages, Version=4.10.3.26734, Culture=neutral, PublicKeyToken=null;HyFlo.Service.Messages.InternalMessages.HyfloReply, HyFlo.Service.Messages, Version=4.10.3.26734, Culture=neutral, PublicKeyToken=null
NServiceBus.Version : 7.6.0
NServiceBus.TimeSent : 2022-01-25 13:45:08:848599 Z

2022-01-25 14:45:08.864 DEBUG Destination: hyflo.service.audit
Message headers:
CorrelationId : 0c6a1541-0a7c-4345-828e-463bf9166667
NServiceBus.MessageId : 47f1681d-afef-4e26-a36b-ae2800e29418
NServiceBus.MessageIntent : Send
NServiceBus.ConversationId : 8b54fcfe-b991-4c9c-8c0b-ae2800e2941a
NServiceBus.CorrelationId : 47f1681d-afef-4e26-a36b-ae2800e29418
NServiceBus.TimeToBeReceived : 00:10:00
NServiceBus.ReplyToAddress : Hyflo.Client.Test
NServiceBus.OriginatingMachine : DYP297
NServiceBus.OriginatingEndpoint : Hyflo.Client.Test
$.diagnostics.originating.hostid : 3a3bbd6661214b655aa6dbcd95d112a2
NServiceBus.ContentType : text/xml
NServiceBus.EnclosedMessageTypes : HyFlo.Service.Messages.Commands.Info.GetVersionCommand, HyFlo.Service.Messages, Version=4.10.3.26734, Culture=neutral, PublicKeyToken=null;HyFlo.Types.Interfaces.IInfoCommand, HyFlo.Types, Version=4.10.8.20782, Culture=neutral, PublicKeyToken=nul
NServiceBus.Version : 7.6.0
NServiceBus.TimeSent : 2022-01-25 13:44:56:844666 Z
NServiceBus.NonDurableMessage : False
NServiceBus.ProcessingStarted : 2022-01-25 13:44:56:926077 Z
NServiceBus.ProcessingEnded : 2022-01-25 13:45:08:848599 Z
$.diagnostics.hostid : 2a5a733a131925ae27cfd3bbc73e152c
$.diagnostics.hostdisplayname : HSWV0601
NServiceBus.ProcessingMachine : HSWV0601
NServiceBus.ProcessingEndpoint : hyflo.service

Hyflo logfile:

2022-01-25 14:45:03.5354 TRACE = New Message =========================================================
2022-01-25 14:45:03.5354 TRACE CommandEventId:51f8ffa9-c00c-417c-bf71-03bb3ad83637: New message handled by handler of type 'HyFlo.Service.CommandHandlers.Info.GetVersionHandler' with CorrelationId '0c6a1541-0a7c-4345-828e-463bf9166667' ..
2022-01-25 14:45:03.5354 TRACE =========================================================
2022-01-25 14:45:03.5354 INFO Retrieving REAL systemstatus ..
2022-01-25 14:45:03.5354 TRACE [468f73e7-13c6-4bd4-8080-feb71d27e607]: Validating input on task HyFlo.Tasks.SystemTestTask
2022-01-25 14:45:03.5354 TRACE [468f73e7-13c6-4bd4-8080-feb71d27e607]: Executing task HyFlo.Tasks.SystemTestTask
2022-01-25 14:45:03.5354 INFO Checking if HSB is online ..
2022-01-25 14:45:03.5354 DEBUG Sync execute of 'HyFlo.Integration.HSB.IsAliveService' ..
2022-01-25 14:45:03.5354 INFO Executing HealthAsync ..
2022-01-25 14:45:05.6135 INFO HealthAsync executed. It returns 'HyFlo.Integration.ServiceManagementAsync.HSBResult' ..
2022-01-25 14:45:05.6135 DEBUG Sync ready of 'HyFlo.Integration.HSB.IsAliveService' ..
2022-01-25 14:45:05.6135 INFO True
2022-01-25 14:45:05.6135 INFO Checking if HDM is online ..
2022-01-25 14:45:05.6135 DEBUG DocService client's state is 'Created' ..
2022-01-25 14:45:05.6135 DEBUG Sync execute of 'HyFlo.Integration.HDM.IsAliveService' ..
2022-01-25 14:45:05.6135 INFO Checking if DocService client exists ..
2022-01-25 14:45:05.6135 INFO Transfering command to HDM.ServiceStatus()
2022-01-25 14:45:08.8329 INFO Returned result from HDM.ServiceStatus() ..
2022-01-25 14:45:08.8329 DEBUG Sync ready of 'HyFlo.Integration.HDM.IsAliveService' ..
2022-01-25 14:45:08.8329 INFO True
2022-01-25 14:45:08.8329 INFO Checking if SQLServer is online ..
2022-01-25 14:45:08.8329 INFO True
2022-01-25 14:45:08.8329 INFO Checking if WorkflowCommandQueueManager is online ..
2022-01-25 14:45:08.8329 INFO True
2022-01-25 14:45:08.8329 INFO Checking if WorkflowDirector is online and if heartbeat is running ..
2022-01-25 14:45:08.8329 INFO True
2022-01-25 14:45:08.8329 TRACE [468f73e7-13c6-4bd4-8080-feb71d27e607]: Task succesful: True : Results: 0
2022-01-25 14:45:08.8329 INFO Systemstatus is '0'. State cached for 15 minutes ..
2022-01-25 14:45:08.8329 INFO Running the injected code ..
2022-01-25 14:45:08.8485 TRACE ============================================================
2022-01-25 14:45:08.8485 TRACE CommandEventId:51f8ffa9-c00c-417c-bf71-03bb3ad83637: Message processed by handler of type 'HyFlo.Service.CommandHandlers.Info.GetVersionHandler' with CorrelationId '0c6a1541-0a7c-4345-828e-463bf9166667' ..
2022-01-25 14:45:08.8485 TRACE Elapsed time: 00:00:00.0156255 ..
2022-01-25 14:45:08.8485 TRACE = End of Message =================================================================

Audit queue:

hyflo.service.audit
Routing Key
Redelivered ○
Properties
type: HyFlo.Service.Messages.Commands.Info.GetVersionCommand
message_id: 47f1681d-afef-4e26-a36b-ae2800e29418
reply_to: Hyflo.Client.Test
correlation_id: 47f1681d-afef-4e26-a36b-ae2800e29418
delivery_mode: 2
headers:
$.diagnostics.hostdisplayname: HSWV0601
$.diagnostics.hostid: 2a5a733a131925ae27cfd3bbc73e152c
$.diagnostics.originating.hostid: 3a3bbd6661214b655aa6dbcd95d112a2
CorrelationId: 0c6a1541-0a7c-4345-828e-463bf9166667
NServiceBus.ContentType: text/xml
NServiceBus.ConversationId: 8b54fcfe-b991-4c9c-8c0b-ae2800e2941a
NServiceBus.CorrelationId: 47f1681d-afef-4e26-a36b-ae2800e29418
NServiceBus.EnclosedMessageTypes: HyFlo.Service.Messages.Commands.Info.GetVersionCommand, HyFlo.Service.Messages, Version=4.10.3.26734, Culture=neutral, PublicKeyToken=null;HyFlo.Types.Interfaces.IInfoCommand, HyFlo.Types, Version=4.10.8.20782, Culture=neutral, PublicKeyToken=null
NServiceBus.MessageId: 47f1681d-afef-4e26-a36b-ae2800e29418
NServiceBus.MessageIntent: Send
NServiceBus.NonDurableMessage: False
NServiceBus.OriginatingEndpoint: Hyflo.Client.Test
NServiceBus.OriginatingMachine: DYP297
NServiceBus.ProcessingEnded: 2022-01-25 13:45:08:848599 Z
NServiceBus.ProcessingEndpoint: hyflo.service
NServiceBus.ProcessingMachine: HSWV0601
NServiceBus.ProcessingStarted: 2022-01-25 13:44:56:926077 Z
NServiceBus.ReplyToAddress: Hyflo.Client.Test
NServiceBus.TimeSent: 2022-01-25 13:44:56:844666 Z
NServiceBus.TimeToBeReceived: 00:10:00
NServiceBus.Transport.RabbitMQ.ConfirmationId: 2
NServiceBus.Version: 7.6.0
content_type: text/xml
Payload
276 bytes
Encoding: string

<?xml version="1.0"?><GetVersionCommand xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:baseType="HyFlo.Types.Interfaces.IInfoCommand" xmlns="http://tempuri.net/HyFlo.Service.Messages.Commands.Info"></GetVersionCommand>
4

For people reading this, I’m currently investigating this issue with Richard over a support case. I will report back here once we have resolved the issue with a short summary.

5

We have looked into the issue. The delay was caused by a complex dependency resolution graph that was injected into the handler.

1 Like
6

As Daniel already said, the issue is solved.

Because of a complex object graph in one of the classes of the solution (the class that is the primary access point to the solution in fact) the delay occurred. Now when creating either specialised classes or injecting the actual needed dependency there was virtually no delay.

So the final solution was to alter each and every IHandleMessages-handler to have it injected a targeted dependency with which the handler could work.

1 Like