search

googleapis / google-cloud-ruby

Google Cloud Client Library for Ruby
https://googleapis.github.io/google-cloud-ruby/
Apache License 2.0
1.36k stars 550 forks source link

GRPC::Core::OutOfTime (grpc_call_start_batch timed out) #753

Closed simonmorley closed 7 years ago

simonmorley commented 8 years ago

Seems to be identical to https://github.com/grpc/grpc/issues/6045.

Under high load, the publisher throws a GRPC::Core::OutOfTime error. We happen to have tried without the Ruby client but suffered from horrific latency.

We're using this in Rails 4.2 project with Ruby 2.3 

    gcloud (0.10.0)
      digest-crc (~> 0.4)
      google-api-client (~> 0.8.3)
      google-protobuf (= 3.0.0.alpha.5.0.5.1)
      grpc (~> 0.13.1)
      mime-types (~> 2.4)
      zonefile (~> 1.04)

Am just about to test with grpc 0.15.0

18:15:57 web.1   | D0629 18:15:57.462925595     594 completion_queue.c:429]     Too many outstanding grpc_completion_queue_pluck calls: maximum is 6
18:15:57 web.1   | I, [2016-06-29T18:15:57.464187 #23]  INFO -- : Completed 500 Internal Server Error in 21ms (Views: 0.2ms | ActiveRecord: 1.5ms)
18:15:57 web.1   | F, [2016-06-29T18:15:57.471138 #23] FATAL -- :
18:15:57 web.1   | GRPC::Core::OutOfTime (grpc_call_start_batch timed out):
18:15:57 web.1   |   app/lib/pubsub.rb:9:in `push'
18:15:57 web.1   |   app/workers/nas_update.rb:42:in `create'
18:15:57 web.1   |   app/models/nas.rb:591:in `update_nas_attributes_v1'
18:15:57 web.1   |   app/models/nas.rb:586:in `update_nas_attributes'
18:15:57 web.1   |   app/controllers/api/v1/nas_controller.rb:59:in `gubbins'
18:15:57 web.1   |
18:15:57 web.1   |
18:15:57 web.1   | I, [2016-06-29T18:15:57.472027 #23]  INFO -- : Completed 200 OK in 102ms (Views: 0.3ms | ActiveRecord: 1.6ms)
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/stats.rb:68: [BUG] Segmentation fault at 0x0000000000008c
18:15:57 web.1   | ruby 2.3.1p112 (2016-04-26 revision 54768) [x86_64-linux]
18:15:57 web.1   |
18:15:57 web.1   | -- Control frame information -----------------------------------------------
18:15:57 web.1   | c:0071 p:0103 s:0530 e:000526 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/stats.rb:68
18:15:57 web.1   | c:0070 p:0038 s:0521 e:000520 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/transaction_metrics.rb:60
18:15:57 web.1   | c:0069 p:0026 s:0513 e:000512 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/transaction_metrics.rb:29
18:15:57 web.1   | c:0068 p:0045 s:0506 e:000505 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/stats_engine/metric_stats.rb:96
18:15:57 web.1   | c:0067 p:0068 s:0495 e:000494 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/method_tracer_helpers.rb:31
18:15:57 web.1   | c:0066 p:0239 s:0483 e:000482 BLOCK  /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/method_tracer_helpers.rb:59
18:15:57 web.1   | c:0065 p:0006 s:0476 e:000475 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/method_tracer_helpers.rb:15
18:15:57 web.1   | c:0064 p:0026 s:0471 e:000470 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/method_tracer_helpers.rb:39
18:15:57 web.1   | c:0063 p:0210 s:0461 e:000460 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/transaction.rb:159
18:15:57 web.1   | c:0062 p:0162 s:0451 e:000449 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:108
18:15:57 web.1   | c:0061 p:0012 s:0442 e:000441 METHOD /usr/local/bundle/gems/rack-1.6.4/lib/rack/head.rb:13
18:15:57 web.1   | c:0060 p:0108 s:0435 e:000434 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0059 p:0036 s:0427 e:000426 METHOD /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/params_parser.rb:27
18:15:57 web.1   | c:0058 p:0108 s:0422 e:000421 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0057 p:0012 s:0414 e:000413 METHOD /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/flash.rb:260
18:15:57 web.1   | c:0056 p:0108 s:0408 e:000407 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0055 p:0025 s:0400 e:000399 METHOD /usr/local/bundle/gems/rack-1.6.4/lib/rack/session/abstract/id.rb:225
18:15:57 web.1   | c:0054 p:0010 s:0392 e:000391 METHOD /usr/local/bundle/gems/rack-1.6.4/lib/rack/session/abstract/id.rb:220
18:15:57 web.1   | c:0053 p:0108 s:0388 e:000387 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0052 p:0012 s:0380 e:000379 METHOD /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/cookies.rb:560
18:15:57 web.1   | c:0051 p:0108 s:0372 e:000371 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0050 p:0061 s:0364 e:000363 METHOD /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/query_cache.rb:36
18:15:57 web.1   | c:0049 p:0108 s:0355 e:000354 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0048 p:0022 s:0347 e:000346 METHOD /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:653
18:15:57 web.1   | c:0047 p:0108 s:0341 e:000340 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0046 p:0014 s:0333 e:000332 BLOCK  /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/callbacks.rb:29
18:15:57 web.1   | c:0045 p:0021 s:0331 e:000330 METHOD /usr/local/bundle/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:88
18:15:57 web.1   | c:0044 p:0015 s:0324 e:000323 METHOD /usr/local/bundle/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:778
18:15:57 web.1   | c:0043 p:0020 s:0320 e:000319 METHOD /usr/local/bundle/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:81
18:15:57 web.1   | c:0042 p:0016 s:0315 E:001f58 METHOD /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/callbacks.rb:27
18:15:57 web.1   | c:0041 p:0108 s:0309 e:000308 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0040 p:0034 s:0301 e:000300 METHOD /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/remote_ip.rb:78
18:15:57 web.1   | c:0039 p:0108 s:0297 e:000296 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0038 p:0014 s:0289 e:000288 METHOD /usr/local/bundle/gems/airbrake-5.4.1/lib/airbrake/rack/middleware.rb:22
18:15:57 web.1   | c:0037 p:0108 s:0282 e:000281 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0036 p:0012 s:0274 e:000273 METHOD /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/debug_exceptions.rb:17
18:15:57 web.1   | c:0035 p:0108 s:0265 e:000264 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0034 p:0012 s:0257 e:000256 METHOD /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/show_exceptions.rb:30
18:15:57 web.1   | c:0033 p:0108 s:0252 e:000251 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0032 p:0083 s:0244 E:000d50 METHOD /usr/local/bundle/gems/railties-4.2.6/lib/rails/rack/logger.rb:38
18:15:57 web.1   | c:0031 p:0061 s:0237 e:000236 METHOD /usr/local/bundle/gems/railties-4.2.6/lib/rails/rack/logger.rb:22
18:15:57 web.1   | c:0030 p:0108 s:0232 e:000231 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0029 p:0025 s:0224 e:000223 METHOD /usr/local/bundle/gems/request_store-1.3.1/lib/request_store/middleware.rb:9
18:15:57 web.1   | c:0028 p:0108 s:0220 e:000219 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0027 p:0035 s:0212 e:000211 METHOD /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/request_id.rb:21
18:15:57 web.1   | c:0026 p:0108 s:0208 e:000207 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0025 p:0099 s:0200 e:000199 METHOD /usr/local/bundle/gems/rack-1.6.4/lib/rack/methodoverride.rb:22
18:15:57 web.1   | c:0024 p:0108 s:0195 e:000194 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0023 p:0020 s:0187 e:000186 METHOD /usr/local/bundle/gems/rack-1.6.4/lib/rack/runtime.rb:18
18:15:57 web.1   | c:0022 p:0108 s:0178 e:000177 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0021 p:0014 s:0170 e:000169 BLOCK  /usr/local/bundle/gems/rack-timeout-0.4.2/lib/rack/timeout/core.rb:122 [FINISH]
18:15:57 web.1   | c:0020 p:0074 s:0167 E:0010f0 METHOD /usr/local/bundle/gems/rack-timeout-0.4.2/lib/rack/timeout/support/timeout.rb:19
18:15:57 web.1   | c:0019 p:0466 s:0160 E:000df8 METHOD /usr/local/bundle/gems/rack-timeout-0.4.2/lib/rack/timeout/core.rb:121
18:15:57 web.1   | c:0018 p:0108 s:0144 e:000143 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0017 p:0098 s:0136 e:000135 METHOD /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120
18:15:57 web.1   | c:0016 p:0108 s:0130 e:000129 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0015 p:0012 s:0122 e:000121 METHOD /usr/local/bundle/gems/rack-1.6.4/lib/rack/sendfile.rb:113
18:15:57 web.1   | c:0014 p:0108 s:0111 e:000110 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0013 p:0037 s:0103 e:000102 METHOD /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/ssl.rb:24
18:15:57 web.1   | c:0012 p:0108 s:0095 e:000094 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0011 p:0066 s:0087 e:000086 METHOD /usr/local/bundle/gems/railties-4.2.6/lib/rails/engine.rb:518
18:15:57 web.1   | c:0010 p:0042 s:0083 e:000082 METHOD /usr/local/bundle/gems/railties-4.2.6/lib/rails/application.rb:165 [FINISH]
18:15:57 web.1   | c:0009 p:---- s:0079 e:000078 CFUNC  :public_send
18:15:57 web.1   | c:0008 p:0033 s:0074 e:000073 METHOD /usr/local/bundle/gems/railties-4.2.6/lib/rails/railtie.rb:194
18:15:57 web.1   | c:0007 p:0108 s:0068 e:000067 METHOD /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96
18:15:57 web.1   | c:0006 p:0032 s:0060 e:000059 METHOD /usr/local/bundle/gems/puma-3.4.0/lib/puma/configuration.rb:224
18:15:57 web.1   | c:0005 p:0258 s:0056 e:000055 METHOD /usr/local/bundle/gems/puma-3.4.0/lib/puma/server.rb:569
18:15:57 web.1   | c:0004 p:0040 s:0032 e:000031 METHOD /usr/local/bundle/gems/puma-3.4.0/lib/puma/server.rb:406
18:15:57 web.1   | c:0003 p:0060 s:0021 e:000020 BLOCK  /usr/local/bundle/gems/puma-3.4.0/lib/puma/server.rb:271 [FINISH]
18:15:57 web.1   | c:0002 p:0120 s:0012 e:000011 BLOCK  /usr/local/bundle/gems/puma-3.4.0/lib/puma/thread_pool.rb:114 [FINISH]
18:15:57 web.1   | c:0001 p:---- s:0002 e:000001 (none) [FINISH]
18:15:57 web.1   |
18:15:57 web.1   | -- Ruby level backtrace information ----------------------------------------
18:15:57 web.1   | /usr/local/bundle/gems/puma-3.4.0/lib/puma/thread_pool.rb:114:in `block in spawn_thread'
18:15:57 web.1   | /usr/local/bundle/gems/puma-3.4.0/lib/puma/server.rb:271:in `block in run'
18:15:57 web.1   | /usr/local/bundle/gems/puma-3.4.0/lib/puma/server.rb:406:in `process_client'
18:15:57 web.1   | /usr/local/bundle/gems/puma-3.4.0/lib/puma/server.rb:569:in `handle_request'
18:15:57 web.1   | /usr/local/bundle/gems/puma-3.4.0/lib/puma/configuration.rb:224:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/railties-4.2.6/lib/rails/railtie.rb:194:in `method_missing'
18:15:57 web.1   | /usr/local/bundle/gems/railties-4.2.6/lib/rails/railtie.rb:194:in `public_send'
18:15:57 web.1   | /usr/local/bundle/gems/railties-4.2.6/lib/rails/application.rb:165:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/railties-4.2.6/lib/rails/engine.rb:518:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/ssl.rb:24:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/rack-1.6.4/lib/rack/sendfile.rb:113:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/rack-timeout-0.4.2/lib/rack/timeout/core.rb:121:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/rack-timeout-0.4.2/lib/rack/timeout/support/timeout.rb:19:in `timeout'
18:15:57 web.1   | /usr/local/bundle/gems/rack-timeout-0.4.2/lib/rack/timeout/core.rb:122:in `block in call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/rack-1.6.4/lib/rack/runtime.rb:18:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/rack-1.6.4/lib/rack/methodoverride.rb:22:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/request_id.rb:21:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/request_store-1.3.1/lib/request_store/middleware.rb:9:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/railties-4.2.6/lib/rails/rack/logger.rb:22:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/railties-4.2.6/lib/rails/rack/logger.rb:38:in `call_app'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/airbrake-5.4.1/lib/airbrake/rack/middleware.rb:22:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:81:in `run_callbacks'
18:15:57 web.1   | /usr/local/bundle/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
18:15:57 web.1   | /usr/local/bundle/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:88:in `__run_callbacks__'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/activerecord-4.2.6/lib/active_record/query_cache.rb:36:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/cookies.rb:560:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/rack-1.6.4/lib/rack/session/abstract/id.rb:220:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/rack-1.6.4/lib/rack/session/abstract/id.rb:225:in `context'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/flash.rb:260:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/actionpack-4.2.6/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:96:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/rack-1.6.4/lib/rack/head.rb:13:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/instrumentation/middleware_tracing.rb:108:in `call'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/transaction.rb:159:in `stop'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/method_tracer_helpers.rb:39:in `trace_execution_scoped_footer'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/method_tracer_helpers.rb:15:in `log_errors'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/method_tracer_helpers.rb:59:in `block in trace_execution_scoped_footer'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/method_tracer_helpers.rb:31:in `record_metrics'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/stats_engine/metric_stats.rb:96:in `record_scoped_and_unscoped_metrics'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/transaction_metrics.rb:29:in `record_scoped_and_unscoped'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/transaction_metrics.rb:60:in `_record_metrics'
18:15:57 web.1   | /usr/local/bundle/gems/newrelic_rpm-3.16.0.318/lib/new_relic/agent/stats.rb:68:in `record'
18:15:57 web.1   |
18:15:57 web.1   | -- Machine register context ------------------------------------------------
18:15:57 web.1   |  RIP: 0x00007fc4da928dbd RBP: 0x00007fc4bd8f5580 RSP: 0x00007fc4d886e5b0
18:15:57 web.1   |  RAX: 0x00007fc4daa0ea46 RBX: 0x000000000000008c RCX: 0x0000000000000001
18:15:57 web.1   |  RDX: 0x0000000000000000 RDI: 0x00007fc4bd8f15a0 RSI: 0x00007fc4bd8f5580
18:15:57 web.1   |   R8: 0x00007fc4eff6a280  R9: 0x0000000000000001 R10: 0x0000000000000000
18:15:57 web.1   |  R11: 0x0000000000000000 R12: 0x00007fc4d886e910 R13: 0x00007fc4eff6a260
18:15:57 web.1   |  R14: 0x00007fc4da929450 R15: 0x0000000000000001 EFL: 0x0000000000010202
18:15:57 web.1   |
18:15:57 web.1   | -- C level backtrace information -------------------------------------------
blowmage commented 8 years ago

Thanks for the issue. Might be related to #691

simonmorley commented 8 years ago

blaalarrr not puma again :(

blowmage commented 8 years ago

@simonmorley I have a branch that switches gcloud-ruby to use grpc 0.15.0. Can you set your rails app to reference this branch and let me know if this resolves the grpc_completion_queue_pluck error?

https://github.com/blowmage/gcloud-ruby/tree/grpc-0.15

/cc @murgatroid99

simonmorley commented 8 years ago

I just forced 0.15 in another way. That one is just building. After that, I'll do the same with this yours.

simonmorley commented 8 years ago

I have a couple of my servers in production running 0.15 without issue. Not from your branch though, do you want me to test with that also?

simonmorley commented 8 years ago

No errors but latency having a party.

screen shot 2016-06-29 at 23 18 10
blowmage commented 8 years ago

@murgatroid99 Any thoughts on the added latency?

blowmage commented 8 years ago

@simonmorley How did you force 0.15.0? I don't know if my branch will be any different. Depends on what exactly you did.

simonmorley commented 8 years ago

As a reference, until 11pm, we were publishing the messages into rabbitmq. That was the only change.

I just installed via the gemfile ~> 0.15

    gcloud (0.6.3)
      beefcake (~> 1.0)
      digest-crc (~> 0.4)
      google-api-client (~> 0.8.3)
      mime-types (~> 2.4)
      zonefile (~> 1.04)

    google-api-client (0.8.6)
      activesupport (>= 3.2)
      addressable (~> 2.3)
      autoparse (~> 0.3)
      extlib (~> 0.9)
      faraday (~> 0.9)
      googleauth (~> 0.3)
      launchy (~> 2.4)
      multi_json (~> 1.10)
      retriable (~> 1.4)
      signet (~> 0.6)

    google-protobuf (3.0.0.alpha.5.0.5.1)

    googleauth (0.5.1)
      faraday (~> 0.9)
      jwt (~> 1.4)
      logging (~> 2.0)
      memoist (~> 0.12)
      multi_json (~> 1.11)
      os (~> 0.9)
      signet (~> 0.7)

    grpc (0.15.0)
      google-protobuf (~> 3.0.0.alpha.5.0.3)
      googleauth (~> 0.5.1)
blowmage commented 8 years ago

@simonmorley gcloud-ruby version 0.6.3 used the REST API for Pub/Sub, not the gRPC API. So the latency you see might be due to that. I'd try using my branch and see how that works for you.

It looks like grpc 0.15 doesn't have the issues that 0.14 had, which is super encouraging.

In the issue description you say:

We happen to have tried without the Ruby client but suffered from horrific latency.

I'm having trouble parsing that. Can you clarify that statement? What clients have you used? Are you using something other than the Google Cloud Pub/Sub service?

simonmorley commented 8 years ago

That might explain it. Let me rebuild.

And your comment about the REST API basically resolves my vagueness. We had tried using the google-api-client since we already had that. That's what first gave us high latencies. We swapped to the gcloud gem to test not realising the both used http.

That will also explain the photo I was just about to send:

screen shot 2016-06-29 at 23 32 18

Confused why there's a get and post in each request.

blowmage commented 8 years ago

Confused why there's a get and post in each request.

Depends on what your code is doing! :)

simonmorley commented 8 years ago

Lol. Ok, you can have that. Should just be a publish, nothing else. Honest guvnor.

Your branch installed, things are looking normal. No crashes/

screen shot 2016-06-30 at 00 19 40
blowmage commented 8 years ago

Woo! God to see latency drop!

simonmorley commented 8 years ago

I think that went pretty well on the whole, thank you for the help.

Just seen this though. Ooops. Will request a quota increase, although there's no way we're at the limit.

Gcloud::ResourceExhaustedError (8:Request throttled due to project QPS limit being reached.):
simonmorley commented 8 years ago

Actually, having re-read the docs. It's now clear that the following also retrieves a topic:

topic = pubsub.topic 'my-topic'

That'll be why there's a get request in there and probably why we're over limit.

I'll move into a global variable and use that way instead.

blowmage commented 8 years ago

You can also use Gcloud::Pubsub::Project#publish to avoid the lookup request.

blowmage commented 8 years ago

Or you can create the topic object without the lookup call:

topic = pubsub.topic 'my-topic', skip_lookup: true
simonmorley commented 8 years ago

Thanks, this is great. Was surprised that was missing. Clearly reading the wrong docs.

Cheers for the help, things are looking rosy again.

blowmage commented 7 years ago

Closing this issue. If this is still an issue for grpc 1.1.2 please open a new issue.