Бэкапил историю сообщений из Skype самописной утилиткой, год назад она работала отлично, а теперь стала люто тормозить. Это неприемлемо, тк. в том числе ради скорости экспорта она и была написана, поэтому полез в профайлер. По итогам узнал всякое и получил множественные просветления. Оказывается, breakpoint на функцию в подгруженной системной DLL ставить приходится с подвывертом, а не просто по имени, но таки можно и нетяжело. Оказывается, Skype API написан местами зверски криво, отчего и тормозища. Оказывается, чужие бинарники иногда можно очень легко подхачить и подоптимизить (слава MS Research!). Оказывается, профайлер может сильно врать, а не просто слегка подбрехивать. Ключевые слова для нетерпеливых: C++, VS, CodeAnalyst, Skype COM API, MS Research, Detours, SQLite; а для всех остальных подробности под катом.
Вкратце, предыстория. Года полтора назад захотел экспортировать логи скайпа в удобном лично мне текстовом формате (почти cut/paste из чата, с махонькими улучшениями). Все найденные утилиты для экспорта чем-либо не устраивали. Либо зверски тормозили (потому как в логах чуть менее 300 контактов и чуть более 360 000 сообщений); либо писали логи в неудобном формате; либо все эти беды сразу; либо тупо не работали, и т.п. Решил написать свое, получилось. Сначала попробовал биндинги Skype API к Python, оказалось медленно. Потом попробовал Skype4COM и C++, оказалось куда быстрее. В итоге получилась довольно быстрая утилитка для экспорта логов. Хардкорная, консольная и на C++, понятное дело.
Очередной раз про бэкапы вспомнил пару недель назад, запустил проверенную утилитку и… понял, что конца не дождусь. Экспорт, который раньше занимал несколько минут, за полчаса продвинулся где-то на 10%, итого ETA получался около 5 часов. Неприемлемо долго. В чем дело?!
Слегка правим утилитку, ограничиваем количество экспортируемых чатов (как я понимаю, скайп отдельные сессии общения с одними и теми же контактами зачем-то разбивает на отдельные т.н. чаты, IChat), засекаем базовое время. Затем запускаем профайлер, благо, CodeAnalyst теперь встраивается в Visual Studio и запускается буквально в 2-3 клика. И внимательно смотрим на результаты.
Профайл выглядит кучеряво, 81% времени процесса жрет kernelbase.dll, еще 12% skype4com.dll, собственно программу даже не видать. Измена! Тормозит не мой код (что легко править), а какой-то сторонний. Но какой именно?
Уверенно побеждают функции InternalLcidToName, LCMapStringEx, NlsValidateLocale. Кто все эти люди? Я ничего подобного из своего кода не вызываю. Значит, вызываю не я. Значит, нужно узнать, откуда они вызываются, и тогда авось станет ясно, почему, и что с этим можно поделать. Надо поставить breakpoint на топовую функцию InternalLcidToName, посмотреть стек. Упс, проблемка. Тупо по названию функции бряка не ставится. Как быть?
Вариантов я знаю два, а есть небось еще больше. Во1х, раз функция вся такая в профайле топовая, то просто несколько раз случайно прервав исполнение мы обязательно в нее попадем. Во2х, слегка погуглив, удается найти магическую строчку {,,KernelBase.dll}@InternalLcidToName@8 — оказывается, нужный символ называется именно так, с собаками и циферкой. Забегая чутка вперед, циферки всегда кратны 4, и вообще сильно смахивают на размер стека, а вместо ведущей собаки для «публичных» символов типично подчеркивание. Заметив это, точные правила mangling уже сильно дольше искать, изучать и применять, чем перебрать пару-тройку вариантов (собака/подчеркивание, 4/8/12/16...), а то и попасть в какой-нибудь _GetStringTypeW@16 с первого же выстрела. Ну, вернувшись из недалекого будушего таки к насущному InternalLcidToName, неоднократно потыкав F5 и набрав статистику, становится видно две занятные вещи. Первое, что стек большинства вызовов выглядит вот так.
Второе, что многократно исполняемый код выглядит вот так. При этом всегда ходит по одному и тому же codepath.
Те. все наши три топовые функции из профайла сводятся на самом деле к одной, _LCMapStringW. В отличие от двух других, внутренних, эта функция вполне себе часть публичного интерфейса и описана в MSDN, Гугл мгновенно находит ссылку msdn.microsoft.com/en-us/library/dd318700%28v=vs.85%29.aspx — выходит, это конверсия строк из одной локали в другую время почему-то жрет, как не в себя.
Что же, ставим очередную бряку (символ _LCMapStringW@24 видно сразу в стеке, удобно) и еще несколько в программе, и смотрим на две вещи. Какой, собственно, вызов API приводит к вызову этой самой дорогой LCMapString (для этого бряки в программе). И какие именно параметры в итоге передаются (для этого бряка на саму функцию). Несколько раз прошагав функцию видно, что код всегда идет по такому path:
Соотв-но все параметры видно крайне наглядно; вот они все, забиваются в стек (в обратном порядке). Результаты их внимательного осмотра, однако, сначала просто шокируют, а затем вызывают непроизвольное отпадение челюсти и неконтролируемое вытекание пены изо рта.
Оказывается, на каждый (каждый) вызов метода IChatMessage::GetBody происходит следующее.
Сначала в функцию LCMapStringEx прилетают данные #APPLICATIONCALLCHATMESSAGECHATMEMBERCHATGROUPSMSUSERVOICEMAIL#, с единственным флагом LCMAP_LOWERCASE («сделай lowercase с учетом локали»), локаль при этом стоит en-US. Возможно, на другой машине будет другая (у меня язык интерфейса винды именно en-US), но для конверсии обычной латиницы в нижний регистр это неважно. Вот только данные эти прилетают не одной длинной строкой, и даже не несколькими коротенькими строчками, а… по одному символу за раз.
Затем, видимо, написавший этот угар индус начинает подозревать неладное, вдруг придется еще одну команду протокола привести в нижний регистр, а у нас тормозища и куча сисколлов? Поэтому происходит гениальная превентивная оптимизация. И в функцию LCMapStringEx прилетает вся таблица от 0 до 255 включительно, опять по одному байту на вызов. Причем на всякий случай это делается еще и 2 раза подряд.
Затем гениальная оптимизация продолжается. (А может быть, просто ее теперь делает другой индус в другом месте кода.) И в функцию снова прилетает вся таблица от 0 до 255! Но каждый байт теперь повторяется подряд по 3 раза. Я лично считаю такой подход более правильным, чем предыдущий, конечно. В море нельзя брать два хронометра, надо либо один, либо три.
Итого более 1000 вызовов LCMapStringEx на каждую [censored] попытку взять текст 1 (одного) сообщения, каждый вызов делается на строчку размером ровно 1 байт. Через это 5000 взятий текста сообщения занимают 5-10 секунд CPU. От версии Skype COM API не зависит, что двухлетней давности, что текущий тормозят одинаково.
Охеренно, охеренно внутри устроен Skype API. Чувствуется, писали крепкие профессионалы.
Проблема ясна, что делать? В идеале надо эти вызовы вообще ликвидировать, но патчить в неизвестном количестве мест skype4com.dll во1х лениво (кто знает, из скольки разных точек дергают эту LCMapString), а во2х чревато (кто знает, к каким багам внезапно приведет). Напрашивается подменить саму функцию и сделать из нее быстрый выход для того самого случая вызова с 1 байтом. Нехитрая техника давно известна, взять адрес функции в памяти, сунуть туда jmp на свою функцию, из своей при необходимости выполнить затертые в начале инструкции и jmp-нуть обратно в исходную. Однако техника нудноватая и выпиливать ее ручками по ассемблеру тоже немного лениво.
Оказывается, уже и не нужно! MS Research уже подумал и сделал все за нас. В природе есть библиотека под названием Detours, которая умеет именно это и еще всякое. Можно, например, подменить функцию в каком-нибудь стороннем .exe вообще без его модификации, на лету подпихнуть свою реализацию из своей DLL. Ну а для моей утилитки Detours обеспечивает простой и понятный C/C++ интерфейс для нужной подмены, примера с названием simple.cpp более чем хватает. Цепляем в проект прожиточный минимум (detours.h, syelog.lib, detoured.lib, detours.lib), дописываем 20 строчек кода, и…
Итого закоротив идиотский и вообще ненужный (!) побайтовый перевод всякого в нижний регистр при помощи системного вызова, ускорили программу в 3.1 раза в целом. Неплохо, неплохо. Смотрим в профайл дальше!
Картинка резко поменялась. Теперь KernelBase.dll жрет только 20%, остальное проводится в неведомых дебрях skype4com.dll, которые уже так просто не возьмешь. Однако явно напрашивается проверить ситуацию с вызовом GetDriveType. Это функция определяет тип диска (съемный, несъемный, CD-ROM, RAM, или сетевой), если ее тоже вызывают тысячами раз, напрашивается закешировать результат. Тут нас ожидает очередное небольшое открытие.
Оказывается, профайлер врет и довольно ощутимо. Функция _GetDriveTypeW вызывается 1 (один) раз за все время работы программы. В профайле она отсвечивает вполне заметно, даже если экспортировать 1000 чатов, а не 100, однако реально времени не жрет.
Впрочем, профайлер таки не врет про _GetStringTypeW. Проделав аналогичные анализу вызовов _LCMapStringW нехитрые манипуляции, выясняем, что в ходе экспорта ее родительскую функцию GetStringTypeEx тоже постоянно дергают на каждый байт от 0 до 255 (кто бы сомневался). Перехватом GetStringTypeEx и возвратом результатов для однобайтового случая из кеша еще в 20 строчек получается ускорение еще на 15%, а всего в 3.6 раза.
Что интересно, после этой оптимизации KernelBase.dll вообще исчезает из профайла. 62% оставшегося времени жрет skype4com.dll, еще 12% употребляет ntdll.dll (на аллокации и критические секции), собственно программа жрет около 8%, ну и далее всякое системное по мелочи. Чувствуется, что потенциал для оптимизации еще в 3-5 раз вполне эдак присутствует, однако разбираться с происходящим при наличии имен функции и документации на них в MSDN это быстро, а дизассемблировать потроха skype4com.dll и выкуривать из них хотспоты нет. Да и экспорт заветных 360 тысяч сообщений уже таки занимает менее 10 минут, что приемлемо.
Короткое техническое резюме вроде уже подведено еще в начале статьи. Кругом живые люди, в том числе в именитых компаниях типа Skype, и код они местами пишут… как живые люди. Иногда ситуацию таки можно исправить минимальными усилиями, даже если тормозит в сторонней библиотеке, для которой нету исходников. На расследование тормозов и оптимизации у меня ушла буквально пара-тройка часов, включая осваивание Detours (первый раз его видел и пробовал). Опасаюсь, что на подготовку заметки суммарно ушло больше. Инструмент могучий, при правильном применении явно может творить небольшие чудеса.
… а логи сообщений Скайп, кстати, хранит в обычной SQLite базе, которая успешно открывается и управляется SQLite Browser при помощи обычного SQL синтаксиса. Зачистить историю для одного контакта выборочно? Пожалуйста. Для всех, на нужную глубину (чего сам Скайп при изменении настроек не делает)? Легко. Оптимизировать зачищенную базу? Опять же один клик. Но это уже другая, совсем не C++-ная история ;)
Успешных вам оптимизаций.
Вкратце, предыстория. Года полтора назад захотел экспортировать логи скайпа в удобном лично мне текстовом формате (почти cut/paste из чата, с махонькими улучшениями). Все найденные утилиты для экспорта чем-либо не устраивали. Либо зверски тормозили (потому как в логах чуть менее 300 контактов и чуть более 360 000 сообщений); либо писали логи в неудобном формате; либо все эти беды сразу; либо тупо не работали, и т.п. Решил написать свое, получилось. Сначала попробовал биндинги Skype API к Python, оказалось медленно. Потом попробовал Skype4COM и C++, оказалось куда быстрее. В итоге получилась довольно быстрая утилитка для экспорта логов. Хардкорная, консольная и на C++, понятное дело.
Очередной раз про бэкапы вспомнил пару недель назад, запустил проверенную утилитку и… понял, что конца не дождусь. Экспорт, который раньше занимал несколько минут, за полчаса продвинулся где-то на 10%, итого ETA получался около 5 часов. Неприемлемо долго. В чем дело?!
Слегка правим утилитку, ограничиваем количество экспортируемых чатов (как я понимаю, скайп отдельные сессии общения с одними и теми же контактами зачем-то разбивает на отдельные т.н. чаты, IChat), засекаем базовое время. Затем запускаем профайлер, благо, CodeAnalyst теперь встраивается в Visual Studio и запускается буквально в 2-3 клика. И внимательно смотрим на результаты.
exporting chat 100/7014...
exported 3925 events in 18.1 sec
Профайл выглядит кучеряво, 81% времени процесса жрет kernelbase.dll, еще 12% skype4com.dll, собственно программу даже не видать. Измена! Тормозит не мой код (что легко править), а какой-то сторонний. Но какой именно?
Уверенно побеждают функции InternalLcidToName, LCMapStringEx, NlsValidateLocale. Кто все эти люди? Я ничего подобного из своего кода не вызываю. Значит, вызываю не я. Значит, нужно узнать, откуда они вызываются, и тогда авось станет ясно, почему, и что с этим можно поделать. Надо поставить breakpoint на топовую функцию InternalLcidToName, посмотреть стек. Упс, проблемка. Тупо по названию функции бряка не ставится. Как быть?
Вариантов я знаю два, а есть небось еще больше. Во1х, раз функция вся такая в профайле топовая, то просто несколько раз случайно прервав исполнение мы обязательно в нее попадем. Во2х, слегка погуглив, удается найти магическую строчку {,,KernelBase.dll}@InternalLcidToName@8 — оказывается, нужный символ называется именно так, с собаками и циферкой. Забегая чутка вперед, циферки всегда кратны 4, и вообще сильно смахивают на размер стека, а вместо ведущей собаки для «публичных» символов типично подчеркивание. Заметив это, точные правила mangling уже сильно дольше искать, изучать и применять, чем перебрать пару-тройку вариантов (собака/подчеркивание, 4/8/12/16...), а то и попасть в какой-нибудь _GetStringTypeW@16 с первого же выстрела. Ну, вернувшись из недалекого будушего таки к насущному InternalLcidToName, неоднократно потыкав F5 и набрав статистику, становится видно две занятные вещи. Первое, что стек большинства вызовов выглядит вот так.
KernelBase.dll!@InternalLcidToName@8()
KernelBase.dll!_LCMapStringW@24() + 0x46 bytes
Skype4COM.dll!280c69f2()
// тут еще много строк про дебри Skype4COM.dll
// и только про них, стека самой программы не видно
Второе, что многократно исполняемый код выглядит вот так. При этом всегда ходит по одному и тому же codepath.
@InternalLcidToName@8:
752F6F33 mov edi,edi
752F6F35 push ebp
752F6F36 mov ebp,esp
752F6F38 push ecx
752F6F39 push edx
752F6F3A lea eax,[ebp-4]
752F6F3D push eax
752F6F3E mov dword ptr [ebp-4],ecx
752F6F41 call _NlsValidateLocale@8 (752F6E04h)
752F6F46 test eax,eax
752F6F48 je @InternalLcidToName@8+17h (7531BAB0h)
752F6F4E push eax
752F6F4F call _LocaleNameFromHash@4 (752F6F13h)
752F6F54 leave
752F6F55 retТе. все наши три топовые функции из профайла сводятся на самом деле к одной, _LCMapStringW. В отличие от двух других, внутренних, эта функция вполне себе часть публичного интерфейса и описана в MSDN, Гугл мгновенно находит ссылку msdn.microsoft.com/en-us/library/dd318700%28v=vs.85%29.aspx — выходит, это конверсия строк из одной локали в другую время почему-то жрет, как не в себя.
Что же, ставим очередную бряку (символ _LCMapStringW@24 видно сразу в стеке, удобно) и еще несколько в программе, и смотрим на две вещи. Какой, собственно, вызов API приводит к вызову этой самой дорогой LCMapString (для этого бряки в программе). И какие именно параметры в итоге передаются (для этого бряка на саму функцию). Несколько раз прошагав функцию видно, что код всегда идет по такому path:
752F8188 push 0
752F818A push 0
752F818C push 0
752F818E push dword ptr [ebp+1Ch]
752F8191 push dword ptr [ebp+18h]
752F8194 push dword ptr [ebp+14h]
752F8197 push dword ptr [ebp+10h]
752F819A push dword ptr [ebp+0Ch]
752F819D push eax
752F819E call _LCMapStringEx@36 (752F81ACh) Соотв-но все параметры видно крайне наглядно; вот они все, забиваются в стек (в обратном порядке). Результаты их внимательного осмотра, однако, сначала просто шокируют, а затем вызывают непроизвольное отпадение челюсти и неконтролируемое вытекание пены изо рта.
Оказывается, на каждый (каждый) вызов метода IChatMessage::GetBody происходит следующее.
Сначала в функцию LCMapStringEx прилетают данные #APPLICATIONCALLCHATMESSAGECHATMEMBERCHATGROUPSMSUSERVOICEMAIL#, с единственным флагом LCMAP_LOWERCASE («сделай lowercase с учетом локали»), локаль при этом стоит en-US. Возможно, на другой машине будет другая (у меня язык интерфейса винды именно en-US), но для конверсии обычной латиницы в нижний регистр это неважно. Вот только данные эти прилетают не одной длинной строкой, и даже не несколькими коротенькими строчками, а… по одному символу за раз.
Затем, видимо, написавший этот угар индус начинает подозревать неладное, вдруг придется еще одну команду протокола привести в нижний регистр, а у нас тормозища и куча сисколлов? Поэтому происходит гениальная превентивная оптимизация. И в функцию LCMapStringEx прилетает вся таблица от 0 до 255 включительно, опять по одному байту на вызов. Причем на всякий случай это делается еще и 2 раза подряд.
Затем гениальная оптимизация продолжается. (А может быть, просто ее теперь делает другой индус в другом месте кода.) И в функцию снова прилетает вся таблица от 0 до 255! Но каждый байт теперь повторяется подряд по 3 раза. Я лично считаю такой подход более правильным, чем предыдущий, конечно. В море нельзя брать два хронометра, надо либо один, либо три.
Итого более 1000 вызовов LCMapStringEx на каждую [censored] попытку взять текст 1 (одного) сообщения, каждый вызов делается на строчку размером ровно 1 байт. Через это 5000 взятий текста сообщения занимают 5-10 секунд CPU. От версии Skype COM API не зависит, что двухлетней давности, что текущий тормозят одинаково.
Охеренно, охеренно внутри устроен Skype API. Чувствуется, писали крепкие профессионалы.
Проблема ясна, что делать? В идеале надо эти вызовы вообще ликвидировать, но патчить в неизвестном количестве мест skype4com.dll во1х лениво (кто знает, из скольки разных точек дергают эту LCMapString), а во2х чревато (кто знает, к каким багам внезапно приведет). Напрашивается подменить саму функцию и сделать из нее быстрый выход для того самого случая вызова с 1 байтом. Нехитрая техника давно известна, взять адрес функции в памяти, сунуть туда jmp на свою функцию, из своей при необходимости выполнить затертые в начале инструкции и jmp-нуть обратно в исходную. Однако техника нудноватая и выпиливать ее ручками по ассемблеру тоже немного лениво.
Оказывается, уже и не нужно! MS Research уже подумал и сделал все за нас. В природе есть библиотека под названием Detours, которая умеет именно это и еще всякое. Можно, например, подменить функцию в каком-нибудь стороннем .exe вообще без его модификации, на лету подпихнуть свою реализацию из своей DLL. Ну а для моей утилитки Detours обеспечивает простой и понятный C/C++ интерфейс для нужной подмены, примера с названием simple.cpp более чем хватает. Цепляем в проект прожиточный минимум (detours.h, syelog.lib, detoured.lib, detours.lib), дописываем 20 строчек кода, и…
#define PROTO (LCID Locale, DWORD dwMapFlags, LPCWSTR lpSrcStr, int cchSrc, LPWSTR lpDestStr, int cchDest)
static int (WINAPI * TrueMap) PROTO = LCMapStringW;
int WINAPI MyMap PROTO
{
if (Locale==1033 && dwMapFlags==256 && cchSrc==1)
{
*lpDestStr++ = *lpSrcStr++;
*lpDestStr++ = 0;
return 1;
}
return TrueMap(Locale, dwMapFlags, lpSrcStr, cchSrc, lpDestStr, cchDest);
}
// ...
DetourRestoreAfterWith();
DetourTransactionBegin();
DetourUpdateThread(GetCurrentThread());
DetourAttach(&(PVOID&)TrueMap, MyMap);
LONG error = DetourTransactionCommit();
if (error != NO_ERROR)
printf ( "error detouring LCMapStringW(); export might be slower (code=%d)\n", error );
// ...
exporting chat 100/7014...
exported 3925 events in 5.8 secИтого закоротив идиотский и вообще ненужный (!) побайтовый перевод всякого в нижний регистр при помощи системного вызова, ускорили программу в 3.1 раза в целом. Неплохо, неплохо. Смотрим в профайл дальше!
Картинка резко поменялась. Теперь KernelBase.dll жрет только 20%, остальное проводится в неведомых дебрях skype4com.dll, которые уже так просто не возьмешь. Однако явно напрашивается проверить ситуацию с вызовом GetDriveType. Это функция определяет тип диска (съемный, несъемный, CD-ROM, RAM, или сетевой), если ее тоже вызывают тысячами раз, напрашивается закешировать результат. Тут нас ожидает очередное небольшое открытие.
Оказывается, профайлер врет и довольно ощутимо. Функция _GetDriveTypeW вызывается 1 (один) раз за все время работы программы. В профайле она отсвечивает вполне заметно, даже если экспортировать 1000 чатов, а не 100, однако реально времени не жрет.
Впрочем, профайлер таки не врет про _GetStringTypeW. Проделав аналогичные анализу вызовов _LCMapStringW нехитрые манипуляции, выясняем, что в ходе экспорта ее родительскую функцию GetStringTypeEx тоже постоянно дергают на каждый байт от 0 до 255 (кто бы сомневался). Перехватом GetStringTypeEx и возвратом результатов для однобайтового случая из кеша еще в 20 строчек получается ускорение еще на 15%, а всего в 3.6 раза.
exporting chat 100/7014...
exported 3925 events in 5.0 secЧто интересно, после этой оптимизации KernelBase.dll вообще исчезает из профайла. 62% оставшегося времени жрет skype4com.dll, еще 12% употребляет ntdll.dll (на аллокации и критические секции), собственно программа жрет около 8%, ну и далее всякое системное по мелочи. Чувствуется, что потенциал для оптимизации еще в 3-5 раз вполне эдак присутствует, однако разбираться с происходящим при наличии имен функции и документации на них в MSDN это быстро, а дизассемблировать потроха skype4com.dll и выкуривать из них хотспоты нет. Да и экспорт заветных 360 тысяч сообщений уже таки занимает менее 10 минут, что приемлемо.
Короткое техническое резюме вроде уже подведено еще в начале статьи. Кругом живые люди, в том числе в именитых компаниях типа Skype, и код они местами пишут… как живые люди. Иногда ситуацию таки можно исправить минимальными усилиями, даже если тормозит в сторонней библиотеке, для которой нету исходников. На расследование тормозов и оптимизации у меня ушла буквально пара-тройка часов, включая осваивание Detours (первый раз его видел и пробовал). Опасаюсь, что на подготовку заметки суммарно ушло больше. Инструмент могучий, при правильном применении явно может творить небольшие чудеса.
… а логи сообщений Скайп, кстати, хранит в обычной SQLite базе, которая успешно открывается и управляется SQLite Browser при помощи обычного SQL синтаксиса. Зачистить историю для одного контакта выборочно? Пожалуйста. Для всех, на нужную глубину (чего сам Скайп при изменении настроек не делает)? Легко. Оптимизировать зачищенную базу? Опять же один клик. Но это уже другая, совсем не C++-ная история ;)
Успешных вам оптимизаций.