我的应用程序不断创建数据库连接，我该如何追踪原因？

Question

我有一个运行在Heroku上的Ruby on Rails应用程序。日志中一直出现以下信息：

2015-05-05T16:11:14Z app[postgres.27102]: [AQUA] connection received: host=xx.xxx.xx.26 port=60278
2015-05-05T16:11:14Z app[postgres.27102]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:14Z app[postgres.27103]: [AQUA] connection received: host=xx.xxx.xx.26 port=60291
2015-05-05T16:11:14Z app[postgres.27103]: [AQUA] connection authorized: user=postgres database=postgres
2015-05-05T16:11:18Z app[postgres.27104]: [AQUA] connection received: host=xx.xxx.x.166 port=54180
2015-05-05T16:11:18Z app[postgres.27104]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:23Z app[postgres.27105]: [AQUA] connection received: host=xx.xxx.x.166 port=55488
2015-05-05T16:11:23Z app[postgres.27105]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:28Z app[postgres.27106]: [AQUA] connection received: host=xx.xxx.x.166 port=56774
2015-05-05T16:11:28Z app[postgres.27106]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:28Z app[postgres.27107]: [AQUA] connection received: host=xx.xxx.x.166 port=56854
2015-05-05T16:11:28Z app[postgres.27107]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:28Z app[postgres.27108]: [AQUA] connection received: host=xx.xxx.x.166 port=56885
2015-05-05T16:11:28Z app[postgres.27108]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:28Z app[postgres.27109]: [AQUA] connection received: host=xx.xxx.x.166 port=56912
2015-05-05T16:11:28Z app[postgres.27109]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:33Z app[postgres.27110]: [AQUA] connection received: host=xx.xxx.x.166 port=58039
2015-05-05T16:11:33Z app[postgres.27110]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:38Z app[postgres.27111]: [AQUA] connection received: host=xx.xxx.x.166 port=59387
2015-05-05T16:11:38Z app[postgres.27111]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:43Z app[postgres.27112]: [AQUA] connection received: host=xx.xxx.x.166 port=60944
2015-05-05T16:11:43Z app[postgres.27112]: [AQUA] connection authorized: user=postgres database=somedb
2015-05-05T16:11:14+00:00 app[heroku-postgres]: source=HEROKU_POSTGRESQL_AQUA sample#current_transaction=511990 sample#db_size=203303096bytes sample#tables=17 sample#active-connections=2 sample#waiting-connections=0 sample#index-cache-hit-rate=0.99997 sample#table-cache-hit-rate=0.94699 sample#load-avg-1m=0.14 sample#load-avg-5m=0.25 sample#load-avg-15m=0.24 sample#read-iops=0.1875 sample#write-iops=1 sample#memory-total=7629448kB sample#memory-free=428388kB sample#memory-cached=6784860kB sample#memory-postgres=171732kB

我无法弄清楚是什么原因导致了这个问题。该应用程序运行Cedar 10堆栈，ruby 2.1.4，rails 3.2.11和带有3个工作进程和1个线程的puma 2.11.2。这种情况并没有在开发或者测试环境中出现，只在Heroku上出现。

运行：select application_name from pg_stat_activity; 显示：

        application_name         
---------------------------------

 puma: cluster worker 2: 3 [app]
 puma: cluster worker 1: 3 [app]
 puma: cluster worker 0: 3 [app]
 psql johnny interactive

这是我的puma配置文件（最小和最大线程均为1）：

workers Integer(ENV['PUMA_WORKERS'] || 3)
threads Integer(ENV['MIN_THREADS']  || 1), Integer(ENV['MAX_THREADS'] || 16)

preload_app!

rackup      DefaultRackup
port        ENV['PORT']     || 3000
environment ENV['RACK_ENV'] || 'development'

on_worker_boot do
  # worker specific setup
  ActiveSupport.on_load(:active_record) do
    config = ActiveRecord::Base.configurations[Rails.env] ||
                Rails.application.config.database_configuration[Rails.env]
    config['pool'] = ENV['MAX_THREADS'] || 16
    ActiveRecord::Base.establish_connection(config)
  end
end

有没有任何想法可以追踪这个问题？

更新：我在on_worker_boot块中添加了调试消息，但它只会在应用程序启动时被调用，所以我仍然不知道为什么连接如此频繁地建立。

- Johnny

---

这可能是一个附加组件建立这些连接。您安装了哪些附加组件？ - infused

Postgres，Mandrill，New Relic，Papertrail，PG Backups，RedisToGo和Heroku Scheduler。 - Johnny

脑海中浮现出几个问题 - 1）您要安排什么（如果有的话）？2）是否有任何来自New Relic的健康检查可能与频率（大致）相对应？ - bimsapi

1. 每24小时运行一次备份作业，每小时发送电子邮件的作业和每10分钟创建DB记录的作业。所有这些作业都非常快速。我认为它们与此无关，因为这些日志在系统上线时立即开始记录。
2. 没有New Relic健康检查。

- Johnny

Answer 1

这是关于建立与Postgres连接的非正式日志记录。因此，您可以忽略它们或尝试在postgresql.conf中禁用它们（请参阅log_connections选项），但我不认为您在Heroku上有访问权限。

- willis

---

我认为不是这样的。如果你查看日志，它每秒钟都会创建多次连接。这不是它应该的行为。 - Johnny

这是日志的开始吗？还是在应用程序工作几分钟后才看到这样的日志信息？如果是第一种情况，可能与启动 Puma 工作进程有关；如果是第二种情况，则表示存在问题。 - willis

这几乎是连续的。 - Johnny

Answer 2

虽然我没有使用过Heroku，但你尝试过使用像xray这样的工具获取ruby进程的线程转储吗？ http://blog.pivotal.io/labs/labs/inspect-running-ruby-processes-using-xray-and-kill-3

线程堆栈可能有助于指出这些调用的来源。

- codedabbler

---

这是线程转储的结果：http://dumptext.com/piqHWgAq。不太确定如何解释这个。 - Johnny

我不知道追踪中出了什么问题。很可能是由于某些错误导致工作进程崩溃并正在重新启动。有更多经验的人可以在这里提供帮助。 - codedabbler