storage: Extremely slow object upload performance (regression in google-apis-core 0.8.0)
stanhu opened this issue · 7 comments
I attempted to upgrade google-apis-core to v0.9.4 from v0.7.2. However, I'm seeing significantly slow upload performance. I used to be able to upload a 10 GB file within the Google Compute Engine environment in 2 minutes; it didn't even finish after an hour.
Environment details
- OS: Linux
- Ruby version: 2.7.7
- Gem name and version:
google-apis-corev0.9.4
Steps to reproduce
First, create a 200 MB test file:
dd if=/dev/urandom bs=1024 count=200000 of=200mb.binWith the older Gemfile and benchmark script below (see below), I see only 1 POST request that finishes in 1.4 seconds:
D, [2023-01-11T22:19:14.101397 #339281] DEBUG -- : Sending upload start command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o? D, [2023-01-11T22:19:14.217974 #339281] DEBUG -- : Upload status active D, [2023-01-11T22:19:14.218078 #339281] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?upload_id=ADPycduIAS9UlGvlle_Ia_pS1UcIIR37KCgLFb6zDMepimf9WZe-G6FL-shcziV2OXQKM1KEg_jYVJis4ToFNr_vrZT6Hv0YljT9&upload_protocol=resumable D, [2023-01-11T22:19:15.529741 #339281] DEBUG -- : Upload status final D, [2023-01-11T22:19:15.533125 #339281] DEBUG -- : Success - #, @time_storage_class_updated= #, @updated= #>0.193927 0.073813 0.267740 ( 1.434075)
The stackprof output shows:
==================================
Mode: cpu(1000)
Samples: 63 (0.00% miss rate)
GC: 1 (1.59%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
48 (76.2%) 48 (76.2%) OpenSSL::Buffering#do_write
60 (95.2%) 10 (15.9%) HTTP::Message::Body#dump_file
50 (79.4%) 2 (3.2%) OpenSSL::Buffering#write
1 (1.6%) 1 (1.6%) block (2 levels) in
1 (1.6%) 1 (1.6%) (marking)
1 (1.6%) 1 (1.6%) Representable::Pipeline#call
1 (1.6%) 0 (0.0%) HTTPClient::SSLConfig#add_trust_ca_to_store
1 (1.6%) 0 (0.0%) HTTPClient::SSLConfig#load_cacerts
1 (1.6%) 0 (0.0%) HTTPClient::SSLConfig#load_trust_ca
1 (1.6%) 0 (0.0%) HTTPClient::SSLConfig#set_context
1 (1.6%) 0 (0.0%) HTTPClient::SSLSocket#create_openssl_socket
1 (1.6%) 0 (0.0%) HTTPClient::SSLSocket#initialize
1 (1.6%) 0 (0.0%) HTTPClient::SSLSocket.create_socket
1 (1.6%) 0 (0.0%) HTTPClient::Session#connect
61 (96.8%) 0 (0.0%) #.timeout
61 (96.8%) 0 (0.0%) HTTPClient::Session#query
61 (96.8%) 0 (0.0%) HTTPClient::SessionManager#query
61 (96.8%) 0 (0.0%) HTTPClient#do_get_block
61 (96.8%) 0 (0.0%) HTTPClient#do_request
61 (96.8%) 0 (0.0%) HTTPClient#protect_keep_alive_disconnected
61 (96.8%) 0 (0.0%) HTTPClient#follow_redirect
61 (96.8%) 0 (0.0%) HTTPClient#request
1 (1.6%) 0 (0.0%) Google::Apis::Core::ResumableUploadCommand#send_start_command
62 (98.4%) 0 (0.0%) Google::Apis::Core::ResumableUploadCommand#execute_once
62 (98.4%) 0 (0.0%) Google::Apis::Core::HttpCommand#do_retry
62 (98.4%) 0 (0.0%) #.retriable
62 (98.4%) 0 (0.0%) Google::Apis::Core::HttpCommand#execute
62 (98.4%) 0 (0.0%) Google::Apis::Core::BaseService#execute_or_queue_command
62 (98.4%) 0 (0.0%) Google::Apis::StorageV1::StorageService#insert_object
62 (98.4%) 0 (0.0%) block (2 levels) in
However, if I update my Gemfile and Gemfile.lock and retest, the transfer takes 15.7 seconds with 25 separate PUT requests:
D, [2023-01-11T22:22:12.846718 #339447] DEBUG -- : Intiating resumable upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o? D, [2023-01-11T22:22:13.007713 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:13.007959 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:13.740444 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:13.740626 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:14.666112 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:14.666316 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:15.310547 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:15.310799 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:16.000622 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:16.000854 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:16.629254 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:16.629440 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:17.194864 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:17.195068 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:17.849816 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:17.850046 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:18.491106 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:18.491323 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:19.146477 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:19.146800 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:19.735007 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:19.735218 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:20.364874 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:20.365094 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:21.016777 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:21.016998 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:21.637977 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:21.638214 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:22.149258 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:22.149488 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:22.735525 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:22.735739 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:23.405292 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:23.405524 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:23.994255 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:23.994481 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:24.559559 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:24.559788 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:25.139717 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:25.139915 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:25.759427 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:25.759638 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:26.401452 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:26.401674 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:27.061783 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:27.061997 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:27.572978 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:27.573195 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:28.190042 #339447] DEBUG -- : Success - nilD, [2023-01-11T22:22:28.190230 #339447] DEBUG -- : Sending upload command to https://storage.googleapis.com/upload/storage/v1/b/stanhu-test/o?uploadType=resumable&upload_id=ADPycduaL8-kX9eSNiDQwcbe6tPF6LGwtN1YCVV870p-QLwPfgGZCgawh0-fJIKi9gIW_ePFZtV3T1wtPkkDtBvrbGx1Ew
D, [2023-01-11T22:22:28.575346 #339447] DEBUG -- : Success - #<Google::Apis::StorageV1::Object:0x000055f4c04b9ca8
@bucket="stanhu-test",
@content_type="application/octet-stream",
@crc32c="mQCzcg==",
@etag="COHsmvzGwPwCEAE=",
@generation=1673475748443745,
@id="stanhu-test/200mb.bin/1673475748443745",
@kind="storage#object",
@md5_hash="nH+KqtvzpXepWRPGpoQXRQ==",
@media_link=
"https://storage.googleapis.com/download/storage/v1/b/stanhu-test/o/200mb.bin?generation=1673475748443745&alt=media",
@metageneration=1,
@name="200mb.bin",
@self_link="https://www.googleapis.com/storage/v1/b/stanhu-test/o/200mb.bin",
@size=204800000,
@storage_class="STANDARD",
@time_created=
#<DateTime: 2023-01-11T22:22:28+00:00 ((2459956j,80548s,527000000n),+0s,2299161j)>,
@time_storage_class_updated=
#<DateTime: 2023-01-11T22:22:28+00:00 ((2459956j,80548s,527000000n),+0s,2299161j)>,
@updated=
#<DateTime: 2023-01-11T22:22:28+00:00 ((2459956j,80548s,527000000n),+0s,2299161j)>>10.339469 3.528497 13.867966 ( 15.731055)
The stackprof output:
==================================
Mode: cpu(1000)
Samples: 3383 (0.24% miss rate)
GC: 1064 (31.45%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
2277 (67.3%) 2277 (67.3%) OpenSSL::Buffering#do_write
807 (23.9%) 807 (23.9%) (marking)
257 (7.6%) 257 (7.6%) (sweeping)
2314 (68.4%) 14 (0.4%) Google::Apis::Core::StorageUploadCommand#send_upload_command
2289 (67.7%) 12 (0.4%) HTTP::Message::Body#dump
2296 (67.9%) 3 (0.1%) #.timeout
2 (0.1%) 2 (0.1%) Addressable::URI#scheme=
1 (0.0%) 1 (0.0%) OpenSSL::SSL::SSLContext#initialize
1 (0.0%) 1 (0.0%) block (2 levels) in
2294 (67.8%) 1 (0.0%) HTTPClient::Session#query
1 (0.0%) 1 (0.0%) HTTPClient::SSLConfig#default_verify_callback
1 (0.0%) 1 (0.0%) HTTPClient::SessionManager#get_cached_session
1 (0.0%) 1 (0.0%) HTTP::Message::Headers#delete
1 (0.0%) 1 (0.0%) OpenSSL::Buffering#fill_rbuff
1 (0.0%) 1 (0.0%) Addressable::URI#query
1 (0.0%) 1 (0.0%) Retriable::ExponentialBackoff#randomize
1 (0.0%) 1 (0.0%) Google::Apis::Core::ApiCommand#decode_response_body
1 (0.0%) 1 (0.0%) #.init
1 (0.0%) 0 (0.0%) Net::HTTP#connect
1 (0.0%) 0 (0.0%) Net::HTTP#do_start
1 (0.0%) 0 (0.0%) Net::HTTP#start
1 (0.0%) 0 (0.0%) Faraday::Adapter::NetHttp#request_with_wrapped_block
1 (0.0%) 0 (0.0%) Faraday::Adapter::NetHttp#perform_request
1 (0.0%) 0 (0.0%) Faraday::Adapter::NetHttp#call
1 (0.0%) 0 (0.0%) Faraday::Adapter#connection
1 (0.0%) 0 (0.0%) Faraday::Request::UrlEncoded#call
1 (0.0%) 0 (0.0%) Faraday::RackBuilder#build_response
1 (0.0%) 0 (0.0%) Faraday::Connection#run_request
1 (0.0%) 0 (0.0%) Faraday::Connection#post
1 (0.0%) 0 (0.0%) Signet::OAuth2::Client#fetch_access_token
Code example
Older Gemfile
source 'https://rubygems.org'
gem 'google-apis-core', '= 0.7.2'
gem 'google-apis-storage_v1'
gem 'stackprof'Updated Gemfile
source 'https://rubygems.org'
gem 'google-apis-core', '~> 0.9.4'
gem 'google-apis-storage_v1'
gem 'stackprof'Script
require 'benchmark'
require 'google/apis/storage_v1'
require 'stackprof'
object_name = '200mb.bin'
bucket_name = 'YOUR-BUCKET-HERE'
options = { content_type: 'application/octet-stream', name: object_name }
data = File.open('200mb.bin')
object_config = ::Google::Apis::StorageV1::Object.new(**options))
scopes = ['storage.googleapis.com']
authorization = Google::Auth.get_application_default(scopes)
storage_json = ::Google::Apis::StorageV1::StorageService.new
storage_json.authorization = authorization
Google::Apis.logger.level = Logger::DEBUG
measure = Benchmark.measure do
StackProf.run(mode: :cpu, out: 'stackprof-cpu.dump') do
storage_json.insert_object(
bucket_name, object_config,
:options => ::Google::Apis::RequestOptions.default.merge(options),
:content_type => options[:content_type],
:upload_source => data
)
end
endAnalysis
I suspect this performance regression was introduced in #11508. This pull request reads a file in 8 MB chunks and issues a PUT request for each chunk.
However, as you can see in the stackprof output and the flamegraph below, the time is dominated in OpenSSL::Buffering#do_write:
The #do_write code is this:
def do_write(s)
@wbuffer = Buffer.new unless defined? @wbuffer
@wbuffer << s
@wbuffer.force_encoding(Encoding::BINARY)
@sync ||= false
if @sync or @wbuffer.size > BLOCK_SIZE
until @wbuffer.empty?
begin
nwrote = syswrite(@wbuffer)
rescue Errno::EAGAIN
retry
end
@wbuffer[0, nwrote] = ""
end
end
endNote that the bottleneck appears to be in the @wbuffer[0, nwrote] = "" line, which truncates written bytes from the buffer.
Previously in v0.7.4, s was a File, @wbuffer would be read a full 16K buffer and syswrite would write that out. The resize would be cheap since the whole string would be truncated.
In v0.8.0+, instead of having a IO object to read/and write to directly, google-apis-core reads 8 MB chunks and ends up calling #do_write repeatedly via the PUT request:
#do_write buffers a String and truncates the string by how much has been written, usually 16K. You can see that buffer gets trimmed 16K at a time:
=== wrote 16384, buffer size is 8389171
=== wrote 16384, buffer size is 8372787
=== wrote 16384, buffer size is 8356403
=== wrote 16384, buffer size is 8340019
=== wrote 16384, buffer size is 8323635
=== wrote 16384, buffer size is 8307251
=== wrote 16384, buffer size is 8290867
=== wrote 16384, buffer size is 8274483
=== wrote 16384, buffer size is 8258099
=== wrote 16384, buffer size is 8241715
=== wrote 16384, buffer size is 8225331
<snip>
This buffer resizing requires allocating a new pointer and copying the remaining contents into it, and that's why the total number of stackprof samples jumped from 48 to 2277 because The garbage collector has to work hard to keep up!
cc: @bajajneha27 @tritone
Why is that string truncation so expensive? To find out, I ran this script under valgrind and generated callgrind output:
valgrind --tool=callgrind ruby bench.rb
gprof2dot --format=callgrind --output /tmp/out.dot callgrind.out.341306
dot -Tpng /tmp/out.dot -o /tmp/out.pngIt looks like since that string isn't frozen, Ruby spends 40% of the time in rb_str_resize() copying memory into a resized buffer:
In https://bugs.ruby-lang.org/issues/14426, the number of Ruby object allocations was decreased, but there is more optimization that could probably be done.
#13213 seems to help. Now the 200 MB upload takes about 4 seconds--still slower than before, but at least we're not blocked on string resizing. I suspect the 25 HTTP requests have more to do with the issue now:
==================================
Mode: cpu(1000)
Samples: 99 (1.00% miss rate)
GC: 7 (7.07%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
53 (53.5%) 53 (53.5%) OpenSSL::Buffering#do_write
90 (90.9%) 19 (19.2%) Google::Apis::Core::StorageUploadCommand#send_upload_command
6 (6.1%) 6 (6.1%) (marking)
58 (58.6%) 4 (4.0%) HTTP::Message::Body#dump_file
2 (2.0%) 2 (2.0%) HTTP::Message::Headers#add
2 (2.0%) 2 (2.0%) HTTP::Message::Headers#create_query_uri
1 (1.0%) 1 (1.0%) block (2 levels) in <class:Store>
67 (67.7%) 1 (1.0%) #<Module:0x0000557a22889900>.timeout
1 (1.0%) 1 (1.0%) HTTPClient::SSLSocket#post_connection_check
54 (54.5%) 1 (1.0%) OpenSSL::Buffering#write
2 (2.0%) 1 (1.0%) HTTPClient::SessionManager#get_cached_session
1 (1.0%) 1 (1.0%) HTTP::Message::Headers#status_code=
2 (2.0%) 1 (1.0%) OpenSSL::Buffering#gets
4 (4.0%) 1 (1.0%) HTTPClient::Session#parse_header
1 (1.0%) 1 (1.0%) HTTPClient::Session#set_header
1 (1.0%) 1 (1.0%) (sweeping)
1 (1.0%) 1 (1.0%) OpenSSL::Buffering#consume_rbuff
1 (1.0%) 1 (1.0%) HTTPClient::Site#hash
1 (1.0%) 1 (1.0%) OpenURI::Meta#content_type_parse
1 (1.0%) 0 (0.0%) HTTPClient::SSLConfig#add_trust_ca_to_store
1 (1.0%) 0 (0.0%) HTTPClient::SSLConfig#load_cacerts
1 (1.0%) 0 (0.0%) HTTPClient::SSLConfig#load_trust_ca
1 (1.0%) 0 (0.0%) HTTPClient::SSLConfig#set_context
1 (1.0%) 0 (0.0%) HTTPClient::SSLSocket#create_openssl_socket
2 (2.0%) 0 (0.0%) HTTPClient::SSLSocket#initialize
2 (2.0%) 0 (0.0%) HTTPClient::SSLSocket.create_socket
2 (2.0%) 0 (0.0%) HTTPClient::Session#connect
63 (63.6%) 0 (0.0%) HTTPClient::Session#query
65 (65.7%) 0 (0.0%) HTTPClient::SessionManager#query
73 (73.7%) 0 (0.0%) HTTPClient#do_get_block
@dazuma I'm still struggling to understand the rationale of #11508. The API calls appear the same:
if upload_source.nil?
command = make_simple_command(:post, 'b/{bucket}/o', options)
else
command = make_storage_upload_command(:post, 'b/{bucket}/o', options)
command.upload_source = upload_source
command.upload_content_type = content_type
endDo you know why it was necessary to change the default behavior to upload in 8 MB chunks as opposed to allowing the default behavior of uploading a single chunk?
Thanks @stanhu for the detailed analysis. The reason behind moving to new protocol was to upload larger files in chunks. I understand for cases like these, it turned out counter-productive. We're updating the default chunk size to 100MB in #13215 . We'll also make the chunk size configurable so that the user can decide the chunk size based on their requirements.
@bajajneha27 Ok, was #13215 closed for a reason? It would be nice to be able to set the chunk size to 0 or negative to disable the chunking. UPDATE: I see #13216 now.
I suspect using 8 MB chunks will also be slower due to TCP slow starts. WIthin the GCP network, a single PUT request should be getting close to 1 GB/s of transfer rate, but ramping up to the full 1 GB/s might take a few round trips.