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

asked 2023-01-05T07:43:14.167+00:00
Rohit Rajbanshi 1 Reputation point

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.

Azure Storage Accounts
Azure Storage Accounts
Globally unique resources that provide access to data management services and serve as the parent namespace for the services.
1,536 questions
Azure Blob Storage
Azure Blob Storage
An Azure service that stores unstructured data in the cloud as blobs.
1,387 questions
{count} votes

1 answer

Sort by: Most helpful
  1. answered 2023-01-11T23:53:06.72+00:00
    SaiKishor-MSFT 14,916 Reputation points Microsoft Employee

    @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!

    No comments