The need for speed

Андрей Собчук andreis@jabber.ru ICQ UIN: 46466235
Алексей Баран alex_hs@mail.ru

При разработке программного обеспечения, программисты неоднократно встречаются с недостаточной производительностью программы. И как решить ту или иную проблему, разобраться иногда бывает сложно.

Понять, что же настраивать - алгоритм работы, параметры сборщика мусора, железо - поможет профайлер. Профайлер - это инструмент, который измеряет потребление ресурсов в определённом блоке кода. В дистрибутив VisualWorks Smalltalk входят профайлеры двух видов. TimeProfiler измеряет время работы программы, а его подвид, MultiTimeProfiler служит для измерения времени выполнения многопоточных программ. И AllocationProfiler, который служит для измерения объемов выделенной памяти. Чтобы получить доступ к профайлеру нужно загрузить парсел 'AT Profiling UI'.

Нередко можно встретится с мнением, что профайлер времени выполнения абсолютно бесполезен. Например, из-за того, что одна и та же программа на различных платформах может выполняться абсолютно по-разному. Но дело в том, что профайлер предназначен, в основном, для нахождения узких мест по факту существования проблемных участков кода.

Рассмотрим небольшой пример из жизни.

Для создания ежедневных билдов в чистый образ загружается код из STORE-репозитория . Репозиторий хранится в субд Oracle 8.0.5. В процессе роста базы росло и время загрузки кода из репозитория. Когда время загрузки достигло 15 минут, терпение закончилось. Пришло время взять профайлер. Для измерения времени загрузки проекта с названием "Oge" использовался такой кусок кода:

TimeProfiler profile:
        [| bundle |
        bundle :=
                Store.Bundle allBundles detect:
                        [:each | each name = 'Oge'].
        Store.Bundle
                loadWithName: bundle name
                version: bundle version].

Тут следует обратить внимание на один немаловажный момент. Smalltalk - это открытая система. То есть, во-первых, нам доступен весь исходный код всей системы (кроме виртуальной машины), во-вторых, мы можем заскриптовать выполнение любого действия, используя сам Smalltalk, как язык скриптования [системы]. Чуть выше и приведён пример такого скрипта.

Профайлер сразу указал на узкое место. 74% всего времени занимал доступ к БД. Несмотря на очевидность (а может именно из-за этой "очевидности"), на то что бы понять, что статистика по репозиторию не обновлялась ни разу , ушло некоторое время. После обновления статистики по всем индексам и таблицам STORE-репозитория время загрузки снизилось до 5 минут.

Хотя, по данным профайлера, доступ к базе теперь не был узким местом, тем не менее, он, всё еще, занимал значимое время. Выяснилось, что практически всё время отнимали запросы одного типа. Кстати, вы можете сами попробовать определить медленные запросы. Если вы используете VisualWorks 7.2, то, для этого, достаточно в новом (PDP) дебагере установить "Expression Variable Watch" где-нибудь в начале метода OracleSession>>executeExternal. В качестве "Watch Expression" можно записать:

^String new writeStream
		cr; 
		nextPutAll: Time now shortPrintString;
		nextPutAll: query;
		nextPutAll: bindValues displayString; cr;
		contents

И побежали запросы: Вот, например, один из них:

03:40:01  SELECT * FROM TW_MethodsView WHERE  packageRef = :primaryKey
               AND  className = :className AND  name = :name
IdentityDictionary (#primaryKey->121 #className->'Root.Smalltalk.Core.Array' #name->'+' )

IdentityDictionary содержит список всех переменных запроса (bind variables).

Этот подход не идеальный, так как можно выводить только начало времени выполнения запроса (концом я считаю полную выборку курсора в базе). Но если запросы идут подряд или база съедает львиную долю времени, то это хорошее решение. Вот так и нашелся самый медленный запрос:

SELECT
    *
FROM store.TW_MethodsAndSourcesView
WHERE  packageRef = "идентификатор пакета"

Запрос выполнялся медленно, потому что при его выполнении происходил полный перебор (full scan) таблицы TW_Methods. TW_Methods - это одна из самых больших таблиц репозитория. После добавления индекса по полю TW_Methods.packageRef время закачки проекта снизилось на 30%, до 210 сек.

Запускаем профайлер еще раз. Теперь профайлер показал, что проблема в том, что до 40% времени тратиться на обновление списков существующих методов в RefactoringBrowser-е. Да, да RefactoringBrowser был открыт. Закрываем его, и время загрузки уменьшается до 110 сек. Так что, при массовой загрузке закрывайте браузер.

Теперь, на первом плане - около 63% - запись в cha-файл. Cha-файл - это лог, в котором сохраняются все изменённые методы . В случае аварийного завершения среды, последние сделанные несохранённые изменения всегда можно восстановить из cha-файла. Так как, важно поскорее сбросить изменения на диск, то после каждого действия вызывается IOAccessor>>commit (в нашем случае PCDiskFileAccessor>>commit). Но, так как, при загрузке из STORE-репозитория весь код у нас есть в БД, то вызывать #commit после компиляции каждого метода излишне. Тут важно не вообще отключить вызов метода IOAccessor>>commit, а отключить вызов только при загрузке кода из репозитория. Используя тот же профайлер легко найти, место, в которое нужно внести изменения. Это метод класса Store.Method с селектором #loadAsNew. Итак, создаём копию метода ClassDescriptor>>compile:classified:notifying:environment:. Назовём новый метод #compileFromStore:classified:notifying:environment:. И изменим в тексте нового метода параметр safely: true на safely: false при посылке сообщения #storeMethodSource:class:category:safely:. Вызов нового метода нужно прописать в методе Store.Method>>loadAsNew.

После внесения этих изменений время загрузки уменьшилось до 55 сек!

Если у Вас загружен парсел DefaultPackageNamespace, то на последнем описанном шаге возникает два момента. Во-первых, модифицировать нужно метод #loadAsNewIn:, а не #loadAsNew. Во-вторых, после загрузки DefaultPackageNamespace появляется еще одно узкое место. Это метод:

includesClassNamed: aName 
	^( self classes 
collect: [ :class | class absoluteName ] )
		includes: aName asClassNameOnly

Переписав его несколько иначе получаем ускорение 20%:

includesClassNamed: aName 
	| className |
	className := aName asClassNameOnly.
	^( self classes 
anySatisfy: 
[ :class | class absoluteName = className ] )

Это изменение входит в пакет DefaultPackageNamespace начиная с версии 2.23.

Теперь профайлер показывает, что явно выраженного "съедателя" времени нет. Вот два лидера: доступ к БД занимает 17%, компиляция методов занимает 16,5%. Полученный результат является вполне удовлетворительным и трата усилий на дальнейшее увеличение производительности кажется бессмысленной.

Краткие выводы:

Основные тормоза - это, зачастую, ввод-вывод. В данном примере - доступ к БД, и к файловой системе. Так, даже после оптимизации доступ к БД занимает заметное время.

Определить где узкое место можно только при помощи профайлера. Если выяснить, что проблема в несобранной базой статистике, еще можно (при помощи инструментария администратора БД), то как определить без профайлера, что проблема в частом вызове IOAccessor>>commit я, например, не представляю.

Открытость системы - большое подспорье для разработчика. Под открытостью я понимаю не только доступность исходного кода, но и скриптуемость, и возможность изменить почти любой метод системы. Кстати, STORE поддерживает механизм "перекрытий" (overrides), который позволяет управлять подобными патчами системы. Суть "перекрытий" в том, что при выгрузке пакета, который перекрыл (пропатчил) уже существующие методы, методы восстанавливают своё предыдущее состояние.

Прочитать больше о методиках оптимизации работы со STORE можно тут:
http://wiki.cs.uiuc.edu/VisualWorks/Store+speedup+tips

О профайлерах в VW ST - в документации по Advanced Tools:
http://www.cincom.com/downloads/pdf/AdvancedTools.pdf

Полный список документации:
http://smalltalk.cincom.com/prodinformation/index.ssp?content=vwdocumentation