Perl + mod_perl + gdb

Попытка отладки mod_perl проекта с помощью gdb - The GNU Debugger


==============================================================================80
[20100404]:

                                                                  "Мне не нужно чтобы вы развивались,
                                                                   мне нужно чтобы вы работали"
                                                                                    Александр Сабаев.
                                                                         Технический директор Adlabs.

13:10

Приветствую.

Много раз меня выручали небольшие статьи и заметки разных людей.
Они сталкивались с проблемой, находили решение и делились им с другими.
Вот и я решил заставить себя поделиться.

Итак что имеем:

- Есть web проект написанный на perl (5.8.8) с огромным количеством кода и логики.
Работающий под mod_perl (1.30), apache (1.3.37), FreeBSD 6.2-RC2 i386

Что не так:

- Меня пригласили заняться его аутсорсингом, первое что увидел - обработка запросов сильно тупит.
Притом то, что она тормозит в первую очередь раздражает именно меня, так как мешает нормальной
разработке и тестированию. При обработке запроса, проц постепенно съедается до 80%,
затем ломка проходит, нагрузка cpu спадает, запрос заканчивает свою обработку.

Задача:

- Нужной найти что тупит, иначе я психону и все на хрен там удалю.

Решение:

- Знаете, идти в код и пытаться везде там сувать дебаг как-то честно говоря лениво,
да знать нужно куда сувать, логику нужно понимать, не в сотни же файлов в каждую
строчку писать "Hello World" (в проекте > 1000 модулей) (насчет "Hello World" утрирую, а то сейчас начнёте)
опять же апач, забирает на себя stdout, stderr, поэтому нужно писать в логи, файлы.. так что геморрой.
Пойдем в лоб:

1. Запускаем top, запускаем запрос, смотрим что докопалась до cpu,
в моем случае это:

         PID   USERNAME    THR PRI NICE   SIZE    RES    STATE    TIME   WCPU    COMMAND
         56133  www        1   106 0      158M    154M   RUN      2:18   88.81%  httpd

2. В разгар пожирания cpu запускаем gdb и аттачимся к пиду 56133

        # gdb
        GNU gdb 6.1.1 [FreeBSD]
        (gdb)
        (gdb) attach 56133

        Attaching to process 56133

Гуд, зааттачились, всякие варнинги, лицензию и прочий мусор, вырезал.
теперь посмотрим куда мы вклинились, начнем со стека:

        (gdb) bt
        #0  0x88349b0c in Perl_swash_fetch () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #1  0x88343641 in S_find_byclass () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #2  0x88346dca in Perl_regexec_flags () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #3  0x882f3dca in Perl_pp_subst () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #4  0x882ee7f1 in Perl_runops_standard () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #5  0x8829574f in S_call_body () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #6  0x8829a6ac in Perl_call_sv () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #7  0x8829a7cc in Perl_call_method () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #8  0x889ded8d in dotop (root=0x108ad8a0, key_sv=0x1096d89c, args=0x1082e668, flags=0) at Stash.xs:508
        #9  0x889dfd9d in do_getset (root=0x108ad8a0, ident_av=0x1096663c, value=0x0, flags=0) at Stash.xs:832
        #10 0x889e0e78 in XS_Template__Stash__XS_get (cv=0x9204330) at Stash.xs:1268
        #11 0x882f5b2a in Perl_pp_entersub () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #12 0x882ee7f1 in Perl_runops_standard () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #13 0x8829574f in S_call_body () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #14 0x8829a6ac in Perl_call_sv () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #15 0x8829a7cc in Perl_call_method () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #16 0x889ded8d in dotop (root=0x10b10a80, key_sv=0x10dd31c4, args=0x10fc2e28, flags=0) at Stash.xs:508
        #17 0x889dfd9d in do_getset (root=0x10b10a80, ident_av=0x10dd239c, value=0x0, flags=0) at Stash.xs:832
        #18 0x889e0e78 in XS_Template__Stash__XS_get (cv=0x9204330) at Stash.xs:1268
        #19 0x882f5b2a in Perl_pp_entersub () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #20 0x882ee7f1 in Perl_runops_standard () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #21 0x8829574f in S_call_body () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #22 0x8829a6ac in Perl_call_sv () from /usr/local/lib/perl5/5.8.8/mach/CORE/libperl.so
        #23 0x8824e791 in perl_call_handler () from /usr/local/libexec/apache/libperl.so
        #24 0x8824ee70 in perl_run_stacked_handlers () from /usr/local/libexec/apache/libperl.so
        #25 0x0efa0034 in ?? ()
        #26 0x00000000 in ?? ()
        #27 0x00000002 in ?? ()
        #28 0x0efa05bc in ?? ()
        #29 0x00000001 in ?? ()
        #30 0xbfbfe3e8 in ?? ()
        #31 0x0804f63e in ap_table_setn ()
        Previous frame inner to this frame (corrupt stack?)

Вспоминаем, что основной строительный элемент перла это SV - scalar value

        struct STRUCT_SV { /* struct sv { */
            void* sv_any;     /* pointer to something */
            U32 sv_refcnt;   /* how many references to us */
            U32 sv_flags;     /* what we are */
        };

Глядя на стек видно, что мы крутимся в каких-то ф-ях, но в каких???
Для отладки было бы очень полезно раздобыть их имя.

Вспоминаем (либо гуглим), что у перла есть внутренняя функция - Perl_sv_dump(my_perl, sv)
Которая позволяет нам разглядеть содержимое sv.
Здорово, тащим её в студию и заставляем помочь нам раздампить какой-нибудь скаляр.

К примеру давайте возьмем этот:

         #16 0x889ded8d in dotop (root=0x10b10a80, key_sv=0x10dd31c4, args=0x10fc2e28, flags=0) at Stash.xs:508

16 - номер фрейма в стеке, выберем его для работы

        (gdb) frame 16
        #16 0x889ded8d in dotop (root=0x10b10a80, key_sv=0x10dd31c4, args=0x10fc2e28, flags=0) at Stash.xs:508
        508                     n = perl_call_method(item, G_ARRAY | G_EVAL);

Зовем несчастную:

        (gdb) call Perl_sv_dump(key_sv)
        $1 = -2009613648

Упс.. получили только код возврата, а где же вывод-то?
Мда.. идем за печенюшками, кофе и на обратном пути до нас доходит (возможно придется сходить несколько раз)
Эврика! апач же забрал дескрипторы stdout, stderr, ах сад мой вишневый сад!
Нужно отобрать их у него, но как? кхм..
кхм..

Как Вы думаете, что такое дескриптор для простого смертного процесса? Правильно, это просто целое число.
Соответственно апач запомнил два числа: 2 - stderr и 1 - stdout и при записи в них говорит ядру: "хочу записать
в дескриптор один (или два), круто, [email protected] не проживешь, закрываем их оба.

        (gdb) call close (2)
        $2 = 0
        (gdb) call close (1)
        $3 = 0

теперь апач сам того не зная отказался от stderr, stdout, но он не дурак и при первой же возможности попытается
в них что-нить написать (кстати то, что нужно нам) Помня особенность, что при открытие файла/сокета/канала
дается первый свободный дескриптор, открываем два файла:

        (gdb) call creat("/tmp/my_stdout.log", 0600)
        $4 = 1

        (gdb) call creat("/tmp/my_stderr.log", 0600)
        $5 = 2

Как мы видим, нам открыли два дескриптора: 1 и 2 (stdout, stderr) так, что когда теперь апач будет
что-нить писать (в как он думает свой stdout, stderr),
мы увидим содержимое (но помните, что обманывать говорят не хорошо)

Помните мы сменили фрейм? Теперь настало время раздампить sv

        (gdb) call Perl_sv_dump(key_sv)
        $6 = -2009613648

На экране не густо, зато в файле "/tmp/my_stderr.log" можем видеть:

        SV = PV(0x10af3f78) at 0x10dd31c4
        REFCNT = 1
        FLAGS = (POK,pPOK)
        PV = 0xf041d70 "render"\0
        CUR = 6
        LEN = 8

А "render" уже зацепка (это название ключа), роем дальше.

Обратим внимание на фрейм

        #18 0x889e0e78 in XS_Template__Stash__XS_get (cv=0x9204330) at Stash.xs:1268

раздампим cv

        (gdb) call Perl_sv_dump(0x9204330)
        $12 = -2009613648

смотрим файл с stderr

        SV = PVCV(0x91c7b00) at 0x9204330
        REFCNT = 1
        FLAGS = ()
        IV = 0
        NV = 0
        COMP_STASH = 0x0
        ROOT = 0x0
        XSUB = 0x889e0d00
        XSUBANY = 0
        GVGV::GV = 0x920421c  "Template::Stash::XS" :: "get"
        FILE = "Stash.c"
        DEPTH = 0
        FLAGS = 0x0
        OUTSIDE_SEQ = 0
        PADLIST = 0x0
        OUTSIDE = 0x0 (null)

Неплохо, есть название модуля в котором мы крутимся

Имея в прошлом небольшой опыт работы с Template-Toolkit я вспомнил,
что Template::Stash::XS уже когда-то показывал себя с плохой стороны,
необъяснимыми зависаниями, съеданиями памяти и т.д.
и что этот модуль написан вроде как для "ускорения работы" этих темплитов.
Для проверки теории, что траблы в нем, я нашел в коде его вызов и заменил
на Template::Stash (этот модуль базовый и он не может похвастаться
такой производительностью как Template::Stash::XS впрочем как и зависаниями
и съеданиями памяти)

После переключения на "не сишный" модуль парсинга темплитов и перезапуска апача,
в логах получил:

        [START OF REPORT] {
            Report ID: "[UNKNOWN20100404134558773106]"
            Report description: "BROKEN IDENT DETECTED, element number: '2' ident: [ALL_CATS, 0, , 0]"

        [START OF STACK TRACE] {
            Vsem::Utils::Fatal::_get_stack_trace(...) at /vsem/lib/Vsem/Utils/Fatal.pm:220
            Vsem::Utils::Fatal::_create_report_problem(...) at /vsem/lib/Vsem/Utils/Fatal.pm:162
         -> Vsem::Utils::Fatal::create_report_problem(...) at /vsem/lib/Vsem/Utils/Fatal.pm:66
         -> Vsem::Utils::Fatal::vsem_die(...) at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Stash.pm:418
            Template::Stash::get(...) at /Vsem/templates/default/common/Anchor_add.tt:7
            eval {...} at /Vsem/templates/default/common/Anchor_add.tt:7
            Template::Document::__ANON__(...) at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Document.pm:156
            eval {...} at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Document.pm:154
            Template::Document::process(...) at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Context.pm:350
            eval {...} at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Context.pm:324
            Template::Context::process(...) at /Vsem/templates/default/common/header:365
            eval {...} at RAWPERL block (starting line 398):4
            Template::Document::__ANON__(...) at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Document.pm:156
            eval {...} at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Document.pm:154
            Template::Document::process(...) at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Context.pm:350
            eval {...} at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Context.pm:324
            Template::Context::process(...) at /Vsem/templates/default/Main.tt:14
            eval {...} at /Vsem/templates/default/Main.tt:7
            Template::Document::__ANON__(...) at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Document.pm:156
            eval {...} at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Document.pm:154
            Template::Document::process(...) at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Context.pm:350
            eval {...} at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Context.pm:324
            Template::Context::process(...) at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Service.pm:100
            eval {...} at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template/Service.pm:97
            Template::Service::process(...) at /usr/local/lib/perl5/site_perl/5.8.8/mach/Template.pm:72
            Template::process(...) at /vsem/lib/Vsem/WWW/Component.pm:393
            Vsem::WWW::Component::render(...) at /vsem/lib/Vsem/WWW.pm:398
            eval {...} at /vsem/lib/Vsem/WWW.pm:256
            Vsem::WWW::handler(...) at /dev/null:0
            eval {...} at /dev/null:0
        } [END OF STACK TRACE]

А это уже интересно, похоже Template::Stash
содержит в себе больше проверок на ошибки, чем Template::Stash::XS

Ок, взглянем на темплит: /Vsem/templates/default/common/Anchor_add.tt:7
с ALL_CATS связана только одна строчка:

        [% SET category_add = ALL_CATS.${msg_or_vars.cat_id} %]

дамп переменных "msg_or_vars.cat_id" и "ALL_CATS" показал, что они пустые
видимо сишная часть Template::Stash::XS не отлавиливает такие вещи
и пытается разименовать пустоту

добавил в темплит проверку на такие события, удалил закешированые темплиты,
перезапустил апач, сделал запрос - ошибка с темплитами исчезла

попробую включить обратно сишный парсинг темплитов Template::Stash::XS
Тада, все ожило.

Итог:
Зная втнутренее устройство perl'а можно использовать нестандартные способы отладки
такие как c gdb. На мой взгляд в данном случае это был самый
быстрый способ, пусть и сложный. В проекте > 1000 модулей и столькоже темплитов,
профайлинг (как его еще к mod_perl прикрутить) отнял бы у меня гораздо больше времени.
В любом случае данный рассказ - просто обмен экспиренсом в надежде на то,
что однажды он кого-то выручит.

Вот собственно пока и все, спасибо что дочитали.
Успехов, Роман.

PS. Дополнительные варианты дампов
Пример:

        #50 0x889ded8d in dotop (root=0x1092d468, key_sv=0x1093203c, args=0x105d1e30, flags=0) at Stash.xs:508

Зовем perl:

        (gdb) call Perl_sv_dump (0x105d1e30)

Получаем на stderr:

            SV = PVAV(0x10999c60) at 0x105d1e30
              REFCNT = 3
              FLAGS = ()
              IV = 0
              NV = 0
              ARRAY = 0xa9f56c0
              FILL = 5
              MAX = 5
              ARYLEN = 0x0
              FLAGS = (REAL)

Этот массив, живет по адрессу 0xa9f56c0
Дампим адреса:

        (gdb) x/5wx 0xa9f56c0
        0xa9f56c0:      0x105d1e84      0x1078a8e8      0x105d198c      0x10a60aa4
        0xa9f56d0:      0x10932288

Внутри указатели на другие sv, ниже дамп одного из них

        (gdb) call Perl_sv_dump (0x105d198c)
        $27 = -2009613648

На stderr:

              SV = PV(0x10ce3960) at 0x105d198c
              REFCNT = 1
              FLAGS = (POK,pPOK)
              PV = 0xf18b9a0 "show_articlelist"\0
              CUR = 16
              LEN = 20

15:46
==============================================================================80






















































Смотрите также:

Вам это будет интересно!

  1. Как создать самый деревянный шаблон к Joomla
  2. Как создать самый деревянный шаблон к Joomla part 3.