<p dir="auto">We're seeing unexpected behavior that seems contrary to Celery design - when more eta/countdown'd tasks are enqueued than the worker is configured to fetch, it will fetch those eta'd tasks, and increment the <code class="notranslate">prefetch_count</code> accordingly, but won't actually fetch any more tasks at that point.</p>
<p dir="auto">We're running Celery 3.1.7 with the RabbitMQ backend. (I'll try this with the latest version of Celery soon, but didn't see anything relevant in the changelogs.)</p>
<p dir="auto">Logs from our Celery worker reproducing this issue:</p>
<div class="snippet-clipboard-content notranslate position-relative overflow-auto" data-snippet-clipboard-copy-content="2015-07-27 16:01:23,768: WARNING/MainProcess] celery@celery_legacy.dev ready.
[2015-07-27 16:01:23,769: DEBUG/MainProcess] | Worker: Hub.register Pool...
[2015-07-27 16:01:23,769: DEBUG/MainProcess] celery@celery_sms.dev joined the party
[2015-07-27 16:01:23,770: DEBUG/MainProcess] celery@low_priority_low_mem.dev joined the party
[2015-07-27 16:01:23,771: INFO/MainProcess] Received task: ScheduledCommand.tq_execute[c1ce36c6-62f8-4698-bea0-ea806bd59329] eta:[2015-08-28 15:27:00+00:00]
[2015-07-27 16:01:23,775: INFO/MainProcess] Received task: ScheduledCommand.tq_execute[d51abfa0-dcbe-44bb-aff1-43de7eb66fda] eta:[2015-11-28 16:28:10+00:00]
[2015-07-27 16:01:23,778: INFO/MainProcess] Received task: ScheduledCommand.tq_execute[a15fa011-eb95-4de4-8d48-91782598a8bb] eta:[2015-09-24 15:29:00+00:00]
[2015-07-27 16:01:23,786: INFO/MainProcess] Received task: ScheduledCommand.tq_execute[e7aa6709-2da0-4d0e-a594-489a7c12c3d4] eta:[2015-09-24 15:30:10+00:00]
[2015-07-27 16:01:23,791: DEBUG/MainProcess] celery@high_priority_high_mem.dev joined the party
[2015-07-27 16:01:25,625: DEBUG/MainProcess] celery@low_priority_high_mem.dev joined the party
[2015-07-27 16:01:25,625: DEBUG/MainProcess] basic.qos: prefetch_count-&gt;8"><pre class="notranslate"><code class="notranslate">2015-07-27 16:01:23,768: WARNING/MainProcess] celery@celery_legacy.dev ready.
[2015-07-27 16:01:23,769: DEBUG/MainProcess] | Worker: Hub.register Pool...
[2015-07-27 16:01:23,769: DEBUG/MainProcess] celery@celery_sms.dev joined the party
[2015-07-27 16:01:23,770: DEBUG/MainProcess] celery@low_priority_low_mem.dev joined the party
[2015-07-27 16:01:23,771: INFO/MainProcess] Received task: ScheduledCommand.tq_execute[c1ce36c6-62f8-4698-bea0-ea806bd59329] eta:[2015-08-28 15:27:00+00:00]
[2015-07-27 16:01:23,775: INFO/MainProcess] Received task: ScheduledCommand.tq_execute[d51abfa0-dcbe-44bb-aff1-43de7eb66fda] eta:[2015-11-28 16:28:10+00:00]
[2015-07-27 16:01:23,778: INFO/MainProcess] Received task: ScheduledCommand.tq_execute[a15fa011-eb95-4de4-8d48-91782598a8bb] eta:[2015-09-24 15:29:00+00:00]
[2015-07-27 16:01:23,786: INFO/MainProcess] Received task: ScheduledCommand.tq_execute[e7aa6709-2da0-4d0e-a594-489a7c12c3d4] eta:[2015-09-24 15:30:10+00:00]
[2015-07-27 16:01:23,791: DEBUG/MainProcess] celery@high_priority_high_mem.dev joined the party
[2015-07-27 16:01:25,625: DEBUG/MainProcess] celery@low_priority_high_mem.dev joined the party
[2015-07-27 16:01:25,625: DEBUG/MainProcess] basic.qos: prefetch_count-&gt;8
</code></pre></div>
<p dir="auto">And then never any <code class="notranslate">Received task</code>s beyond this.</p>
<p dir="auto">The params we're using:<br>
<code class="notranslate">/home/vagrant/venv/app_tophat/bin/python /vagrant/THM/manage.py celery worker -E -c 1 --maxtasksperchild=100 -n celery_legacy.%%h -Ofair --loglevel=DEBUG</code></p>
<p dir="auto">Screenshot of RabbitMQ admin showing the 4 fetched tasks with many more tasks waiting: <a href="https://www.dropbox.com/s/rkcaomg8kqga937/Screenshot%202015-07-27%2012.07.42.png?dl=0" rel="nofollow">https://www.dropbox.com/s/rkcaomg8kqga937/Screenshot%202015-07-27%2012.07.42.png?dl=0</a> This is after <code class="notranslate">prefetch_count-&gt;8</code> in the Celery logs.</p>
<p dir="auto">Please let me know if any other details would help here. Thanks.</p>
<p dir="auto">I'm running into an issue where some of my worker processes will stop processing new tasks, causing them to pile up on the queue server. Left alone it will sometimes clear, and sometimes grow to impact all workers, effectively blocking processing.</p>
<p dir="auto">However, if I issue a management command, such as "celery inspect scheduled" it will cause workers to resume operation immediately. Although sometimes only briefly before halting again.</p>
<p dir="auto"><strong>The setup:</strong></p>
<ul dir="auto">
<li>celery 3.1.9</li>
<li>kombu 3.0.12</li>
<li>amqp 1.4.4</li>
<li>RabbitMQ (3.1.3) / ampq for all communication and results.</li>
<li>Mid-sized config: 7 worker nodes, 13 queues for service differentiation, and about 40 total worker processes per worker node.</li>
<li>Nodes are running the prefork worker, with 1-8 processes per queue, depending on the queue.</li>
<li>CELERYD_PREFETCH_MULTIPLIER = 1</li>
<li>CELERY_ACKS_LATE = True</li>
<li>CELERYD_MAX_TASKS_PER_CHILD = 16</li>
<li>I'm using -Ofair, as even within a given queue some tasks may take very different times to execute. Overall task per second throughput has never been an issue.</li>
<li>Example command line:
<blockquote>
<p dir="auto">python /home/celeryworker/web/manage.py celery worker --without-gossip --loglevel=INFO -Q transcode -Ofair -c 2 -n celery-worker-7-prod_transcode</p>
</blockquote>
</li>
</ul>
<p dir="auto">I believe it may have to do with scheduled tasks, as everytime I've been able to catch it in action there have been a fairly large number of tasks waiting for a countdown to expire. On the order of the total number of task slots available for that queue (I'm counting 7 workers, listening with -c4 on a queue, and a prefetch multiplier of 1 to be 28 task slots)</p>
<p dir="auto">I have not been able to confirm if the rabbitmq channel prefetch value is being correctly incremented when this issue is occurring and there are scheduled tasks; though it is being correctly incremented by scheduled tasks during normal operation. (I'll double check that the next time this recurs.)</p>
<p dir="auto">In general the above config is doing exactly what I expect; one task per worker process, multiple tasks per node, and the next task coming out of the queue as soon as any given worker is no longer busy. It's only occasionally that things go off the rails and, one node at a time, new tasks will no longer be executed. (Other processes listening on other queues on that node will continue to work, or fail, independently.)</p>