История одной оптимизации

Речь пойдет о unity-launcher-editor — редакторе элементов и контекстного меню (quicklists) панели Unity для Ubuntu. Редактор написан с использованием связки python+gtk, с обязанностями справляется сносно. Раздражает время запуска: до появления главного окна проходит непозволительно много времени.

Можно пенять на Python, Unity или разработчиков, а можно попробовать разобраться в чем же дело, проект ведь с открытым кодом. Во время «исследования» делал пометки, которые и легли в основу этой заметки. Любопытных прошу под кат.


Шаг 1

Смотрим под капот с помощью стандартного профайлера: python -m cProfile -s cumulative ule
Результат:
 211267 function calls (203946 primitive calls) in 49.801 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.002    0.002   49.801   49.801 ule:19(<module>)
        1    0.000    0.000   49.415   49.415 ule:29(main)
4598/4584    0.007    0.000   49.224    0.011 types.py:46(function)
4599/4585   49.208    0.011   49.218    0.011 {method 'invoke' of 'gi.CallableInfo' objects}
        1    0.001    0.001   46.013   46.013 app.py:47(__init__)
        1    0.001    0.001   45.945   45.945 app.py:230(__populate)
       24    0.007    0.000   45.936    1.914 app.py:211(new_from_file)
       45    0.002    0.000   45.454    1.010 iconmanager.py:93(get_icon)
       45    0.014    0.000    0.408    0.009 iconmanager.py:29(__init__)
        1    0.000    0.000    0.343    0.343 iconmanager.py:71(get_icon_with_file)
        1    0.000    0.000    0.343    0.343 iconmanager.py:60(get_icon_with_name)
        ................................................................................

Ого! 50 секунд на запуск небольшого приложения.

Шаг 2

Судя по всему, что-то неладное происходит в модуле app.py:
app.py:230(__populate) — вызывается один раз, на вызов тратится 46 секунд
app.py:211(new_from_file) — вызывается 24 раза, примерно 2 секунды на каждый вызов
iconmanager.py:93(get_icon) — вызывается 45 раз, примерно 1 секунда на вызов

Беглый просмотр кода подтверждает догадку, что функция __populate вызывает new_form_file, которая вызывает get_icon.

Начнем с __populate:
def __populate(self):
        self.launcher_view.clear_list();
        self.unity = self.gsettings.get_value('favorites')
        log.info(self.unity)
        for menu_item in self.unity:
            self.new_from_file(menu_item, False)
        self.launcher_view.connect('selection-changed', self.__launcher_view_row_change)
        #make first row active
        self.launcher_view.set_selected_iter(0)

Видимо в панели находятся 24 элемента для каждого из которых вызывается new_from_file(menu_item, False)
def new_from_file(self, filename, selected=True):
    try:
        file_path = normalize_path(filename, True)
        obj = DesktopParser(file_path)
        sname = obj.get('Name',locale=LOCALE)
        desc = obj.get('Comment',locale=LOCALE)
        icon = obj.get('Icon')
        pix = IconManager().get_icon(ThemedIcon('image-missing'),32)
        if icon:
            if icon.rfind('.') != -1:
                pix = IconManager().get_icon(FileIcon(File(icon)),32)
            else:
                pix = IconManager().get_icon(ThemedIcon(icon),32)

            data = (pix, '%s' % sname, obj, sname.upper(), file_path)
        return self.launcher_view.add_row(data,selected)
    except:
        return None

Первое, что бросается в глаза, это строка:
pix = IconManager().get_icon(ThemedIcon('image-missing'),32)

Иконка типа image-missing одна для всех, поэтому нет необходимости каждый раз ее искать. Сделаем ее атрибутом класса. В методе __init__ перед вызовом __populate добавляем:
self.pix_missing = IconManager().get_icon(ThemedIcon('image-missing'), 32)

и заменяем соответствующую строку в new_from_file на pix = self.pix_missing

Посмотрим как изменилось время запуска: python -m cProfile -s cumulative ule
Результат2:
194247 function calls (186926 primitive calls) in 8.863 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.007    0.007    8.864    8.864 ule:19(<module>)
        1    0.000    0.000    8.363    8.363 ule:29(main)
2988/2974    0.008    0.000    8.189    0.003 types.py:46(function)
2989/2975    8.176    0.003    8.182    0.003 {method 'invoke' of 'gi.CallableInfo' objects}
        1    0.001    0.001    6.817    6.817 app.py:48(__init__)
        1    0.000    0.000    6.704    6.704 app.py:244(__populate)
       24    0.003    0.000    6.697    0.279 app.py:224(new_from_file)
       22    0.001    0.000    6.489    0.295 iconmanager.py:93(get_icon)
        1    0.004    0.004    0.248    0.248 app.py:18(<module>)

Результат несколько неожиданный, поэтому перепроверил(с изменениями и без): стабильно минус 35-40 секунд.
9 секунд гораздо меньше раздражают, но тем не менее раздражают.
Попробуем еще улучшить.

Шаг 3

IconManager каждый раз создается как отдельный объект (и всегда без аргументов), сделаем его атрибутом класса.

В __init__ добавляем:
self.icon_manager = IconManager()

Все вхождения IconManager() заменяем на self.icon_manager.

Проверяем: python -m cProfile -s cumulative ule
Результат3:
178980 function calls (171659 primitive calls) in 1.949 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.001    0.001    1.949    1.949 ule:19(<module>)
        1    0.000    0.000    1.449    1.449 ule:29(main)
1560/1546    0.004    0.000    1.314    0.001 types.py:46(function)
1561/1547    1.304    0.001    1.310    0.001 {method 'invoke' of 'gi.CallableInfo' objects}
        1    0.001    0.001    0.285    0.285 app.py:48(__init__)
        1    0.004    0.004    0.252    0.252 app.py:18(<module>)
   206/45    0.005    0.000    0.191    0.004 {__import__}
      9/5    0.000    0.000    0.187    0.037 importer.py:56(load_module)
      9/5    0.000    0.000    0.186    0.037 module.py:239(_load)
        1    0.002    0.002    0.174    0.174 pkg_resources.py:14(<module>)
        1    0.000    0.000    0.159    0.159 app.py:245(__populate)
 2617/377    0.011    0.000    0.159    0.000 {map}
       24    0.003    0.000    0.153    0.006 app.py:225(new_from_file)
        1    0.004    0.004    0.146    0.146 Gtk.py:22(<module>)
  159/132    0.012    0.000    0.132    0.001 module.py:111(__getattr__)
        1    0.000    0.000    0.107    0.107 pkg_resources.py:698(subscribe)
      102    0.000    0.000    0.107    0.001 pkg_resources.py:2835(<lambda>)
      102    0.001    0.000    0.106    0.001 pkg_resources.py:2256(activate)
       22    0.001    0.000    0.098    0.004 iconmanager.py:93(get_icon)


Окно появляется практически мгновенно. Общее время почти две секунды, однако оно включает также закрытие окна с помощью мыши. Лучше ориентироваться на строку 1 0.001 0.001 0.285 0.285 app.py:48(__init__): время выполнения изменилось с 6.8 секунд в предыдущем замере до 0.3 в последнем.
На этом можно и остановиться.

Итог

Небольшие изменения привели к уменьшению времени запуска приложения с 46 секунд до 0.3 (для app.py:48(__init__) ).
Изменения отправлены разработчикам.
Открытый код не идеален, но каждый может его улучшить потратив совсем немного своего времени.

Изменения в виде diff-файла
=== modified file 'unitylaunchereditor/dialogs/app.py'
--- unitylaunchereditor/dialogs/app.py	2011-11-28 17:12:07 +0000
+++ unitylaunchereditor/dialogs/app.py	2013-02-26 16:47:52 +0000
@@ -71,6 +71,8 @@
         #bottom window buttons
         self.__create_bottom_box(main_box)
         
+        self.icon_manager = IconManager()
+        self.pix_missing = self.icon_manager.get_icon(ThemedIcon('image-missing'),32)
         self.__populate()
         self.connect('delete-event', Gtk.main_quit)
         
@@ -198,12 +200,12 @@
         sname = info['Name']
         desc = info['Comment']
         icon = info['Icon']
-        pix = IconManager().get_icon(ThemedIcon('image-missing'),32)
+        pix = self.pix_missing
         if icon:
             if icon.rfind('.') != -1:
-                pix = IconManager().get_icon(FileIcon(File(icon)),32)
+                pix = self.icon_manager.get_icon(FileIcon(File(icon)),32)
             else:
-                pix = IconManager().get_icon(ThemedIcon(icon),32)
+                pix = self.icon_manager.get_icon(ThemedIcon(icon),32)
         data = (pix, '%s' % sname, obj, sname.upper(), file_path)
         
         return self.launcher_view.add_row(data,True)
@@ -215,12 +217,12 @@
             sname = obj.get('Name',locale=LOCALE)
             desc = obj.get('Comment',locale=LOCALE)
             icon = obj.get('Icon')
-            pix = IconManager().get_icon(ThemedIcon('image-missing'),32)
+            pix = self.pix_missing
             if icon:
                 if icon.rfind('.') != -1:
-                    pix = IconManager().get_icon(FileIcon(File(icon)),32)
+                    pix = self.icon_manager.get_icon(FileIcon(File(icon)),32)
                 else:
-                    pix = IconManager().get_icon(ThemedIcon(icon),32)
+                    pix = self.icon_manager.get_icon(ThemedIcon(icon),32)
             
                 data = (pix, '%s' % sname, obj, sname.upper(), file_path)
             return self.launcher_view.add_row(data,selected)
@@ -325,12 +327,12 @@
                     self.launcher_view.set_value(obj['Name'], self.launcher_view.COLUMN_NAME)
                     self.launcher_view.set_value(obj['Name'].upper(), self.launcher_view.COLUMN_NAME_UPPER)
                     icon = obj['Icon']
-                    pix = IconManager().get_icon(ThemedIcon('image-missing'),32)
+                    pix = self.pix_missing
                     if icon:
                         if icon.rfind('.') != -1:
-                            pix = IconManager().get_icon(FileIcon(File(icon)),32)
+                            pix = self.icon_manager.get_icon(FileIcon(File(icon)),32)
                         else:
-                            pix = IconManager().get_icon(ThemedIcon(icon),32)
+                            pix = self.icon_manager.get_icon(ThemedIcon(icon),32)
                         self.launcher_view.set_value(pix, self.launcher_view.COLUMN_ICON)
                         
         if button_type == TOOLBUTTON_REMOVE:



UPD:
А слона то я и не заметил

Невыясненными остались два вопроса:
  • слишком долгий запуск(50 секунд) для двух десятков элементов меню;
  • неожиданное уменьшение времени загрузки(в 5 раз) после первой же оптимизации.

Косвенным виновником стал объект self.icontheme = Gtk.IconTheme.get_default().
В конструкторе IconManager-а расширяется список путей, в которых происходит поиск иконок. Все изменения сохраняются на время выполнения приложения, хотя Gtk.IconTheme.get_default() и не является Singleton-ом. В моем случае каждая инициализация IconManager-а увеличивает список на 67 элементов, что приводит к изменению его размера примерно в 300 раз (с 10 до 2985).
Конструктор класса IconManager
def __init__(self):
        self.icontheme = Gtk.IconTheme.get_default()
        # add the humanity icon theme to the iconpath, as not all icon 
        # themes contain all the icons we need
        # this *shouldn't* lead to any performance regressions
        path = '/usr/share/icons/Humanity'
        if exists(path):
            for subpath in listdir(path):
                subpath = join(path, subpath)
                if isdir(subpath):
                    for subsubpath in listdir(subpath):
                        subsubpath = join(subpath, subsubpath)
                        if isdir(subsubpath):
                            self.icontheme.append_search_path(subsubpath)


Изменив несколько строк в конструкторе можно уменьшить время запуска до 0.8 секунды(без предыдущих оптимизаций) и 0.6(с оптимизациями). Предыдущие изменения стали «косметическими».
Изменения в виде diff-файла
=== modified file 'unitylaunchereditor/core/iconmanager.py'
--- unitylaunchereditor/core/iconmanager.py	2011-11-26 14:36:43 +0000
+++ unitylaunchereditor/core/iconmanager.py	2013-02-28 19:13:42 +0000
@@ -28,6 +28,7 @@
 class IconManager:
     def __init__(self):
         self.icontheme = Gtk.IconTheme.get_default()
+        search_paths = self.icontheme.get_search_path()
         # add the humanity icon theme to the iconpath, as not all icon 
         # themes contain all the icons we need
         # this *shouldn't* lead to any performance regressions
@@ -38,7 +39,7 @@
                 if isdir(subpath):
                     for subsubpath in listdir(subpath):
                         subsubpath = join(subpath, subsubpath)
-                        if isdir(subsubpath):
+                        if isdir(subsubpath) and subsubpath not in search_paths:
                             self.icontheme.append_search_path(subsubpath)
         
     def get_icon_with_type(self,filepath, size=24):


Bug создан, patch отправлен.
Метки:
Поделиться публикацией
Реклама помогает поддерживать и развивать наши сервисы

Подробнее
Реклама
Комментарии 15
  • НЛО прилетело и опубликовало эту надпись здесь
    • +8
      Они может на ssd с ram 16 gb
      Где все в кэшах :)
      • 0
        может зависит от кол-во иконок, объектов, с которыми работает программа (что зависит от пользовательских настроек)? наверное, тестировали на меньшем количестве, и этих вызовов в цикле было меньше… Или да, — суперпроизводительные компьютеры у разрабов :-)
        • 0
          Натыкался на это, когда репортил перформанс-проблемы GPU Canvas в Chrome.
          «Мы не можем повторить ваш репорт, потому что у нас нигде нет такого старого GPU, поэтому мы его просто заблеклистим».
          ATI Radeon HD 4225.
      • –6
        Почему тут еще до сих пор нет холивара про Unity и $любой_ваш_WM/DE?
        • +7
          Школьники спать ушли?
        • +3
          Пожалуйста, отправьте им свой дифф, в виде баги.
        • 0
          Тоже, что ли, взяться за допиливание nm-applet — безмерно досаждают постоянные краши, «потери» вложенных менюшек (когда оные становятся пустыми), да и просто убогое поведение при коннектах.
          • 0
            Займитесь займитесь. Но учтите — писать GUI на C это занятие не для слабонервных.
          • 0
            Увеличение производительности в 150 раз при изменении 11 строк кода. Неплохо!
            • +2
              Оптимизация крутая. Но вот не пойму откуда такие дикие цифры берутся… Если в панели всего 24 изображения, то как действие «найти картинку 24 раза» может занимать 40 секунд?! То же самое касается и менеджера.
              • +2
                Дополнил статью описанием истинной причины такого странного поведения.
              • НЛО прилетело и опубликовало эту надпись здесь

                Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.