CC: @mattia any ideas?

Probibly related to the 'large update' ?

but not sure why it wouldn't be processing...

I spent some time investigating this and I'm no wiser. Here is the log from message processing:

2025-12-08 16:10:11,121 INFO [fedora_messaging.twisted.consumer][MainThread] Consuming message from topic org.fedoraproject.stg.buildsys.tag (message id 1fb5b9ec-a958-448d-a258-abf172164c2b)
2025-12-08 16:10:11,122 INFO [bodhi][PoolThread-twisted.internet.reactor-0] Received message from fedora-messaging with topic: org.fedoraproject.stg.buildsys.tag
2025-12-08 16:10:11,122 INFO [bodhi][PoolThread-twisted.internet.reactor-0] vim-commentary-1.3-19.fc43 tagged into f43-signing-pending
2025-12-08 16:10:49,937 INFO [bodhi][PoolThread-twisted.internet.reactor-0] Tag is not testing side tag, skipping
2025-12-08 16:10:50,148 INFO [fedora_messaging.twisted.consumer][MainThread] Successfully consumed message from topic org.fedoraproject.stg.buildsys.tag (message id 1fb5b9ec-a958-448d-a258-abf172164c2b)

I noticed that the database db01.stg was under heavy load, so I bumped the number of vCPUs, but this doesn't seem to be related. I tried to enable debug output as well, but it didn't show anything new.

The processing is done by this code and I don't see anything that would take 40 seconds in there

        log.info("%s tagged into %s" % (build_nvr, tag))
        with self.db_factory() as dbsession:
            build = Build.get(build_nvr)
            if not build:
                log.info("Build was not submitted, skipping")
                return
            if not build.release:
                log.info('Build is not assigned to release, skipping')
                return
            if build.update \
                    and build.update.from_tag \
                    and not build.update.release.composed_by_bodhi:
                koji_testing_tag = build.release.get_pending_testing_side_tag(build.update.from_tag)
                if tag != koji_testing_tag:
                    log.info("Tag is not testing side tag, skipping")
                    return

So I ran strace on the thread processing the message and here is what is happening during that 40 seconds:

1. SELECT send to db01.stg - 6 seconds
   11:33:20 sendto(12, "Q\0\0\21\362SELECT updates.autokarma AS"..., 4595, MSG_NOSIGNAL, NULL, 0) = 4595
2. Processing the response - 17 seconds
   11:33:26 recvfrom(12, "T\0\0\r\314\0[updates_autokarma\0\0\207\201T\0\30\0"..., 16384, 0, NULL, NULL) = 12236
3. mmap calls - 15 seconds
   11:33:43 mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f9a80089000
4. None strace call - 7 seconds
5. munmap calls - 2 seconds
   11:34:05 munmap(0x7f98aac00000, 1048576) = 0

Not sure why processing the db response is taking 17 seconds (the thread is using ~100% of CPU during that), mmap makes sense as the thread has 10 GB of allocated memory (but I'm not sure why it allocates that much).

It seems that the SELECT that is send to db01.stg returns ~700 000 rows. I'm not surprised the processing of the query response takes 17 seconds.

And this is the update that is causing it on staging https://bodhi.stg.fedoraproject.org/updates/FEDORA-2025-3d83cfd7e4

I assume once we get through this update, the processing should be done much quicker. I will for now change the number of consumers to what looks reasonable and see if it starts to be quicker once this big update is processed.

Yes, that was a test from https://forge.fedoraproject.org/releng/tickets/issues/12869

possibly we want to share this info there.

I wonder, could we do any index in the db to make those queries faster?

CC: @mattia

The query is fast, it takes only few seconds, but processing through 700 000 rows takes consumer a lot of time.

In the meantime I increased the number of consumers to 15 and the queue started to slowly being processed, around 20 000 messages processed in the last few hours.

Total messages in the queue at 12.12.2025 8:27 UTC - 1,198,745

We also discussed some optimization of bodhi SQLAlchemy queries with @abompard on standup and he had some ideas. As the amount of data retrieved is much more than we need.

Total messages in the queue at 15.12.2025 10:13 UTC - 1,130,723

The queue is slowly being consumed.

Unfortunately the number of consumers got reset to 1 and the queue started growing again, but hopefully this PR could help.

Currently running 20 consumers.

Total messages in the queue at 17.12.2025 8:29 - 1,171,790

For some reason the queue is rising again :/. According to rabbitmq UI there is a lot of redelivered messages, so maybe the consumers have trouble processing them. Will check it out.

The bottleneck was db01.stg, so I added more vCPUs (16) to handle all the bodhi consumers as the messages were timing out during db queries.

Total messages in the queue at 17.12.2025 15:42 UTC - 1,148,940

The queue is being consumed again :-)

Total messages in the queue at 18.12.2025 7:34 UTC - 1,107,069

It seems that the SELECT that is send to db01.stg returns ~700 000 rows. I'm not surprised the processing of the query response takes 17 seconds.

And this is the update that is causing it on staging https://bodhi.stg.fedoraproject.org/updates/FEDORA-2025-3d83cfd7e4

I assume once we get through this update, the processing should be done much quicker. I will for now change the number of consumers to what looks reasonable and see if it starts to be quicker once this big update is processed.

A Build.get() select should return only one row, I assume it returns 700k rows because it pulls in every other object associated to that build (update / other builds / comments / test cases / etc...).
I have tried in the past to look at optimizing results returned from queries, unfortunately I'm not expert on SQL or sqlalchemy. Perhaps there's a way to better optimize bodhi db / sqlalchemy objects, but I don't know how.

A Build.get() select should return only one row, I assume it returns 700k rows because it pulls in every other object associated to that build (update / other builds / comments / test cases / etc...).
I have tried in the past to look at optimizing results returned from queries, unfortunately I'm not expert on SQL or sqlalchemy. Perhaps there's a way to better optimize bodhi db / sqlalchemy objects, but I don't know how.

@abompard should be able to help with that. We already discussed it in our morning standup.

Total messages in the queue at 05.01.2026 8:19 UTC - 277,192

So the queue is almost processed, I will lower the amount of consumers when we reach 0. Hopefully it will not raise again after that.

Total messages in the queue at 07.01.2026 8:37 - 204,957

Only few more days and the queue will be processed.

Total messages in the queue at 12.01.2026 8:30 - 856

It seems that I will be able to close this ticket today :-)

The queue is now reaching 0, so I lowered the number of consumers to 10 and will monitor the situation for now.

Will keep this ticket open till I find a correct number of consumers that can keep up with the amount of messages published.

After some experimenting I found out that number of consumers that keep up with the publishers is 10.

I will update the ansible to reflect that.

This is resolved in https://pagure.io/fedora-infra/ansible/pull-request/3045

So I'm closing this as fixed.