Вчора вбив купу часу на профайлінг. Хто програміст, той зрозуміє. Для інших - це процес отримання кількісних характеристик процесу виконання кожної функції програми. Я зазвичай використовую профайлер для отримання кумулятивного часу: в деяких випадках це дає можливість швидко визначити функцію, що з'їдає більшість часу виконання програми.
В мене є бібліотека, надбудова над libjpeg, для розпізнавання капчей Yahoo. На основі цієї бібліотеки побудовані багатопоточний сервер та тестер для перевірки відсотку розпізнавання та швидкості роботи бібліотеки. Тестер також багатопоточний.
Яха капчу періодично змінює (який сюрприз! :), тож алгоритми бібліотеки теж доводиться міняти або підналаштовувати під нові капчі. Взяли хлопця під цю задачу товариша. Я передав йому весь codebase, пояснив що до чого і він пішов працювати. Першочергове завдання, що стояло перед ним - це підвищити відсоток розпізнаних капч, тому на швидкість вирішили, для початку, не звертати уваги.
Пару днів тому він ніби отримав якийсь результат і я вирішив його перевірити. В мене є база з приблизно 3*105 розпізнаних капчей, яку я використовую для перевірки швидкості та відсотка перед переводом робочої версії в продакшн. Забрав останню версію коду, запустив: мої слова щодо "не звертати уваги на швидкість" товариш зрозумів більш ніж буквально. Замість приблизно 0.05 сек/капчу я бачу майже пів-секунди. І це - на 8-миголовому Xeon'і при повному завантаженні всіх ядер.
Відкриваю іще один термінал на ноуті, hg clone ssh://server/ocr && cd ocr && make. Запускаю - 10 сек/капча! Товариш каже, що в нього на ноуті, теж макбук, та сама картинка, при чому цей-же тестер запущений під віндою, що крутиться в емуляторі, дає 2.5 секунди!!!. Жуть. Але при наступних запусках тестера у себе помічаю деталь: індикатори CPU на панелі показують, що система з'їдає втричі більше процесора, ніж user level. Все стає більш-меньш зрозуміло: тепер треба тільки знайти місце, де в алгоритм розпізнавання прокрався syscall. Очима це довго, тож...
Привіт, профайлер: make clean PROF=1 all && ./tester 2 && gprof tester. Красота! От тільки no time accumulated: в колонці self seconds - нулі стоять. А так все інше - пораховано нормально. Хм, думаю. І лізу збираю профільованую версію тестера на сервері (FreeBSD 7.1-PRERELEASE amd64). Запускаю - зовсім круто: tester вішається. Збираю debug-версію, щоби запустити і пристрелити підвисший процес kill -6 та отримати корку. Фігвам, тільки kill -9.
Лізу в інет: gprof сам по собі не вміє профілювати багатопоточні програми. Йому потрібна допомога. Дивлюсь в код тестера і розумію, що мені швидше буде відірвати в мухи ніжки від нього pthreads. Відриваю, запускаю...
Є одна функція, що при розпізнаванні кожної капчі викликається трохи меньше 1000-і разів. В основному вона виконує купу бітових операцій. Так от товариш примудрився в цю функу, крім іншого, додати створення тимчасового об'єкта в конструкторі/деструкторі якого відповідно new/delete, в середину циклу!!! Сцуко... Таких сильних емоцій в мене вже давно не було. Чи треба казати, що свої останні кілька проектів він писав на Джаві?
P.S.: Схоже, віжуалстудійні new/delete працюють в кілька разів швидше за ті, що йдуть в libstdc++ від GCC. Якщо хтось має конкретну інфу з цього приводу - поділиться, будь-ласка.
P.P.S: навіть після фікса цього бага нова версія працює на 30% повільніше та дає меньший відсоток. Швидкість - хрін з нею, це можна побустити, а от відсоток - це неприємно.
