6 мая 2010 в 3:32
Сижу вот ковыряюсь в том, почему у меня медленно грузится.
Ковыряю внутренности drupal вместе с xdebug и функцией xdebug_time_index, привожу лог числа секунд от начала запуска скрипта index.php
:start module_list:bootstrap arg(1)0.250838041306
:module_list after db_query:0.26384305954
:end module_list:0.391767024994
0.672405004501:_drupal_bootstrap_full start
:start module_list:0.853047132492
:start module_list:bootstrap arg()0.853068113327
:module_list after db_query:0.854508161545
:end module_list:3.06656503677
:start load module:drupalforfirebug_preprocess:3.06660509109:end load module:drupalforfirebug_preprocess:3.08917212486
:start load module:block:3.08918118477:end load module:block:3.10769104958
:start load module:dblog:3.10770010948:end load module:dblog:3.126912117
:start load module:filter:3.12692213058:end load module:filter:3.14705300331
:start load module:help:3.14706206322:end load module:help:3.16486001015
:start load module:locale:3.1648709774:end load module:locale:3.18375205994
:start load module:menu:3.18376207352:end load module:menu:3.20202898979
:start load module:node:3.20203709602:end load module:node:3.22570514679
:start load module:path:3.22571516037:end load module:path:3.24375319481
:start load module:php:3.24376416206:end load module:php:3.26116108894
:start load module:search:3.26117014885:end load module:search:3.28117203712
:start load module:statistics:3.28118109703:end load module:statistics:3.28119516373
:start load module:system:3.28120112419:end load module:system:3.30464220047
:start load module:taxonomy:3.30465006828:end load module:taxonomy:3.32498908043
:start load module:upload:3.32499814034:end load module:upload:3.34720516205
:start load module:user:3.34721708298:end load module:user:3.3704931736
:start load module:ca:3.37050318718:end load module:ca:3.43222308159
:start load module:content:3.43223500252:end load module:content:3.46039414406
:start load module:content_copy:3.46040415764:end load module:content_copy:3.48980307579
:start load module:content_permissions:3.48981404305:end load module:content_permissions:3.5172522068
:start load module:nodereference:3.51726007462:end load module:nodereference:3.54697418213
:start load module:number:3.54698300362:end load module:number:3.57618808746
:start load module:optionwidgets:3.57620000839:end load module:optionwidgets:3.60514497757
:start load module:text:3.60515499115:end load module:text:3.63449406624
:start load module:userreference:3.63450503349:end load module:userreference:3.66422009468
:start load module:filefield:3.66423010826:end load module:filefield:3.75764608383
:start load module:imageapi:3.75765800476:end load module:imageapi:3.78091812134
:start load module:imageapi_imagemagick:3.78092908859:end load module:imageapi_imagemagick:3.80404114723
:start load module:imagecache:3.80405020714:end load module:imagecache:3.82884311676
:start load module:imagecache_ui:3.82885217667:end load module:imagecache_ui:3.85157203674
:start load module:imagefield:3.85158205032:end load module:imagefield:3.93378210068
:start load module:jmenu:3.93379306793:end load module:jmenu:3.95634913445
:start load module:mimedetect:3.95635914803:end load module:mimedetect:3.97886013985
:start load module:node_images:3.97886919975:end load module:node_images:4.00426220894
:start load module:revision_deletion:4.00427412987:end load module:revision_deletion:4.02848601341
:start load module:revision_moderation:4.02849507332:end load module:revision_moderation:4.08142709732
:start load module:taxonomy_image_blocks:4.08143901825:end load module:taxonomy_image_blocks:4.10958600044
:start load module:taxonomy_image_link_alter:4.10959720612:end load module:taxonomy_image_link_alter:4.13733816147
:start load module:taxonomy_image_node_display:4.13734698296:end load module:taxonomy_image_node_display:4.16571307182
:start load module:taxonomy_image:4.16572499275:end load module:taxonomy_image:4.19015908241
:start load module:taxonomy_menu:4.19016814232:end load module:taxonomy_menu:4.21313714981
:start load module:uc_attribute:4.21314620972:end load module:uc_attribute:4.27387404442
:start load module:uc_cart:4.27388620377:end load module:uc_cart:4.27390098572
:start load module:uc_order:4.2739071846:end load module:uc_order:4.42829918861
:start load module:uc_product:4.42831206322:end load module:uc_product:4.45594906807
:start load module:uc_product_kit:4.45596003532:end load module:uc_product_kit:4.48147010803
:start load module:uc_store:4.48147916794:end load module:uc_store:4.48149418831
:start load module:views_ui:4.48150014877:end load module:views_ui:4.50438499451
:start load module:wysiwyg:4.50439405441:end load module:wysiwyg:4.5288901329
:start load module:pathauto:4.52889919281:end load module:pathauto:4.55416607857
:start load module:fieldgroup:4.55417609215:end load module:fieldgroup:4.58487010002
:start load module:token:4.5848801136:end load module:token:4.60825800896
:start load module:views:4.60826706886:end load module:views:4.63354301453
:end module_list:4.63359713554
:end module_list:4.63435220718
:end module_list:4.70732617378
:end module_list:4.7073700428
:end module_list:4.70739912987
:end module_list:4.70742797852
:end module_list:4.70746302605
:end module_list:4.70754909515
:end module_list:4.76631498337
4.89600205421:_drupal_bootstrap_full FULL END
:end module_list:4.94938802719
:end module_list:4.94995117188
:end module_list:5.01108312607
:end module_list:5.06264305115
:end module_list:5.26359510422
:end module_list:5.366533041
:end module_list:5.37884712219
:end module_list:5.37951612473
:end module_list:5.74506211281
:end module_list:5.7456882
:end module_list:5.74580812454
5.92401218414
:end module_list:6.00745606422
cached menu 6.07676506042 - тут перед запуском моего кода из одного блока еще была потеряна где-то секунда, да и после тоже
:end module_list:6.08942818642
:end module_list:6.09099817276
:end module_list:6.09153699875
:end module_list:6.41775417328
:end module_list:6.43561315536
:end module_list:6.4366080761
:end module_list:7.35179519653
:end module_list:7.44590115547
Сразу скажу специально отключил всякие там оптимайзеры zend-ы, eaccelerator, оставил только xdebug. Также полностью отключен кэш в друпал, только jss и css с компрессией страницы включены.
Честно говооря, результат вывода одной страницы в таком случае просто обалденно впечатляет, особенно конечная цифра в 6 секунд.
Например, зачем грузятся модули магазина, учитывая, что я точно знаю, что от самого магазина ну нет там никакого кода на этой странице. Но это вопрос скорее к развитию drupal-а, иначе флаг в руки дадите 
Второй вопрос, зачем в module_list постоянно дергается файловая система чтобы проверить что модуль существует, у меня если верить счетчику под windows на домашней локальной машине тратится на это 2,3 секунды!
Вот нафига это делать, когда можно все проверить во время включения и выключения модуля из админки?
Есть случай когда это удобно. Например, включили вы модуль, а он зараза весь сайт рушит вы заходите удаляете его просто тупо из папочки modules и вуаля у вас престроен весь список модулей.
И вопрос третий, у меня такое ощущение что bootstrap в режиме full у меня запускается по какой-то другой причине. Сейчас я могу только предположить несколько:
1) надо бы все таки включить нормальное кэширование в друпал, тогда и для зареганных пользователей может не будет делаться полный bootstrap?
2) какая то фигня с чистыми ссылками
3) нет никакого кэширования типа boost и других, которые до полного bootstrap доходят только при первой генерации страницы
4) какая то ошибка в сессиях друпала у меня. Например, зашли вы на сайт, зарегались, сайт вам сессию открыл, и при всех последующих ваших посещениях сайта полный bootstrap не делается, делается какой нить укороченный, зачем ведь его делать, если уже при создании сессии сделали полный bootstrap, выяснили, что вам можно и что нельзя, все хуки меню созданы и все довольны, ну хотя бы модули в полном бутстрапе могли бы снова не перебирать
Я закоментировал код в module_list, где модуль на существование проверяется и удалось сэкономить
3.71884608269:_drupal_bootstrap_full FULL END
против того, что было: 4.89600205421:_drupal_bootstrap_full FULL END
только ~ 1,2 секунды, куда опять секунда делась не понятно.
Это не считая, что всякие модули грузятся по полной программе каждый раз, только кэширование спасает, да и то
нужно дождаться того, кто первый раз хоття бы загрузит страницу и подождет 7 секунд!
Также мне совсем не понятна идея вызова метода drupal_get_filename из module_list, особенно если учесть, что ровно эта же функция вызывается чуть позже из метода drupal_load. Хотя нет, как раз в drupal_load есть проверка, что файл модуля существует, так как метод drupal_get_filename хитрый с внутренней статической мапой. То есть первый вызов функции drupal_get_filename, заполняет ее, что для данного модуля нет файла, если его нет, а второй вызов честно возвращает ноль, что файла нет и в методе drupal_load include_once не выполняется. А спрашивается нафига? Потеряли еще секунду, на проверки и сокрытии того факта, что хотели подключит такой то php файл, но не включили, зато потом где нибудь в коде полезут уже php ошибки, что такой то метод не найден, так как он как раз в том файле должен быть. Но зато этот модуль мы оставляем в списке, ведь метод module_list даже не проверил результат функции drupal_get_filename. Нафига эта канитель? словно специально производительность угробить.
Комментарии
file_exists в drupal_get_filename как раз съел ту потерявшуюся секунду.
Если посмотреть код в drupal, который вызывает drupal_get_filename, то мало где проверяют потом, что функция возвращает. К примеру, можно взять метод drupal_install_system, там вызывают, но толку от того, что внутри функции drupal_get_filename проверяется существование файла никакого, так как все равно через require_once подключают не существующий файл.
ну если стоит eaccelerator (или что-то подобное), то даже удобнее загрузить все модули память и потом пользоваться тем, что надо, т.е. тут вопрос доступной оперативки просто... А насчет module_list надо посмотреть. Ну и вобще, в друпале есть что оптимизировать )
Вот как раз хочется узнать сколько при текущих установленных модулях без всякого кэширования грузится drupal.
!!!ВАЖНО!!!
Xочу отметить, не знаю от чего, но такая длительная загрузка, возможно, у меня в логе первом сообщении связана с тем, что тестовая система windows + xampp и у меня что-то глюкануло в этой связке. Вчера в связи с этим я нашел некое упоминание, что это может быть от отсутствия записи localhost в hosts, но это не помогло и потом я удалил hosts за неимением эффекта, чтобы вернуть в исходное.
Сегодня утром ушел, компьютер выключил, пришел, включил, модули грузятся в разы быстрее и без всякого акселератора, и вот ведь ничего не поменял просто перезагрузил windows.
Apache и MySQL я и вчера постоянно перезагружал.
Сейчас главная страница без оптимизаций загружается за 0,9 секунды. Чудеса какие-то. Я как раз и стал смотреть, что к чему из-за того, что вдруг стало все тормозить ужасно и Apache загружал CPU на 100%. Но понять от чего все началось так и не смог.
Знать бы еще от чего были такие дикие тормоза, ведь сам компьютер не тормозил, другие скрипты от того же xampp не тормозили. Что произошло, для меня просто загадка до сих пор, но я рад что это какой-то временный глюк.
-------
Убрал свои оптимизации из module_list и из drupal_load,
сейчас время затраченное на проверку существования файла модуля в файловой системе тратится существенно меньше, а именно:
start module_list:0.164741039276
end module_list:0.412463188171
т.е. 0.412-0.166 ~ 250 мс, а если проверку существования файлов убрать, то тратится только 1 мс
При выключенном eaccelerator и оптимизацией в module_list метод bootstrap_full выполняется за 348 мс сейчас. А вся страница грузится за 948 мс.
Все тоже самое, но при включенном eaccelerator, метод bootstrap_full выполняется за 300мс при первой загрузке страницы, и за 900 мс вся страница.
При повторном запросе страницы страница загружается за 770мс, а метод выполняется за 230 мс.
Т.е. включение eaccelerator дает некоторое ускорение загрузки модулей.
Но, те потерянные 250~300 мс в module_list смотрятся весьма заманчиво, чтобы их сэкономить.
Щас еще воспользуюсь drupal-ким таймером вместо xdebug, чтобы отключить xdebug и посмотреть сколько тратится времени без xdebug.
Получилось, что без xdebug, с включенным eaccelerator, и без оптимизации в module_list, методы выполняются за
module_list: 242.45
_drupal_bootstrap_full: 462.47
с оптимизацией module_list:
module_list: 1.8
_drupal_bootstrap_full: 221.13
Думаю выводы сделаете сами
Еще бы понять точно зачем делают проверку файлов в module_list и в drupal_get_filename.
В drupal_get_filename могу проверять, например, из-за шаблонов при темизации, но я не увидел чтобы где-либо потом проверялся результат этой функции и как-то реагировали адекватно с предупреждением в лог на отсутствие запрашиваемого файла.
Кстати подобное тестирование я таки нашел вот здесь
http://2bits.com/articles/high-php-execution-times-drupal-and-tuning-apc...
, но там module_list на разбирали, только метод drupal_load
Надеюсь это будет полезно узнать для кого нибудь.
ваша главная ошибка заключается в том что вы упускаете из виду такую вещь как особенности работы файловой системы и используемых в ОС систем кеширования.
самый примитивный пример повторное чтение файла в почти любой nix системе в общем случае не приведет к дисковым операциям.
я не специалист в архитектуре виндовс но допускаю что и там используется нечто подобное, и ваш случай с торможением по всей видимости связан с тем, что система по каким то причинам перестала нормально кешировать данные. Иными словами кто то сьесл всю память.
принцип работы eaccelerator достаточно прост, прекомпилияция php скриптов.
и есть одна важная ОПЦИЯ - как eacelerator это делает. По умолчанию он всегда проверяет все файлы по дате - были ли изменения. А это как вы понимаете файловая операция. Попробуйте отключить эту проверку в eaccelerator и вы невооруженным взглядом увидите еще больший прирост.
ну и так далее.
надо попробывать на линухе, кстати через xdebug можно диаграммы строить
Я с вами полностью согласен, связка windows + сайт, вообще вредна :D.
Есть у меня мысля что память у меня тогда мог прикущать firefox, у меня у него апетиты не мерянные, но не все же 3 гига
Для эксперимента было бы интересно все таки взглянуть на данные таймеров
хотя бы в linux сколько время тратится на проверку файлов в module_list, как с включенными так и отключенными оптимизаторами типа APC и eAccelerator
Я потестировал опцию check_mtime в eaccelerator
в данном случае она не повлияла, но с отключенным check_mtime тяжеловато, пока его не включишь обратно он opcode даже обновить не захочет
В принципе понятно, используются файловые операрации а не include, оптимизировать он их не может.
В документации на метод file_exists написано, что результат в общем то кэшируется и что в safe_mode еще FALSE возвращается, хотя .
Потестил еще раз, у меня порядка 125 мс теряется на проверках file_exists для включенных модулей, еще столько же в методе drupal_get_filename, так как там тоже этот метод вызывается. Было бы интересно узнать, как он все таки кэшируется в php. Так как повторные загрузки страниц как с оптимизатором так и без увы не показали что результат file_exists в php-5.2.4 у меня кэшируются, может опция какая в php есть
У меня же file_exists сейчас пустоту возвращает наверное от того что ему в качестве провеки файла пустую строку передают, (непереводимая игра слов) за пустую строку в качестве пути к файлу или директории. Вот отсюда наверное и не кэширует ничего, странно, куда же имя файла тогда делось:)
В последнем абзаце поторопился, имена файлов есть, не там свой лог вывод у себя вставил и сделал неправильный вывод из этого. У меня проверяется 59 файлов, тратится на это порядка 127 мс, при повторном вызове кэширования результатов выполнения функции file_exists не заметил
Php наверное не кэширует между запусками скриптов, а в рамках одного может быть
http://stackoverflow.com/questions/1708768/file-exists-is-too-slow-in-ph...
а file_exists во многих модулях используется в drupal
1) php под виндой тормозит.
2) XDebug в режиме отладки сам является тормозом. Нахрен нужны измерения, в которых измерительный прибор искажает результаты измерений ?
3) Все измерения, и связанную с ними оптимизацию надо проводить в окружении, идентичном рабочему.