Aws-sdk-ruby: SNS client initialization is slow

[rhymes]

Hello, we have an app in which we have resque jobs pulling work from a queue and sending notifications in a Rails 4.2 app.

Each job sends one notification and then quits. To send a notification each job, among other things, does the following operations:

client = Aws::S3::Client.new
client.publish(<payload>)

Jobs are running in heroku workers in processes managed resque pool

What we've noticed is sometimes things slow down a lot, so we started measuring and we've found out that the S3 client initialization (which happens in the job) can be painfully slow (a random benchmarked job reports 858 ms just for the new!).

We've thought it maybe was a problem with a specific version we were using of aws-sdk (2.6.44) so we've downgraded to other ones but it didn't change).

So I just fired up the console and benchmarked the latest release of every 2.x version and noticed a pretty consistent pattern:

aws-sdk 2.2.37
[1] pry(main)> 5.times { puts Benchmark.measure { Aws::SNS::Client.new } }
  0.160000   0.110000   0.270000 (  0.472128)
  0.010000   0.000000   0.010000 (  0.001521)
  0.000000   0.000000   0.000000 (  0.001308)
  0.000000   0.000000   0.000000 (  0.001338)
  0.000000   0.000000   0.000000 (  0.000938)
=> 5
[2] pry(main)> 5.times { puts Benchmark.measure { Aws::SNS::Client.new } }
  0.000000   0.000000   0.000000 (  0.003046)
  0.000000   0.000000   0.000000 (  0.002310)
  0.000000   0.010000   0.010000 (  0.002296)
  0.000000   0.000000   0.000000 (  0.003701)
  0.010000   0.000000   0.010000 (  0.002971)
=> 5

aws-sdk 2.3.22
[1] pry(main)> 5.times { puts Benchmark.measure { Aws::SNS::Client.new } }
  0.160000   0.090000   0.250000 (  0.407532)
  0.000000   0.000000   0.000000 (  0.001716)
  0.000000   0.000000   0.000000 (  0.001121)
  0.010000   0.000000   0.010000 (  0.001500)
  0.000000   0.000000   0.000000 (  0.001463)
=> 5
[2] pry(main)> 5.times { puts Benchmark.measure { Aws::SNS::Client.new } }
  0.000000   0.010000   0.010000 (  0.002422)
  0.010000   0.000000   0.010000 (  0.002473)
  0.000000   0.000000   0.000000 (  0.002408)
  0.000000   0.000000   0.000000 (  0.001822)
  0.000000   0.000000   0.000000 (  0.002350)
=> 5

aws-sdk 2.4.4
[1] pry(main)> 5.times { puts Benchmark.measure { Aws::SNS::Client.new } }
  0.160000   0.100000   0.260000 (  0.387920)
  0.000000   0.000000   0.000000 (  0.002706)
  0.010000   0.000000   0.010000 (  0.001887)
  0.000000   0.000000   0.000000 (  0.001199)
  0.000000   0.000000   0.000000 (  0.001617)
=> 5
[2] pry(main)> 5.times { puts Benchmark.measure { Aws::SNS::Client.new } }
  0.000000   0.000000   0.000000 (  0.002290)
  0.010000   0.000000   0.010000 (  0.002203)
  0.000000   0.010000   0.010000 (  0.002673)
  0.000000   0.000000   0.000000 (  0.001650)
  0.000000   0.000000   0.000000 (  0.002323)
=> 5

aws-sdk 2.5.11
[1] pry(main)> 5.times { puts Benchmark.measure { Aws::SNS::Client.new } }
  0.180000   0.100000   0.280000 (  0.414667)
  0.000000   0.000000   0.000000 (  0.001932)
  0.000000   0.000000   0.000000 (  0.001593)
  0.000000   0.000000   0.000000 (  0.002150)
  0.000000   0.000000   0.000000 (  0.001256)
=> 5
[2] pry(main)> 5.times { puts Benchmark.measure { Aws::SNS::Client.new } }
  0.000000   0.000000   0.000000 (  0.002883)
  0.000000   0.000000   0.000000 (  0.002793)
  0.000000   0.000000   0.000000 (  0.004321)
  0.010000   0.000000   0.010000 (  0.002467)
  0.000000   0.000000   0.000000 (  0.002947)

aws-sdk 2.6.47
[1] pry(main)> 5.times { puts Benchmark.measure { Aws::SNS::Client.new } }
  0.170000   0.090000   0.260000 (  0.416427)
  0.000000   0.000000   0.000000 (  0.001382)
  0.010000   0.000000   0.010000 (  0.001645)
  0.000000   0.000000   0.000000 (  0.001542)
  0.000000   0.000000   0.000000 (  0.002331)
=> 5
[2] pry(main)> 5.times { puts Benchmark.measure { Aws::SNS::Client.new } }
  0.000000   0.000000   0.000000 (  0.002204)
  0.010000   0.000000   0.010000 (  0.001891)
  0.000000   0.000000   0.000000 (  0.002007)
  0.000000   0.000000   0.000000 (  0.002008)
  0.000000   0.000000   0.000000 (  0.002316)
=> 5

As you can see the very first time the client is initialized it takes even half a second to create the object which for us is done for every single job.

I tried to look into the code but I couldn't figure out what was the issue.

Any suggestions or solutions?

I was thinking that, as a workaround, we might initialize a "singleton" client in a Rails initializer and then use that in each and every job (they all push to the same server reading options from the environment).

[trevorrowe]

The SDK is reading a handful of JSON service definition files at SDK load when defining a service module for the first time. These JSON documents are used to dynamically define the modules, classes, methods, etc for the service. This will be slow because it is generating classes at runtime as well as source potentially large JSON documents from disk to build these classes. It will also do a large amount of string inflections from the source JSON document to provide the snake_cased method and param names that are idiomatic in Ruby.

The good news is that we are currently in a preview stage of a significant update to the SDK. The SDK is being modularized so that each service is bundled into its own gem. In addition to modularizing the SDK, the runtime generation is replaced with generated source that is compatible with the existing SDK. I ran the benchmarks above locally and got the following results:

> require 'benchmark'; 5.times { require 'aws-sdk-sns'; puts Benchmark.measure { Aws::SNS::Client.new } }
  0.000000   0.000000   0.000000 (  0.003313)
  0.000000   0.000000   0.000000 (  0.000687)
  0.000000   0.000000   0.000000 (  0.001271)
  0.000000   0.000000   0.000000 (  0.001422)
  0.000000   0.000000   0.000000 (  0.000663)

There is obviously still some extra time spend during the initial require statement for the gem, but it is significantly faster. Aside from some very minor changes in your Gemfile and possibly a change in how you require the SDK, these should be backwards compatible. There are a pair of blog posts that highlight these new versions here:

• Modularization
• Upgrading from v2 to v3

Hope this helps!

[trevorrowe]

I failed to answer one of your questions. It is safe to use the SDK clients as singletons. They are immutable and safe to share across threads.

[trevorrowe]

I just realized I made a significant mistake in my benchmark above and now I feel really silly.

> require 'benchmark'; 5.times { require 'aws-sdk-sns'; puts Benchmark.measure { Aws::SNS::Client.new } }

Notice that I required the aws-sdk-sns gem outside of the benchmark block. Moving inside I get similar results to what you are getting, even with the code-generated branch:

require 'benchmark'; 5.times { puts Benchmark.measure { require 'aws-sdk-sns'; Aws::SNS::Client.new } }
  0.180000   0.040000   0.220000 (  0.219647)
  0.000000   0.000000   0.000000 (  0.000643)
  0.000000   0.000000   0.000000 (  0.000673)
  0.000000   0.000000   0.000000 (  0.000664)
  0.000000   0.000000   0.000000 (  0.000687)

I was surprised by this until I realized why. Version 2 of the SDK makes heavy use of autoload. Version 3 does not. I uses explicit require and require_relative statements. This means there is some cost paid up-front when the library is required. First client instantiation is significantly faster as there are no more files to autoload. This means there is still a pretty heavy startup time.

If you require the SDK at process startup, this should move the cost there. If you are using short-lived processes then this may not help.

[trevorrowe]

Also worth noting is most of the time is not spent loading sns, rather is it is in loading its downstream dependencies:

require 'benchmark'; 5.times { puts Benchmark.measure { require 'aws-sdk-core'; require 'aws-partitions'; require 'aws-sigv4'; require 'aws-sigv4' }}
  0.150000   0.030000   0.180000 (  0.181079)
  0.000000   0.000000   0.000000 (  0.000015)
  0.000000   0.000000   0.000000 (  0.000012)
  0.000000   0.000000   0.000000 (  0.000019)
  0.000000   0.000000   0.000000 (  0.000011)

[rhymes]

Thank you for the great explanation. I'm looking forward to the new version then, in the meantime I already switched the code to use a singleton, like you suggested, and it's working fine. Thanks for the discussions pointers also.

[cjyclaire]

Looks like questions have been answered, closing. Yet feel free to reopen with further questions. : )