There is a 4-12 seconds delay seen in when uploading a small blob to azure blob storage of size less than 2 MB

Question

Hello, I have a multi threaded application which uploads small blobs to azure blob storage. At a time maximum 3 threads are running. Every thread tries to upload a blob with size less than 2 BM. I am getting a delay of 4-10 seconds for every blob upload response. Which results is very slow performance for many blobs.

Here is the log snippet of one of the thread which uploads a blob:

2023-01-05 07:08:12,110 INFO com.ibm.svc.mcstore.AzureConnector [main] Calling upload API with container-name: rohitaawsxd1 and blob-name: pack/6005076812a700ec5800000000000000/1/0/1
2023-01-05 07:08:12,124 DEBUG reactor.netty.resources.PooledConnectionProvider [reactor-http-nio-6] [a66c8ca4] Created a new pooled channel, now: 0 active connections, 0 inactive connections and 0 pending acquire requests.
2023-01-05 07:08:12,131 DEBUG reactor.netty.tcp.SslProvider [reactor-http-nio-6] [a66c8ca4] SSL enabled using engine com.ibm.jsse2.bg@8962e3e9 and SNI tctrohitwest.blob.core.windows.net:443
2023-01-05 07:08:12,174 DEBUG reactor.netty.transport.TransportConfig [reactor-http-nio-6] [a66c8ca4] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2023-01-05 07:08:12,250 DEBUG reactor.netty.transport.TransportConnector [reactor-http-nio-6] [a66c8ca4] Connecting to [tctrohitwest.blob.core.windows.net/20.150.43.97:443].
2023-01-05 07:08:12,261 DEBUG reactor.netty.resources.DefaultPooledConnectionProvider [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Registering pool release on close event for channel
2023-01-05 07:08:12,261 DEBUG reactor.netty.resources.PooledConnectionProvider [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Channel connected, now: 2 active connections, 0 inactive connections and 0 pending acquire requests.
2023-01-05 07:08:12,312 DEBUG io.netty.handler.ssl.SslHandler [reactor-http-nio-6] [id: 0xa66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] HANDSHAKEN: protocol:TLSv1.2 cipher suite:SSL_ECDHE_RSA_WITH_AES_256_GCM_SHA384
2023-01-05 07:08:12,312 DEBUG reactor.netty.resources.DefaultPooledConnectionProvider [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] onStateChange(PooledConnection{channel=[id: 0xa66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443]}, [connected])
2023-01-05 07:08:12,312 DEBUG reactor.netty.resources.DefaultPooledConnectionProvider [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0xa66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443]}}, [configured])
2023-01-05 07:08:12,313 DEBUG reactor.netty.http.client.HttpClientConnect [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Handler is being applied: {uri=https://tctrohitwest.blob.core.windows.net/rohitaawsxd1/pack%2F6005076812a700ec5800000000000000%2F1%2F0%2F1, method=PUT}
2023-01-05 07:08:12,313 DEBUG reactor.netty.resources.DefaultPooledConnectionProvider [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] onStateChange(PUT{uri=/rohitaawsxd1/pack%2F6005076812a700ec5800000000000000%2F1%2F0%2F1, connection=PooledConnection{channel=[id: 0xa66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443]}}, [request_prepared])
2023-01-05 07:08:12,313 DEBUG reactor.netty.ReactorNetty [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Added decoder [azureWriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureWriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2023-01-05 07:08:18,551 DEBUG reactor.netty.resources.DefaultPooledConnectionProvider [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] onStateChange(PUT{uri=/rohitaawsxd1/pack%2F6005076812a700ec5800000000000000%2F1%2F0%2F1, connection=PooledConnection{channel=[id: 0xa66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443]}}, [request_sent])
2023-01-05 07:08:18,551 DEBUG reactor.netty.ReactorNetty [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Removed handler: azureWriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2023-01-05 07:08:18,551 DEBUG reactor.netty.ReactorNetty [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Added decoder [azureResponseTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureResponseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2023-01-05 07:08:18,604 DEBUG reactor.netty.http.client.HttpClientOperations [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Received response (auto-read:false) : [Content-MD5=9msbZMpFmnwtk1uKP43q7g==, Last-Modified=Thu, 05 Jan 2023 07:08:18 GMT, ETag="0x8DAEEEB9F700346", Server=Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0, x-ms-request-id=7e0e87b8-401e-00a3-5dd4-2042ac000000, x-ms-client-request-id=d6ed88b6-5495-40f4-aa75-4fe483a131bb, x-ms-version=2021-06-08, x-ms-content-crc64=KBLhhQ+ofvE=, x-ms-request-server-encrypted=true, Date=Thu, 05 Jan 2023 07:08:18 GMT, content-length=0]
2023-01-05 07:08:18,604 DEBUG reactor.netty.resources.DefaultPooledConnectionProvider [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] onStateChange(PUT{uri=/rohitaawsxd1/pack%2F6005076812a700ec5800000000000000%2F1%2F0%2F1, connection=PooledConnection{channel=[id: 0xa66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443]}}, [response_received])
2023-01-05 07:08:18,604 DEBUG reactor.netty.ReactorNetty [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Removed handler: azureResponseTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2023-01-05 07:08:18,604 DEBUG reactor.netty.ReactorNetty [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Added decoder [azureReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2023-01-05 07:08:18,605 DEBUG reactor.netty.channel.FluxReceive [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
2023-01-05 07:08:18,605 DEBUG reactor.netty.http.client.HttpClientOperations [reactor-http-nio-6] [a66c8ca4-1, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Received last HTTP packet
2023-01-05 07:08:18,608 DEBUG reactor.netty.resources.DefaultPooledConnectionProvider [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] onStateChange(PUT{uri=/rohitaawsxd1/pack%2F6005076812a700ec5800000000000000%2F1%2F0%2F1, connection=PooledConnection{channel=[id: 0xa66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443]}}, [response_completed])
2023-01-05 07:08:18,608 DEBUG reactor.netty.ReactorNetty [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Removed handler: azureReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2023-01-05 07:08:18,608 DEBUG reactor.netty.ReactorNetty [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Non Removed handler: azureWriteTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2023-01-05 07:08:18,608 DEBUG reactor.netty.ReactorNetty [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Non Removed handler: azureResponseTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2023-01-05 07:08:18,608 DEBUG reactor.netty.ReactorNetty [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Non Removed handler: azureReadTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2023-01-05 07:08:18,608 DEBUG reactor.netty.resources.DefaultPooledConnectionProvider [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] onStateChange(PUT{uri=/rohitaawsxd1/pack%2F6005076812a700ec5800000000000000%2F1%2F0%2F1, connection=PooledConnection{channel=[id: 0xa66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443]}}, [disconnecting])
2023-01-05 07:08:18,608 DEBUG reactor.netty.resources.DefaultPooledConnectionProvider [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Releasing channel
2023-01-05 07:08:18,609 DEBUG reactor.netty.resources.PooledConnectionProvider [reactor-http-nio-6] [a66c8ca4, L:/9.122.123.52:60968 - R:tctrohitwest.blob.core.windows.net/20.150.43.97:443] Channel cleaned, now: 2 active connections, 1 inactive connections and 0 pending acquire requests.

Answer 1

@Rohit Rajbanshi Thank you for reaching out to Microsoft Q&A. From the logs, I see that there is delay before the request was sent i.e.,

Added decoder - 07:08:12,313
[request_sent]) - 07:08:18,551
[response_received])- 07:08:18,604

Looking at the above logs, there seems to be delay with sending the request itself. Is this something to do with your application? Please let me know. Thank you!