Pungi Performance, Profiling?

Sep 01, 2017 | categories: factory2, fedora View Comments

Happy Flockery!

This might not be new to others, but I wanted to identify which parts of the compose process were slow, so I wrote a little script. If you didn't know, our compose process is broken up into phases some of which run in serial, others of which run in parallel. The composes take a long time, and speeding them up would be great.

#!/usr/bin/env python3
""" Usage:  python3 analyze-compose.py Fedora-27-20170901.n.1 """

import operator
import sys

import requests
import dogpile.cache

cache = dogpile.cache.make_region().configure(

# Fedora-27-20170901.n.1
target = sys.argv[-1]

def get_messages(target):
        url = 'https://apps.fedoraproject.org/datagrepper/raw'
        params = dict(
        print("Querying %r %r" % (url, params))
        response = requests.get(url, params=params)
        return [m for m in response.json()['raw_messages']]

if __name__ == '__main__':
        print('Analyzing compose %r' % target)
        messages = get_messages(target)
        starts, stops = {}, {}
        for message in messages:
                if message['topic'].endswith('compose.status.change'):
                if message['topic'].endswith('compose.phase.start'):
                        starts[message['msg']['phase_name']] = message['timestamp']
                if message['topic'].endswith('compose.phase.stop'):
                        stops[message['msg']['phase_name']] = message['timestamp']

        deltas = {}
        for phase in starts:
                if phase not in stops:
                deltas[phase] = stops[phase] - starts[phase]

        deltas = list(deltas.items())
        deltas.sort(key=operator.itemgetter(1), reverse=True)
        for phase, delta in deltas:
                print("{0:20} {1:.2f} hours".format(phase, delta / 60.0 / 60.0))

This script prints out stats about all of the phases. Take a look at this compose from a few days ago and focus in on just one phase:

❯ ./analyze-compose.py Fedora-27-20170830.n.0
Analyzing compose 'Fedora-27-20170830.n.0'
createrepo           8.50 hours

That createrepo phase is gigantic!

After one or two patches we were able to get it down a little tighter the next day:

./analyze-compose.py Fedora-27-20170901.n.1
Analyzing compose 'Fedora-27-20170901.n.1'
createrepo           0.33 hours

createrepo phase -- greatly improved.

The next one that jumps out at me is the pkgset phase. What's going on there?

I'm not sure yet but have posted a patch introducing more logging so we can get a feel for it.

View Comments
blog comments powered by Disqus