Бэкапил историю сообщений из 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++-ная история ;)
Успешных вам оптимизаций.
