dotnet / dotnet/MQTTnet

Timing of ConnectAsync

Open
#2,066 1 comment 0 reactions 0 assignees View on GitHub
question
Dominant language
C#
Stars
5.1k
Forks
1.2k
PR merge metrics
No merged PRs in 30d

Description

Hi everyone

I realized the [client](https://github.com/dotnet/MQTTnet/blob/master/Source/MQTTnet/Client/MqttClient.cs) takes ~**200ms** to connect to my remote broker, which seems very slow to me.
If I disconnect the client, instantiate, and connect a new one, connecting takes only **14ms** instead of 200ms.
I can reproduce this behavior and am wondering if this is related to the client or any other network-related issue? Has anyone observed similar behavior?

**Approach:**
To evaluate timing, I create a new StreamWriter for each client and write to a file on each LogMessagePublished

```
StreamWriter _stream = new StreamWriter($"{ClientId}.log", false);
MqttNetEventLogger _logger = new MqttNetEventLogger(ClientId);
_logger.LogMessagePublished += Logger_LogMessagePublished;

MqttFactory _factory = new MqttFactory(_logger);
MqttClientOptions _clientOptions = new MqttClientOptionsBuilder()
.WithTcpServer(ServerAddress, ServerPort)
.WithTimeout(Timeout)
.WithProtocolVersion(MqttProtocolVersion.V500)
.WithCleanSession(true) // CleanSession: With no existing subscriptions at start-up
.Build();
IMqttClient _client = _factory.CreateMqttClient();
_client.ConnectAsync(_clientOptions, CancellationToken.None).Wait(5000);

[...]

private void Logger_LogMessagePublished(object sender, MqttNetLogMessagePublishedEventArgs e)
{
_stream.WriteLine(String.Format("{0}\t{1}\t{2}", e.LogMessage.Timestamp.ToString("HH:mm:ss.ffffff"), ClientId, e.LogMessage.Message));
}
```

**Output Logfile**
> 07:47:31.058276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Trying to connect with server '10.10.101.43:1883'
> 07:47:31.167276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Connection with server established
> 07:47:31.200276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (61 bytes) >>> Connect: [ClientId=JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e] [Username=] [Password=] [KeepAlivePeriod=15] [CleanSession=True]
> 07:47:31.255276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e RX (11 bytes) <<< ConnAck: [ReturnCode=ConnectionAccepted] [ReasonCode=Success] [IsSessionPresent=False]
> 07:47:31.257276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Authenticated MQTT connection with server established.
> 07:47:31.257276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Connected
> 07:47:31.276276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Start receiving packets
> 07:47:31.282276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Start sending keep alive packets
> 07:47:31.284276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (53 bytes) >>> Subscribe: [PacketIdentifier=1] [TopicFilters=2940524/+/+@AtLeastOnce]
> 07:47:31.302276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e RX (6 bytes) <<< SubAck: [PacketIdentifier=1] [ReasonCode=GrantedQoS1]
> 07:47:31.314276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e RX (811 bytes) <<< Publish: [Topic=2940524/2940524-000001/00b9423f-12a8-47b3-8e50-e3784ba40740] [PayloadLength=656] [QoSLevel=AtLeastOnce] [Dup=False] [Retain=True] [PacketIdentifier=1]
> 07:47:31.318276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e RX (811 bytes) <<< Publish: [Topic=2940524/2940524-000002/d78febb9-354b-4c12-8072-7542d4895f71] [PayloadLength=656] [QoSLevel=AtLeastOnce] [Dup=False] [Retain=True] [PacketIdentifier=2]
> [...]
> 07:47:39.571276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (6 bytes) >>> PubAck: [PacketIdentifier=19996] [ReasonCode=Success]
> 07:47:39.572276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (6 bytes) >>> PubAck: [PacketIdentifier=19997] [ReasonCode=Success]
> 07:47:39.572276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (6 bytes) >>> PubAck: [PacketIdentifier=19998] [ReasonCode=Success]
> 07:47:45.367276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (52 bytes) >>> Unsubscribe: [PacketIdentifier=2] [TopicFilters=2940524/+/+]
> 07:47:45.377276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e RX (6 bytes) <<< UnsubAck: [PacketIdentifier=2] [ReasonCodes=Success] [ReasonString=]
> 07:47:45.390276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e TX (4 bytes) >>> Disconnect: [ReasonCode=NormalDisconnection] [ReasonString=] [ServerReference=] [SessionExpiryInterval=0]
> 07:47:45.392276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Stopped receiving packets
> 07:47:45.397276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Stopped sending keep alive packets
> 07:47:45.398276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Disconnecting [Timeout=00:00:05]
> 07:47:45.404276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Disconnected from adapter.
> 07:47:45.411276 JEN-TS007.0a9499dc-4639-4f33-b6dd-3966d0d28b6e Disconnected.

**Details:**
- MQTTnet: v4.3.3.952
- Target Framework: .Net Framework 4.7
- Mosquitto: v2.0.14 (located in my local network, and accessible via IP address)

Many thanks and looking forward to your hints/ideas
Filip

Contributor guide

No contributing guide indexed for this repository

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.