Pull to refresh

Аудит одного «медленного» приложения в одном крупном концерне

Reading time 7 min
Views 14K
В общем-то хотел просто ответить на этот комментарий и в качестве примера привести неожиданные результаты одного как-то сделанного мною аудита веб-приложения, но ответ получался очень громоздкий.
Так родилась эта статья.

Вступление


Речь шла о том, что иногда в корпоративном секторе, прикрываясь надуманными нормативами или навязанными стандартами от безопасности, случаются совершенно неоправданные, а иногда и совершенно дикие реализации последних, нередко граничащих просто с невозможными условиями работы. Например CIO и иже с ним (либо нерадивые или просто ленивые исполнители), руководствуясь такими политиками, возможно переусердствовали, а часто не нашли (или не искали) лучшего решения.

В результате имеем антивирусы на серверах, со всеми вытекающими, потому что просто должен быть на каждом компьютере. Сотрудников вынужденных работать под админом (aka MakeMeAdmin), потому что создать админский аккаунт (тех-юзера), тупо для скриптов, перестартовки и дебага сервисов, ну никак не возможно (да и ладно — все-равно есть же антивирус). Политики позволяющие запустить исполняемый файл отовсюду (сеть, временный каталог и т.д.), потому что какая-то там служба обновления по другому не умеет (не страшно — снова антивирус как аргумент). И т.д. и т. п.

На самом деле я совершенно четко понимаю откуда у таких требований ноги растут. Довольно часто это действительно условия клиентов-заказчиков, требования материнской там или партнерской компании или де-факто стандарты индустрии, которым просто нужно соответствовать. Ну т.е. тупо никуда не денешься.
Но, дело в том что технически как раз некоторые вещи, что касается безопасности, совершенно не оправданы, хуже того в действительности совсем «не секьюрны», мало того — мешают как разработке, так и продуктивной работе того же клиента.
И если прикрывая свою пятую точку (прикрываясь фальшивыми «стандартами»), решаешь соответствовать требованию безопасности от лукавого, то сделай это хотя бы включая голову, так чтобы это не влияло (ну или минимально влияло) на продуктивность компании.

Пример: как-то бились с одним известным антивирусом (доказуемо бажным, вероятно где-то в районе аналитики и очередях real time scanning) — при очень большой загруженности сервера (32 ядра >= 50% cpu load):
  • антивирус блокирует (от нескольких миллисекунд до 30 секунд!) доступ к файлам, после их переименования — в результате многопоточный pipeline (асинхронная очередь заданий) периодически вылетает с «access denied» при доступе например к временным, только что созданным и затем переименованным файлам из другого потока, сообщившего об окончании работы. При том, что working folder вроде бы совсем исключен из real time scanning.
  • или того хуже, кладет дочерние процессы спать (suspended) и забывает их «разбудить», а поток в предке бесконечно ждет окончания работы уснувшего дитя.
И ведь отключить его в продакшн на серверах «никак не возможно» (даже временно в качестве доказательства, т.к. таким антивирусом как правило они себе одно место прикрывают).

Например, что стоит разделить ту же сеть и воткнуть тот же антивирус за NAT-ом. Или хотя бы проверить на такие болячки и заменить на другой, более надежный. Сравните эту стоимость со скажем человеко-часом * 25000 сотрудников, ежедневно минута за минутой тратящихся на тупое ожидание ответа приложения.
А в результате растет-растет число велосипедов типа «safe_rename», «real_delete» или «start_process_with_observe» вокруг проектов. Тот же CIO быстро пересмотрел бы свою позицию, если бы ему (его подразделению) коллективный счет выставить за суммарное время «простоя» (ожидания) всех сотрудников.

Аудит


Мне как-то приходилось делать audit одного более-менее крупного приложения в одном очень большом концерне. Web-приложение в интранете компании. Оно, по слухам, вроде бы и раньше не блистало скоростью. А после какого-то там релиза все стало ну очень-очень медленно.
Изготовитель божился, что у них все в порядке — якобы по логам не видно, что приложение перегружено, однако точно такой нагрузочный тест как в продакшн нереально симулировать. В общем терпение клиента кончилось — ну и собственно аудит…

Началось все с написания анализаторов присланных логов (слава богу протоколы в приложении, точнее в app-server'е можно было довольно сильно детализировать). В результате огромные логи сведены в более-менее читаемый вид. Пример обрезанного протокола после анализатора (и подстроенного под хабрапарзер), кому вдруг интересно, можно увидеть под спойлером ниже — скажу лишь сразу, что логи не показали ничего явного. Т.е. сервера (приложение) ну да — не быстрые (где-то местами SQL притормаживает, где-то — storage или NAS), но в общем могли бы в принципе справится и с нагрузкой, в десятеро превышающую анализируемую.

Пример протокола анализа ...
Analyse:
Analyse-Time 9338645
(155,644 min)
07:45:09 — 10:20:48
Idle(ms) 6069160 (101,153 min) Idle-AVG: 735,66 Count: 8250
Busy(ms) 3269485 (54,491 min) Busy-AVG: 396,3
Total(ms) 4536133 (75,602 min)  
AVG(ms) 285,6  
Requests 15883        
Users 106 Avg(ms) Min(ms) Max(ms)
WorkTime(ms) 521217468 (8.686,958 min) 4917145 (81,952 min) 344 (0,006 min) 9322426 (155,374 min)
ServerTime(ms) 4536133 (75,602 min) 42793 (0,713 min) 142 (0,002 min) 298511 (4,975 min)
Name /app/mailbox.htm /app/docmain.htm /port/result.htm /app/tree.htm /app/view.htm /app/docnavi.htm /port/docview.htm /app/result.htm /port/report2.htm /port/search.htm /port/pdfview.htm /app/action.htm ... /app/empty.htm
Time(ms) 1135731 (18,929 min) 770339 (12,839 min) 616371 (10,273 min) 606983 (10,116 min) 286304 (4,772 min) 255469 (4,258 min) 173729 (2,895 min) 135370 (2,256 min) 109145 (1,819 min) 72917 (1,215 min) 34346 (0,572 min) 32499 (0,542 min) ... 0 (0,000 min)
AVG(ms) 1.108,03 514,59 1.064,54 211,35 239,79 222,73 622,68 474,98 5.457,25 197,07 602,56 172,87 ... 0
Count 1025 1497 579 2872 1194 1147 279 285 20 370 57 188 ... 1
User-Times:
UID net\u101165 net\u144102 net\u193619 ...
Time(ms) 298511 (4,975 min) 238661 (3,978 min) 168190 (2,803 min) ...
AVG(ms) 2.446,81 269,07 282,2 ...
Count 122 887 596 ...
WorkTime 131,818 min 07:55:26-10:07:16 117,066 min 08:23:28-10:20:32 150,534 min 07:46:35-10:17:07 ...
Requests Name Time(ms) AVG(ms) Count Name Time(ms) AVG(ms) Count Name Time(ms) AVG(ms) Count ...
/port/result.htm 280962 (4,683 min) 12.771,00 22 /app/docmain.htm 89560 (1,493 min) 621,94 144 /app/mailbox.htm 53689 (0,895 min) 1.677,78 32 ...
/port/docview.htm 11938 (0,199 min) 746,13 16 /app/tree.htm 55327 (0,922 min) 278,03 199 /app/docmain.htm 39019 (0,650 min) 750,37 52 ...
/port/search.htm 3750 (0,063 min) 250 15 /app/docnavi.htm 42245 (0,704 min) 291,34 145 /app/tree.htm 22122 (0,369 min) 254,28 87 ...
/port/tree.htm 797 (0,013 min) 88,56 9 /app/view.htm 22986 (0,383 min) 247,16 93 /app/view.htm 15830 (0,264 min) 316,6 50 ...
/port/view.htm 640 (0,011 min) 40 16 /app/mailbox.htm 16126 (0,269 min) 1.466,00 11 /port/result.htm 9622 (0,160 min) 253,21 38 ...

Грубо говоря, об этом сообщает даже суммарный сведенный idle-time всех воркеров сервера (101,153 min из 155,644 min).

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

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

И потратив всего час на поиски — был в результате в тихом ужасе (тут вообще-то другое слово).

Но по порядку: сперва втиснул свой прокси, с включённым accesslog, между браузером и сервером, намучившись с MITM с подменой NTLM-credential (прокси работал тоже под аккаунтом пользователя), и с подменой абсолютных URL на другой порт и т.п. Я-то ожидал в логах увидить, что приложение ни при чем — это или антивирус, ну или что-то с браузером (скрипты там и т.д.).
А сделав несколько кликов в приложении, неожиданно обнаружил в тайл лога добрую сотню мини-реквестов от браузера на каждый вызванный запрос (на каждый клик). Вся статика, т.е. иконки, статичные скрипты и стили при каждом клике отрабатывалась снова и снова — т.е. имеем один-два больших запроса 200 и много (очень много) мелких 304 (Not Modified).

Однако приложение, как положено, отсылало для статики корректные заголовки для кеширования (Cache-Control, Expires и т.д.).
Короче говоря, выяснилось — кэш браузера был просто-тупо «выключен» (политиками)!
Во всем концерне!!!
Ну т.е. галочка «Check for newer version» стояла в «Every time I visit the webpage».

Добавим ко всему NTLM сверху (с handshake туда-сюда и запрос-ответ к PDC от обоих) и учитывая что имеем множество приложений в компании на веб-архитектуре, помножим на количество сотрудников всего концерна и Вуаля! Можно идти в серверную и любоваться красным свечением раскаленного донельзя сетевого оборудования.
Т.е. браузер мало того, что шлет и принимает кучу с гаком мелких запрос-ответов, еще и ждет подтверждения от последнего ресурса в страничке — я неизменен, чтобы закончить рендеринг и показать страницу. Думается мне, что и антивирус, постоянно бомбардируемый дополнительными запросами, внес свою посильную лепту в общую картину (хотя реакция его на к примеру тот же скрипт, вернувшийся с 304, мне не известна).
Ну и как бонус сверху — тупая донельзя сеть — про то, как огромная масса мини-пакетов может скрасить жизнь всего сетевого сегмента в целом и конкретного маршрутизатора в частности, сетевые администраторы могут длинные истории рассказывать (как правило нецензурно).

Кстати мне с поиском (да и клиенту) еще мягко говоря повезло — в настройках моего прокси accesslog для статики был включен, хотя обычно он выключен (просто крайний раз тестировал 304 и иже с ними и конфигурацию обратно не поправил). Ну не ожидал никто (присутствующие там админы тоже пошли пятнами), что сотрудники, отвечающие за полиси (в этом случае за настройки браузера), настолько некомпетентны. Настолько, что просто граничит, имхо, с основанием для увольнения с работы.

По слухам же, кэш был «выключен» потому, что совсем в другом проекте, какая-то бажная версия какой-то там SAP-компоненты, где-то не умела по другому (возможно не там проставили Cache-Control, Expires и т.д. или некорректно отрабатывался If-Modified-Since). Смысл в том, что тестеры не обнаружили, а исполнители, выкатившие бажный релиз в продакшн, не смогли откатится назад и не нашли ничего лучше, как тупо «отключить» проверку expires и cache-control. Еще раз — во всем концерне! Т. е. для всех приложений и серфинга как такового.
Они могли бы например поставить что-нибудь проксирующее перед приложением, чтобы поменять заголовки только для конкретно этих URL, или например врезаться в application server для «rewrite» в нем напрямую. На вскидку можно придумать десяток решений лучше.
Кстати, вместо того, чтобы признать фэйл — по слухам, они с пеной у рта доказывали что оно — нужно и хорошо, и что даже Microsoft рекомендует эти настройки для IE. В результате, вашему покорному слуге пришлось, в качестве приложения к отчету о проделанной работе, писать еще и «диссертацию» на тему «Почему плохо — это нехорошо».

А у простых пользователей той компании я прослыл волшебником, за час решившим проблему, которую месяцами (а то и годами) не могли найти местные IT-специалисты.
Вы представляете, вдруг не только то приложение, но и всё остальное в компании внезапно стало работать намного быстрее! Вплоть до последнего сетевого принтера…

Засим откланиваюсь, с просьбой не пинать со словами типа «Программисты тоже делают ошибки», и с надеждой, что может быть всё же ответственные лица (а также исполнители) прислушаются к нам и хотя бы иногда будут включать голову… Сильно помогает.
Tags:
Hubs:
If this publication inspired you and you want to support the author, do not hesitate to click on the button
+15
Comments 36
Comments Comments 36

Articles