Skip to content
Snippets Groups Projects
New issue look: Off

Upgrade from 7.14 to 8.x slows down Sidekiq jobs: issue with commits count in repositories?

    • Closed Issue created by username-removed-39115 @daniel.leberre

    I noticed that since I upgraded to 8.x two weeks ago (from 7.14) merging may take also ages in my case (a few hours), and that the web app is not properly updated.

    The reason for that is that some Sidekiq jobs take hours to complete:

    2015-11-24T19:33:53.172Z 1675 TID-ouioxol88 PostReceive JID- INFO: done: 3231.524 sec
2015-11-24T20:20:19.285Z 1675 TID-ouiovs6f4 ProjectCacheWorker JID-6462f97941c43b42b706edc9 INFO: done: 5572.114 sec
2015-11-24T20:35:47.984Z 1675 TID-ouiov013o PostReceive JID- INFO: done: 6481.818 sec
2015-11-24T20:51:16.743Z 1675 TID-ouioxl488 ProjectCacheWorker JID-7b3d7d458f711bc3e1a0c325 INFO: done: 6500.514 sec
2015-11-24T21:06:45.442Z 1675 TID-ouioxa0l0 PostReceive JID- INFO: done: 7126.051 sec
2015-11-24T21:22:14.153Z 1675 TID-ouiou12mo PostReceive JID- INFO: done: 7473.421 sec
2015-11-24T21:37:42.849Z 1675 TID-ouiox3e4k PostReceive JID- INFO: done: 7993.463 sec
2015-11-24T21:53:11.548Z 1675 TID-ouioxol88 ProjectCacheWorker JID-12780dfd5e608dfc4622b146 INFO: done: 8358.296 sec

    As suggested by @stanhu in the ML, it might be related to counting the number of commits in the repository.

    I maintain a gitlab instance for our university. We have 685 projects and 537 users currently. Most projects are students projects, so they do not contain that many commits.

    Designs

    Child items 0

    • No child items are currently open.

    Activity

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      What's odd to me is that all of those services are taking a long time. PostReceive should just take moments to process each new push. ProjectCacheWorker the repository size, the commit count, and the cache (branch names etc.). This shouldn't take very long.

      Is it possible there is something going on with this machine? Do you see unusual CPU or disk activity while these workers are in progress?

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      No, that's the weird thing. It looks like the jobs are stalled on Sidekiq queue. Then at some point they are executed.

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      could it be related to #3649 (closed) ?

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      Some additional information from the logs: it might be related to database connections.

      Here is what I see (note the waited 7429.618 seconds):

      2015-11-25T13:18:55.151Z 1675 TID-ouipj4wa8 WARN: could not obtain a database connection within 5.000 seconds (waited 7429.618 seconds)
2015-11-25T13:18:55.152Z 1675 TID-ouipj4wa8 WARN: /home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `block in wait_poll'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `loop'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `wait_poll'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:136:in `block in poll'
/usr/local/lib/ruby/2.1.0/monitor.rb:211:in `mon_synchronize'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:146:in `synchronize'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:134:in `poll'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:418:in `acquire_connection'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:351:in `block in checkout'
/usr/local/lib/ruby/2.1.0/monitor.rb:211:in `mon_synchronize'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:350:in `checkout'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:265:in `block in connection'
/usr/local/lib/ruby/2.1.0/monitor.rb:211:in `mon_synchronize'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:264:in `connection'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_adapters/abstract/connection_pool.rb:541:in `retrieve_connection'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_handling.rb:113:in `retrieve_connection'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/connection_handling.rb:87:in `connection'
/home/git/gitlab/lib/gitlab/database.rb:8:in `postgresql?'
/home/git/gitlab/app/models/concerns/case_sensitivity.rb:11:in `iwhere'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/relation/delegation.rb:70:in `block in iwhere'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/relation.rb:292:in `scoping'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/relation/delegation.rb:70:in `iwhere'
/home/git/gitlab/app/models/project.rb:253:in `find_with_namespace'
/home/git/gitlab/app/workers/post_receive.rb:17:in `perform'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:75:in `execute_job'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:52:in `block (2 levels) in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:127:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:127:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidetiq-0.6.3/lib/sidetiq/middleware/history.rb:8:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/logging.rb:22:in `with_context'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:132:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:132:in `invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:51:in `block in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:98:in `stats'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:50:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `public_send'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `dispatch'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in `dispatch'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15:in `block in create'
2015-11-25T13:18:55.157Z 1675 TID-ouiou12mo PostReceive JID- INFO: start
Server timed out, retrying
      Edited by username-removed-39115
    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      That is really odd. Is your database on an external network? Are there errors in your database logs?

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      The database is on another computer. I have to check the logs of that database.

      Again, gitlab worked fine until 30 minutes ago. The jobs stalled again. a service gitlab restart solves the problem.

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      And here is a normal-problem-back-to-normal log: I really do not understand what's going on.

      2015-11-25T17:51:10.227Z 5504 TID-owb9tyj70 EmailsOnPushWorker JID-9de4eb5061bb853213d91ac1 INFO: done: 6.932 sec

2015-11-25T17:51:10.389Z 5504 TID-owb9sxt04 EmailsOnPushWorker JID-05747111b9a162e8d051e3eb INFO: done: 5.583 sec

2015-11-25T17:51:10.505Z 5504 TID-owb9x54bg EmailsOnPushWorker JID-18ff98010643ab7125cf92fe INFO: done: 5.702 sec

2015-11-25T17:51:12.460Z 5504 TID-owb9t0p14 EmailsOnPushWorker JID-e424c2dab8480089cc8ab3d3 INFO: done: 5.519 sec

2015-11-25T17:51:16.415Z 5504 TID-owb9t0p14 Sidekiq::Extensions::DelayedMailer JID-2d0dff7008e3b988339b25e2 INFO: start

2015-11-25T17:51:21.754Z 5504 TID-owb9t0p14 Sidekiq::Extensions::DelayedMailer JID-2d0dff7008e3b988339b25e2 INFO: done: 5.339 sec

2015-11-25T17:58:05.743Z 5504 TID-owb9t0p14 PostReceive JID- INFO: start

2015-11-25T17:58:05.812Z 5504 TID-owb9x54bg ProjectServiceWorker JID-372d944ac48db28a0d56b963 INFO: start

2015-11-25T17:58:05.814Z 5504 TID-owb9t0p14 PostReceive JID- INFO: done: 0.07 sec

2015-11-25T17:58:05.814Z 5504 TID-owb9sxt04 ProjectCacheWorker JID-1416b0d50cfc3ed7edb85932 INFO: start

2015-11-25T17:58:05.866Z 5504 TID-owb9sxt04 ProjectCacheWorker JID-1416b0d50cfc3ed7edb85932 INFO: done: 0.051 sec

2015-11-25T17:58:05.941Z 5504 TID-owb9x54bg ProjectServiceWorker JID-372d944ac48db28a0d56b963 INFO: done: 0.13 sec

2015-11-25T19:29:29.645Z 5504 TID-owb9x54bg PostReceive JID- INFO: start

2015-11-25T19:31:23.168Z 5504 TID-owb9sxt04 PostReceive JID- INFO: start

2015-11-25T19:34:14.753Z 5504 TID-owb9t0p14 PostReceive JID- INFO: start

2015-11-25T19:44:58.429Z 5504 TID-owb9tyj70 ProjectServiceWorker JID-7b9b224a56cdb1545b6c2c1a INFO: start

2015-11-25T19:44:58.433Z 5504 TID-owb9ubmss ProjectCacheWorker JID-8a5f757a9b52dd9b99488d36 INFO: start

2015-11-25T19:45:06.292Z 5504 TID-owb9vcq00 PostReceive JID- INFO: start

2015-11-25T19:53:48.633Z 5504 TID-owb9vs4g0 PostReceive JID- INFO: start

2015-11-25T20:00:27.112Z 5504 TID-owb9x6fjg ProjectServiceWorker JID-448c9490be298b33c5f5d024 INFO: start

2015-11-25T20:00:27.113Z 5504 TID-owb9vuz6w ProjectCacheWorker JID-a669496879c3f84721f6ee31 INFO: start

2015-11-25T20:06:25.888Z 5504 TID-owb9tp3mk PostReceive JID- INFO: start

2015-11-25T20:15:55.746Z 5504 TID-owb9x54bg PostReceive JID- INFO: done: 2786.101 sec

2015-11-25T20:15:55.809Z 5504 TID-owb9sxt04 PostReceive JID- INFO: done: 2672.641 sec

2015-11-25T20:15:56.047Z 5504 TID-owb9t0p14 PostReceive JID- INFO: done: 2501.294 sec

2015-11-25T20:15:56.072Z 5504 TID-owb9t0p14 ProjectServiceWorker JID-b8e0240a3a840493df3df340 INFO: start

2015-11-25T20:15:56.085Z 5504 TID-owb9sxt04 ProjectCacheWorker JID-752861350bf029846ee47fe0 INFO: start

2015-11-25T20:15:56.140Z 5504 TID-owb9vcq00 PostReceive JID- INFO: done: 1849.848 sec

2015-11-25T20:15:56.166Z 5504 TID-owb9x54bg ProjectCacheWorker JID-849e4a999f571d9328742781 INFO: start

2015-11-25T20:15:56.247Z 5504 TID-owb9vcq00 ProjectServiceWorker JID-bc8a636cb0ef1dc986cad549 INFO: start

2015-11-25T20:15:56.252Z 5504 TID-owb9vtdc4 ProjectCacheWorker JID-d869160fe7949012aac2da19 INFO: start

2015-11-25T20:15:56.257Z 5504 TID-owb9vs4g0 PostReceive JID- INFO: done: 1327.624 sec

2015-11-25T20:15:56.261Z 5504 TID-owb9tyj70 ProjectServiceWorker JID-7b9b224a56cdb1545b6c2c1a INFO: done: 1857.832 sec

2015-11-25T20:15:56.301Z 5504 TID-owb9x6fjg ProjectServiceWorker JID-448c9490be298b33c5f5d024 INFO: done: 929.189 sec

2015-11-25T20:15:56.312Z 5504 TID-owb9vuz6w ProjectCacheWorker JID-a669496879c3f84721f6ee31 INFO: done: 929.198 sec

2015-11-25T20:15:56.323Z 5504 TID-owb9ubmss ProjectCacheWorker JID-8a5f757a9b52dd9b99488d36 INFO: done: 1857.89 sec

2015-11-25T20:15:56.366Z 5504 TID-owb9ubmss ProjectServiceWorker JID-94e186765ec74840fe1fe264 INFO: start

2015-11-25T20:15:56.375Z 5504 TID-owb9tp3mk PostReceive JID- INFO: done: 570.487 sec

2015-11-25T20:15:56.377Z 5504 TID-owb9sxt04 ProjectCacheWorker JID-752861350bf029846ee47fe0 INFO: done: 0.292 sec

2015-11-25T20:15:56.393Z 5504 TID-owb9ubmss ProjectServiceWorker JID-94e186765ec74840fe1fe264 INFO: done: 0.028 sec

2015-11-25T20:15:56.396Z 5504 TID-owb9vuz6w ProjectCacheWorker JID-0e12b04acbd4070bbf26b562 INFO: start

2015-11-25T20:15:56.404Z 5504 TID-owb9x6fjg EmailsOnPushWorker JID-478ea5ce6a7d28d3927cb373 INFO: start

2015-11-25T20:15:56.494Z 5504 TID-owb9x54bg ProjectCacheWorker JID-849e4a999f571d9328742781 INFO: done: 0.328 sec

2015-11-25T20:15:56.562Z 5504 TID-owb9t0p14 ProjectServiceWorker JID-b8e0240a3a840493df3df340 INFO: done: 0.49 sec

2015-11-25T20:15:56.567Z 5504 TID-owb9vtdc4 ProjectCacheWorker JID-d869160fe7949012aac2da19 INFO: done: 0.315 sec

2015-11-25T20:15:56.585Z 5504 TID-owb9vcq00 ProjectServiceWorker JID-bc8a636cb0ef1dc986cad549 INFO: done: 0.338 sec

2015-11-25T20:15:56.903Z 5504 TID-owb9vuz6w ProjectCacheWorker JID-0e12b04acbd4070bbf26b562 INFO: done: 0.507 sec

2015-11-25T20:16:13.325Z 5504 TID-owb9x6fjg EmailsOnPushWorker JID-478ea5ce6a7d28d3927cb373 INFO: done: 16.921 sec

2015-11-25T20:24:42.276Z 5504 TID-owb9x6fjg Sidekiq::Extensions::DelayedMailer JID-6c1721120f360415e80aa1c0 INFO: start

2015-11-25T20:24:47.789Z 5504 TID-owb9x6fjg Sidekiq::Extensions::DelayedMailer JID-6c1721120f360415e80aa1c0 INFO: done: 5.513 sec

2015-11-25T20:50:04.693Z 5504 TID-owb9x6fjg PostReceive JID- INFO: start

2015-11-25T20:50:04.813Z 5504 TID-owb9vcq00 ProjectCacheWorker JID-dc8193c6bacdc3ece7b5c26c INFO: start

2015-11-25T20:50:04.814Z 5504 TID-owb9vuz6w ProjectServiceWorker JID-6363b6bf07717947e3a13fb2 INFO: start

2015-11-25T20:50:04.819Z 5504 TID-owb9x6fjg PostReceive JID- INFO: done: 0.126 sec

2015-11-25T20:50:04.820Z 5504 TID-owb9vuz6w ProjectServiceWorker JID-6363b6bf07717947e3a13fb2 INFO: done: 0.007 sec

2015-11-25T20:50:04.821Z 5504 TID-owb9vtdc4 EmailsOnPushWorker JID-7d5b9fb4a8110ca7935fec15 INFO: start

2015-11-25T20:50:04.942Z 5504 TID-owb9vcq00 ProjectCacheWorker JID-dc8193c6bacdc3ece7b5c26c INFO: done: 0.129 sec

2015-11-25T20:50:10.164Z 5504 TID-owb9vtdc4 EmailsOnPushWorker JID-7d5b9fb4a8110ca7935fec15 INFO: done: 5.343 sec

2015-11-25T20:51:06.185Z 5504 TID-owb9vtdc4 PostReceive JID- INFO: start

2015-11-25T20:51:06.289Z 5504 TID-owb9vcq00 ProjectServiceWorker JID-117553c4d0b61b44dafdd066 INFO: start

2015-11-25T20:51:06.290Z 5504 TID-owb9vuz6w ProjectCacheWorker JID-f2bf228bfec145d2d49c6029 INFO: start

2015-11-25T20:51:06.295Z 5504 TID-owb9vtdc4 PostReceive JID- INFO: done: 0.11 sec

2015-11-25T20:51:06.297Z 5504 TID-owb9vcq00 ProjectServiceWorker JID-117553c4d0b61b44dafdd066 INFO: done: 0.008 sec

2015-11-25T20:51:06.298Z 5504 TID-owb9x6fjg EmailsOnPushWorker JID-4a4c9f6b3ce83be7c41abc27 INFO: start

2015-11-25T20:51:06.502Z 5504 TID-owb9vuz6w ProjectCacheWorker JID-f2bf228bfec145d2d49c6029 INFO: done: 0.211 sec

2015-11-25T20:51:11.679Z 5504 TID-owb9x6fjg EmailsOnPushWorker JID-4a4c9f6b3ce83be7c41abc27 INFO: done: 5.382 sec

2015-11-25T20:59:15.053Z 5504 TID-owb9x6fjg PostReceive JID- INFO: start

2015-11-25T20:59:15.122Z 5504 TID-owb9x6fjg PostReceive JID- INFO: done: 0.069 sec

2015-11-25T20:59:15.124Z 5504 TID-owb9vuz6w ProjectCacheWorker JID-c3eee44be444ec7942a79ce3 INFO: start

2015-11-25T20:59:15.348Z 5504 TID-owb9vuz6w ProjectCacheWorker JID-c3eee44be444ec7942a79ce3 INFO: done: 0.224 sec
    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      I wonder if one of the issues might explain something:

      Do you have HAProxy or some other proxy in front of your database?

      Edited by Stan Hu
    • username-removed-39115 mentioned in issue #3649 (closed)

      mentioned in issue #3649 (closed)

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      I updated our redis server to 2.8 and still have the same issue, so it is unrelated to #3649 (closed).

      We do not have any proxy in front of our database. I updated the pool size to 20 instead of 10. It does not solve the problem.

      Gitlab is currently not usable for project management in my case: I need to wait hours to get notifications, see activity update on the dashboard, etc.

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      When I check Sidekiq logs on the server, I can see a lot of ActiveRecord issues, such as:

      2015-11-30T10:24:49.425Z 9118 TID-ow4ogslmo WARN: Couldn't find Note with 'id'=1683
2015-11-30T10:24:49.425Z 9118 TID-ow4ogslmo WARN: /home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/relation/finder_methods.rb:320:in `raise_record_not_found_exception!'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/relation/finder_methods.rb:429:in `find_one'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/relation/finder_methods.rb:413:in `find_with_ids'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/relation/finder_methods.rb:68:in `find'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.1.12/lib/active_record/querying.rb:3:in `find'
/home/git/gitlab/app/mailers/emails/notes.rb:19:in `note_issue_email'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionpack-4.1.12/lib/abstract_controller/base.rb:189:in `process_action'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionpack-4.1.12/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.12/lib/active_support/callbacks.rb:82:in `run_callbacks'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionpack-4.1.12/lib/abstract_controller/callbacks.rb:19:in `process_action'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionpack-4.1.12/lib/abstract_controller/base.rb:136:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionview-4.1.12/lib/action_view/rendering.rb:30:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.1.12/lib/action_mailer/base.rb:580:in `block in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.12/lib/active_support/notifications.rb:159:in `block in instrument'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.12/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.12/lib/active_support/notifications.rb:159:in `instrument'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.1.12/lib/action_mailer/base.rb:577:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.1.12/lib/action_mailer/base.rb:568:in `initialize'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.1.12/lib/action_mailer/base.rb:551:in `new'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.1.12/lib/action_mailer/base.rb:551:in `method_missing'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/extensions/action_mailer.rb:17:in `public_send'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/extensions/action_mailer.rb:17:in `perform'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:75:in `execute_job'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:52:in `block (2 levels) in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:127:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:127:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidetiq-0.6.3/lib/sidetiq/middleware/history.rb:8:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/logging.rb:22:in `with_context'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:132:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:132:in `invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:51:in `block in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:98:in `stats'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:50:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `public_send'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `dispatch'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in `dispatch'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15:in `block in create'
2015-11-30T10:26:16.480Z 9118 TID-ow4ogslmo Sidekiq::Extensions::DelayedMailer JID-bb38fb8e928fe6d3815219ff INFO: start
2015-11-30T10:26:16.486Z 9118 TID-ow4ogslmo Sidekiq::Extensions::DelayedMailer JID-bb38fb8e928fe6d3815219ff INFO: fail: 0.006 sec

      and

      2015-11-30T10:23:24.228Z 9118 TID-ow4o10hd0 WARN: /home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.12/lib/active_support/dependencies.rb:478:in `load_missing_constant'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.12/lib/active_support/dependencies.rb:180:in `const_missing'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.12/lib/active_support/dependencies.rb:512:in `load_missing_constant'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.1.12/lib/active_support/dependencies.rb:180:in `const_missing'
/home/git/gitlab/app/models/repository.rb:606:in `cache'
/home/git/gitlab/app/models/repository.rb:184:in `block in expire_cache'
/home/git/gitlab/app/models/repository.rb:183:in `each'
/home/git/gitlab/app/models/repository.rb:183:in `expire_cache'
/home/git/gitlab/app/services/git_push_service.rb:21:in `execute'
/home/git/gitlab/app/workers/post_receive.rb:41:in `block in perform'
/home/git/gitlab/app/workers/post_receive.rb:28:in `each'
/home/git/gitlab/app/workers/post_receive.rb:28:in `perform'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:75:in `execute_job'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:52:in `block (2 levels) in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:127:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:127:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidetiq-0.6.3/lib/sidetiq/middleware/history.rb:8:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/logging.rb:22:in `with_context'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:132:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/middleware/chain.rb:132:in `invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:51:in `block in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:98:in `stats'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-3.3.0/lib/sidekiq/processor.rb:50:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `public_send'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `dispatch'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in `dispatch'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15:in `block in create'

      The logs are typically not updated correctly currently on the webapp so I cannot really on the admin panel to check what's going on.

      Could it be possible that the exceptions launched by ActiveRecord could simple exhaust the connections in the database, thus blocking the other process requiring a database connection?

    • username-removed-289841
      username-removed-289841 @fernandoneto ·

      Im getting the same problem in 8.2.1

      2015-12-22T17:19:11.457Z 801 TID-9u8vc ProjectServiceWorker JID-f4fd4b2cda2b5f9d71f49051 INFO: start
2015-12-22T17:19:11.474Z 801 TID-7dmqc ProjectCacheWorker JID-22cfe6af5c16bb3804f4a25e INFO: start
2015-12-22T17:34:41.616Z 801 TID-9s6h0 PostReceive JID- INFO: done: 11147.723 sec
2015-12-22T17:34:41.617Z 801 TID-98fik ProjectServiceWorker JID-2957b38bcf56b73f15fc336a INFO: done: 10243.003 sec
2015-12-22T17:34:41.617Z 801 TID-9r36k ProjectCacheWorker JID-d2e97f845deff3db5257aeda INFO: done: 10242.986 sec
2015-12-22T17:34:41.617Z 801 TID-9sz6c ProjectServiceWorker JID-c5e717d14848ef0ca44049be INFO: done: 9313.251 sec
2015-12-22T17:34:41.617Z 801 TID-9qsuw ProjectCacheWorker JID-c5dde439fe2ff7f9a9c2f1a0 INFO: done: 9313.247 sec
2015-12-22T17:34:41.617Z 801 TID-808bs ProjectServiceWorker JID-41848f33bdf3694c946ff7b8 INFO: done: 8379.269 sec
2015-12-22T17:34:41.617Z 801 TID-973xs ProjectCacheWorker JID-433e94b20d2b840c18331485 INFO: done: 8379.255 sec
2015-12-22T17:34:41.624Z 801 TID-7n2gw PostReceive JID- INFO: done: 7746.919 sec
2015-12-22T17:35:51.943Z 801 TID-973xs PostReceive JID- INFO: start
2015-12-22T17:46:06.371Z 801 TID-7n2gw PostReceive JID- INFO: start
2015-12-22T17:47:54.335Z 801 TID-9r36k PostReceive JID- INFO: start
2015-12-22T17:50:13.265Z 801 TID-9s6h0 ProjectCacheWorker JID-cc4097009d89d6bca57d002e INFO: start
2015-12-22T18:05:44.555Z 801 TID-98fik ProjectServiceWorker JID-a742e744ee32ac10530a9b2e INFO: start
2015-12-22T18:05:44.558Z 801 TID-808bs ProjectCacheWorker JID-e3df839f40db539413bec345 INFO: start
2015-12-22T18:17:41.240Z 801 TID-9qsuw PostReceive JID- INFO: start
2015-12-22T18:21:15.908Z 801 TID-9sz6c ProjectServiceWorker JID-8ef278982fb6ad65207fb878 INFO: start
2015-12-22T18:21:15.913Z 801 TID-5i534 ProjectCacheWorker JID-956f24af53f1634bd7b6c543 INFO: start
2015-12-22T18:25:12.651Z 801 TID-ull2g PostReceive JID- INFO: start
2015-12-22T18:36:47.316Z 801 TID-ukri0 ProjectCacheWorker JID-881ead8e7df648494932a45f INFO: start

      does anyone have a solution?

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      After upgrading to 8.3.2, I still have the same problem: the jobs look like blocked at some point, and the only way to retrieve a normal behavior is to perform a service gitlab restart.

      It never happened before 8.0 (I have been running gitlab for almost 2 years before).

    • username-removed-289841
      username-removed-289841 @fernandoneto ·

      @daniel.leberre how many sidekiq workers are busy when gitlab stuck? im my case im using v8.2.1 and when gitlab block all sidekiq workers are busy 25/25. I even thought that the problem could be the sidekiq . But the latest versions of gitlab use the most recent version of sidekiq.

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      @fernandoneto Only 5, on two different queues (post_receive and default). This is why I do not understand that the jobs are stalled. They will eventually complete, after thousands of seconds, but this is unacceptable for daily operations.

      Yes, I am running sidekiq 4.0.1, I hoped it could solve the problem. It does not.

    • username-removed-289841
      username-removed-289841 @fernandoneto ·

      @daniel.leberre i have big hope in sidekiq 4.0.1. One thing we can all do is work together and share informations to understand the origin of problem, because only few users are getting this problem so it can be a configuration problem.

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      I wonder if the issue I met is not due to several different issues which end up launching an exception when the job is executed. Here is the kind of error I get in sidekiq.log

      2016-01-05T15:32:19.688Z 8874 TID-oryzc9og4 WARN: RuntimeError: Circular dependency detected while autoloading constant Banzai::LazyReference
2016-01-05T15:32:19.688Z 8874 TID-oryzc9og4 WARN: /home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/dependencies.rb:492:in `load_missing_constant'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/dependencies.rb:184:in `const_missing'
/home/git/gitlab/lib/banzai/reference_extractor.rb:21:in `lazily'
/home/git/gitlab/lib/banzai/reference_extractor.rb:46:in `references'
/home/git/gitlab/lib/gitlab/reference_extractor.rb:33:in `issues'
/home/git/gitlab/lib/gitlab/closing_issue_extractor.rb:25:in `closed_by_message'
/home/git/gitlab/app/models/commit.rb:174:in `closes_issues'
/home/git/gitlab/app/services/git_push_service.rb:92:in `block in process_commit_messages'
/home/git/gitlab/app/services/git_push_service.rb:82:in `each'
/home/git/gitlab/app/services/git_push_service.rb:82:in `process_commit_messages'
/home/git/gitlab/app/services/git_push_service.rb:52:in `execute'
/home/git/gitlab/app/workers/post_receive.rb:41:in `block in perform'
/home/git/gitlab/app/workers/post_receive.rb:28:in `each'
/home/git/gitlab/app/workers/post_receive.rb:28:in `perform'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:150:in `execute_job'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:132:in `block (2 levels) in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:127:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/logging.rb:30:in `with_context'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:132:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:132:in `invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:127:in `block in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:166:in `stats'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:126:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:79:in `process_one'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:67:in `run'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/util.rb:16:in `watchdog'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/util.rb:24:in `block in safe_thread'
    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      @fernandoneto I agree that it is probably a configuration problem. I have been updating my config files each month since sept 2013: I might have overlooked one change at some point which is only important right now.

    • username-removed-289841
      username-removed-289841 @fernandoneto ·

      @daniel.leberre we can use email if you want to prevent this issue get huge and only post relevant information to help. My email is fernando.neto@junglecloud.com

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      GitLab 8.3.x upgraded to Sidekiq 4.0. @daniel.leberre, are you still having issues with that?

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      Was the circular dependency fixed via 2a20c0e5?

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      Yes, I updated to sidekiq 4.01

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      No, I did not apply any patch yet. I can see the dependency problem in my logs.

      However, it is not clear that it is related to my problem: the timestamp does not seem to match the moment when the sidekiq jobs are paused.

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      @daniel.leberre One suggestion I have for you use something like ruby-prof to profile the different Sidekiq tasks (e.g. ProjectCacheWorker in app/workers/project_cache_worker.rb), save the outputs to different files, and see if there's an obvious place where all the time is being spent. I used it in this example.

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      @stanhu Thanks for the suggestion. I will try that. Note however that the issue is not AFAIK the task itself, since restarting gitlab will just allow the tasks to complete normally, i.e. in reasonable time (a few seconds).

      The issue is that sidekiq stops executing all the jobs, which are then just being enqueued, and will eventually fill in the queue. After thousands of seconds, the jobs are executed again.

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      Hmm, perhaps it's time to file an issue with Sidekiq then. There seems to be a number of closed issues that may be relevant:

      Edited by Stan Hu
    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      Thanks for the pointers. I noted in the comments that several people met issues while trying to connect to redis or other third party tools. I also believe that the issue is due to the jobs trying to access either our db (MySQL) or redis or gitlab-workhorse but that it fails to do so.

      We found from time to time some issues related to one of the framework in the logs, but could not isolate one as the source of our problem.

      Do you know if one exception raised during a sidekiq job could really pause sidekiq?

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      I had to restart gitlab this evening before going to bed.

      Here is what I found in the log.

      I sent a TINT signal to sidekiq as suggested in issue 2003 but it did not output anything.

      2016-01-20T22:32:01.820Z 28345 TID-orvxsmbk4 WARN: Thread TID-orvyn1qng 
2016-01-20T22:32:01.820Z 28345 TID-orvxsmbk4 WARN: /usr/local/lib/ruby/2.1.0/monitor.rb:185:in `lock'
/usr/local/lib/ruby/2.1.0/monitor.rb:185:in `mon_enter'
/usr/local/lib/ruby/2.1.0/monitor.rb:209:in `mon_synchronize'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:280:in `release_connection'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:552:in `each'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/connection_adapters/abstract/connection_pool.rb:552:in `clear_active_connections!'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activerecord-4.2.4/lib/active_record/connection_handling.rb:129:in `clear_active_connections!'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/active_record.rb:8:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/logging.rb:30:in `with_context'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:132:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:132:in `invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:127:in `block in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:166:in `stats'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:126:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:79:in `process_one'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:67:in `run'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/util.rb:16:in `watchdog'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/util.rb:24:in `block in safe_thread'
    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      And last one for the day, I see another circular dependency error in the logs:

      WARN: RuntimeError: Circular dependency detected while autoloading constant Gitlab::Email::Message::RepositoryPush
2016-01-20T22:35:39.205Z 4992 TID-oqzkmkemw WARN: /home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/dependencies.rb:492:in `load_missing_constant'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/dependencies.rb:184:in `const_missing'
/home/git/gitlab/app/mailers/emails/projects.rb:64:in `repository_push_email'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/abstract_controller/base.rb:198:in `process_action'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:88:in `__run_callbacks__'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:778:in `_run_process_action_callbacks'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/callbacks.rb:81:in `run_callbacks'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/abstract_controller/callbacks.rb:19:in `process_action'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionpack-4.2.4/lib/abstract_controller/base.rb:137:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionview-4.2.4/lib/action_view/rendering.rb:30:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.2.4/lib/action_mailer/base.rb:596:in `block in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/notifications.rb:164:in `block in instrument'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/activesupport-4.2.4/lib/active_support/notifications.rb:164:in `instrument'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.2.4/lib/action_mailer/base.rb:593:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.2.4/lib/action_mailer/base.rb:584:in `initialize'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.2.4/lib/action_mailer/message_delivery.rb:25:in `new'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.2.4/lib/action_mailer/message_delivery.rb:25:in `__getobj__'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.2.4/lib/action_mailer/message_delivery.rb:34:in `message'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/actionmailer-4.2.4/lib/action_mailer/message_delivery.rb:85:in `deliver_now'
/home/git/gitlab/app/workers/emails_on_push_worker.rb:56:in `block in perform'
/home/git/gitlab/app/workers/emails_on_push_worker.rb:44:in `each'
/home/git/gitlab/app/workers/emails_on_push_worker.rb:44:in `perform'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:150:in `execute_job'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:132:in `block (2 levels) in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:127:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/logging.rb:30:in `with_context'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:132:in `call'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:132:in `invoke'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:127:in `block in process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:166:in `stats'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:126:in `process'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:79:in `process_one'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:67:in `run'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/util.rb:16:in `watchdog'
/home/git/gitlab/vendor/bundle/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/util.rb:24:in `block in safe_thread'
    • username-removed-391823
      username-removed-391823 @Jakai ·

      Faced with the same problem after update 8.0->8.4.2

      GitLab 8.4.2
GitLab Shell 2.6.10
GitLab API v3
Git 1.9.1
Ruby 2.1.5p273
Rails 4.2.5.1 

System information
System:         Debian 7.8
Current User:   git
Using RVM:      no
Ruby Version:   2.1.5p273
Gem Version:    2.2.2
Bundler Version:1.7.7
Rake Version:   10.5.0
Sidekiq Version:4.0.1
      Edited by username-removed-391823
    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      I finally found the root of all my problems: a firewall was blocking database connections after 3600s of inactivity. It looks like release 8.X changed the way the database connections were used, thus increased the number of time it happened. The system was stalled when gitlab was trying to use a connection blocked by the firewall.

    • Stan Hu
      Stan Hu @stanhu ·
      Maintainer

      @daniel.leberre That sounds like something I've run into with Google Cloud. Have you tried adding keepalive settings in database.yml?

      http://www.postgresql.org/docs/9.1/static/libpq-connect.html

    • username-removed-39115
      username-removed-39115 @daniel.leberre ·
      Author

      Well, for the moment we use a workaround, and gitlab just rocks as it used to right now. I will keep an eye around that topic.

    • username-removed-391823
      username-removed-391823 @Jakai ·

      I use mysql

      MariaDB [(none)]> SHOW GLOBAL VARIABLES LIKE '%time%';
+---------------------------------+-------------------+
| Variable_name                   | Value             |
+---------------------------------+-------------------+
| connect_timeout                 | 10                |
| datetime_format                 | %Y-%m-%d %H:%i:%s |
| deadlock_timeout_long           | 50000000          |
| deadlock_timeout_short          | 10000             |
| delayed_insert_timeout          | 300               |
| explicit_defaults_for_timestamp | OFF               |
| flush_time                      | 0                 |
| handlersocket_timeout           | 3600              |
| handlersocket_wrlock_timeout    | 12                |
| innodb_flush_log_at_timeout     | 1                 |
| innodb_lock_wait_timeout        | 240               |
| innodb_old_blocks_time          | 1000              |
| innodb_rollback_on_timeout      | OFF               |
| interactive_timeout             | 28800             |
| lc_time_names                   | en_US             |
| lock_wait_timeout               | 31536000          |
| long_query_time                 | 0.000000          |
| max_statement_time              | 0.000000          |
| net_read_timeout                | 30                |
| net_write_timeout               | 60                |
| progress_report_time            | 5                 |
| slave_net_timeout               | 3600              |
| slow_launch_time                | 2                 |
| system_time_zone                | MSK               |
| thread_pool_idle_timeout        | 60                |
| time_format                     | %H:%i:%s          |
| time_zone                       | SYSTEM            |
| timed_mutexes                   | OFF               |
| wait_timeout                    | 28800             |
+---------------------------------+-------------------+
29 rows in set (0.00 sec)
    • username-removed-391823
      username-removed-391823 @Jakai · 
      Process 	TID 	JID 	Очередь 	Задача 	Аргументы 	Запущено
domain:10072:280c4e3b546b 	osqql6ntw 	9ea7d02778732df9ed35363d 	default ProjectCacheWorker 2 23 минуты назад
domain:10072:280c4e3b546b 	osqpyim44 	510bf490ae19b377e83b43b7 	default  ProjectCacheWorker 2 11 минут назад

      I think I found the problem. The task "ProjectCacheWorker" with argument "2" takes a long time. And more of them accumulated in the queue handled the longer the rest. I understand how the cache is built. And judging by the code argument of "2" is project_id I know that it is for the project and that it is big. But before such was not. How to find out why this task is carried out so long?

    • username-removed-391823
      username-removed-391823 @Jakai ·

      before upgrade

      2016-01-29T08:10:32.364Z 11311 TID-otbdi82jg ProjectCacheWorker JID-00089604c4d8865488f34f2f INFO: done: 4.314 sec
2016-01-29T08:24:02.335Z 13237 TID-oucs18fzc ProjectCacheWorker JID-c17a5fece626c7313b7f4cce INFO: start
2016-01-29T08:24:06.947Z 13237 TID-oucs18fzc ProjectCacheWorker JID-c17a5fece626c7313b7f4cce INFO: done: 4.612 sec
2016-01-29T08:31:29.595Z 13237 TID-oucrzfcuk ProjectCacheWorker JID-098ec041815c5917dc84e48b INFO: start
2016-01-29T08:31:34.050Z 13237 TID-oucrzfcuk ProjectCacheWorker JID-098ec041815c5917dc84e48b INFO: done: 4.455 sec
2016-01-29T09:18:16.328Z 29738 TID-owzcf8mr0 ProjectCacheWorker JID-188f8cf9fbaeb679e58ff076 INFO: start
2016-01-29T09:18:22.660Z 29738 TID-owzcf8mr0 ProjectCacheWorker JID-188f8cf9fbaeb679e58ff076 INFO: done: 6.332 sec
2016-01-29T09:26:55.839Z 29738 TID-owzcf3d4w ProjectCacheWorker JID-c50925669b318a3f4dbf9a6b INFO: start
2016-01-29T09:26:56.220Z 29738 TID-owzcf3d4w ProjectCacheWorker JID-c50925669b318a3f4dbf9a6b INFO: done: 0.381 sec
2016-01-29T09:30:14.785Z 29738 TID-owzcdxxxk ProjectCacheWorker JID-5b03b503b7961e7c022ee051 INFO: start
2016-01-29T09:30:19.063Z 29738 TID-owzcdxxxk ProjectCacheWorker JID-5b03b503b7961e7c022ee051 INFO: done: 4.279 sec
2016-01-29T09:31:32.338Z 29738 TID-owzcf7kcs ProjectCacheWorker JID-4ec195fdc1e5b7d8dc38c2d4 INFO: start
2016-01-29T09:31:37.435Z 29738 TID-owzcf7kcs ProjectCacheWorker JID-4ec195fdc1e5b7d8dc38c2d4 INFO: done: 5.097 sec
2016-01-29T09:32:08.602Z 29738 TID-owzcf8mr0 ProjectCacheWorker JID-eabb88b9d26c96aba61c360b INFO: start
2016-01-29T09:32:08.850Z 29738 TID-owzcf8mr0 ProjectCacheWorker JID-eabb88b9d26c96aba61c360b INFO: done: 0.247 sec
2016-01-29T09:40:00.588Z 29738 TID-owzcf8mr0 ProjectCacheWorker JID-f0d3acf7087bee5da0831231 INFO: start
2016-01-29T09:40:06.895Z 29738 TID-owzcf8mr0 ProjectCacheWorker JID-f0d3acf7087bee5da0831231 INFO: done: 6.307 sec

      after upgrade

      2016-02-03T07:56:27.923Z 10072 TID-osqql6ntw ProjectCacheWorker JID-9ea7d02778732df9ed35363d INFO: fail: 2667.862 sec
2016-02-03T07:56:27.926Z 10072 TID-osqptbh2s ProjectCacheWorker JID-8ebaedeb8835efcf628362ba INFO: fail: 303.729 sec
2016-02-03T07:56:27.931Z 10072 TID-osqpyim44 ProjectCacheWorker JID-510bf490ae19b377e83b43b7 INFO: fail: 1981.233 sec
2016-02-03T08:49:30.290Z 27113 TID-otlyxc3uo ProjectCacheWorker JID-9ea7d02778732df9ed35363d INFO: fail: 3074.78 sec
2016-02-03T08:49:30.292Z 27113 TID-otlyx95og ProjectCacheWorker JID-510bf490ae19b377e83b43b7 INFO: fail: 3074.777 sec
    • username-removed-391823
      username-removed-391823 @Jakai ·

      I made a workaround:

      diff --git a/app/workers/project_cache_worker.rb b/app/workers/project_cache_worker.rb
index 55cb6af..1ebf00c 100644
--- a/app/workers/project_cache_worker.rb
+++ b/app/workers/project_cache_worker.rb
@@ -1,7 +1,7 @@
 class ProjectCacheWorker
   include Sidekiq::Worker
 
-  sidekiq_options queue: :default
+  sidekiq_options queue: :cacher
 
   def perform(project_id)
     project = Project.find(project_id)

      In turn cacher allocated separate sidekiq with one thread.

      Now, the basic tasks are performed quickly.

      But there are two questions:

      1. Why is queued second cache of the same project if you do not complete the first (you must either kill the old job replacing it with a new, or not to put in a new place)
      2. Why to cache all commit to the project? Now only one of our projects 146000 commit!
    • username-removed-289841 mentioned in issue #1546 (closed)

      mentioned in issue #1546 (closed)

    • Drew Blessing
      Drew Blessing @dblessing ·
      Maintainer

      Closing in favor of gitlab-org/gitlab-ce#14058

    • Drew Blessing Status changed to closed

      Status changed to closed

    • Drew Blessing mentioned in issue #14058 (closed)

      mentioned in issue #14058 (closed)

    • username-removed-128633 mentioned in merge request !3724 (merged)

      mentioned in merge request !3724 (merged)

    • Robert Speicher mentioned in commit 971662e6

      mentioned in commit 971662e6

    • Robert Speicher Mentioned in commit pfjason/gitlab-ce@971662e6

      Mentioned in commit pfjason/gitlab-ce@971662e6

    Please register or sign in to reply