Hello. I've setup NYTProf to start with apache. Clicked some pages. There where several nytprof.$$.out.pid files. Not all files were decrypted with nytprofhtml. I've found big seconds on two of files. I don't know what to search for very well, so this is some text:
Profile of /srv/httpd/bin/httpd for 40.4s (of 40.6s), executing 51799 statements and 39622 subroutine calls in 174 source files and 53 string evals. Top 15 Subroutines Calls P F Exclusive Time Inclusive Time Subroutine 1 1 1 3.00s 3.00s DBD::mysql::db::_login (xsub) 13711 1 1 571ms 619ms Encode::utf8::decode_xs (xsub) 1 1 1 383ms 1.00s Kernel::System::Fred::STDERRLog::CORE:readline (opcode) 29 8 7 222ms 498ms Kernel::System::Main::Require 1 1 1 114ms 142ms Kernel::Config::Defaults::new 25 1 1 73.3ms 782ms Kernel::System::ObjectManager::_ObjectBuild (recurses: max depth 1, inclusive time 157ms) 1 1 1 66.5ms 98.3ms Kernel::System::ObjectManager::BEGIN@24 4 1 1 49.0ms 49.9ms Template::Document::new 13711 1 1 47.8ms 47.8ms Encode::Encoding::renewed 1 1 1 46.3ms 46.4ms Template::Parser::BEGIN@41 1 1 1 41.7ms 1.05s Kernel::System::Fred::STDERRLog::DataGet 10 3 1 40.3ms 120ms Template::Config::load 4 4 4 36.2ms 39.8ms utf8::SWASHNEW 20 20 20 33.9ms 96.8ms base::import (recurses: max depth 1, inclusive time 135µs) 1 1 1 28.8ms 29.0ms Kernel::System::ObjectManager::BEGIN@30 See all 2571 subroutines
Source Code Files — ordered by exclusive time then name Stmts Exclusive Time Reports Source File 124 3.02s line • block • sub DBD/mysql.pm 114 1.05s line • block • sub /srv/otrs//Kernel/System/Fred/STDERRLog.pm 1 123ms line • block • sub -e 2338 112ms line • block • sub /srv/otrs/Kernel/Config/Files/ZZZAAuto.pm 716 76.2ms line • block • sub /srv/otrs//Kernel/Output/HTML/Layout.pm 2230 68.8ms line • block • sub /srv/otrs//Kernel/Language/en_ITSMChangeManagement.pm 1580 66.3ms line • block • sub /srv/otrs//Kernel/System/ObjectManager.pm 210 53.0ms line • block • sub Template/Document.pm (including 13 string evals) 16 42.3ms line • block • sub Template/Grammar.pm 5995 42.0ms line • block • sub /srv/otrs//Kernel/Config/Defaults.pm (including 1 string eval) 1932 41.4ms line • block • sub utf8_heavy.pl 2426 40.2ms line • block • sub /srv/otrs/Kernel/cpan-lib/JSON/PP.pm (including 20 string evals) 13010 36.0ms line • block • sub /srv/otrs/Kernel/cpan-lib/Apache2/Reload.pm 2205 31.2ms line • block • sub /srv/otrs//Kernel/System/Main.pm 163 29.3ms line • block • sub /srv/otrs//Kernel/System/DB.pm 6 28.4ms line • block • sub /srv/otrs//Kernel/System/Group.pm 203 21.2ms line • block • sub /srv/httpd/../modperl/lib/perl/5.14.2/ModPerl/RegistryCooker.pm (including 1 string eval) 6 20.7ms line • block • sub /srv/otrs//Kernel/System/LinkObject.pm 710 19.6ms line • block • sub /srv/otrs//Kernel/Language/en_CA_ITSMChangeManagement.pm 710 19.2ms line • block • sub /srv/otrs//Kernel/Language/en_GB_ITSMChangeManagement.pm 1820 18.1ms line • block • sub Template/Context.pm 56 16.2ms line • block • sub Cwd.pm (including 2 string evals) 348 15.5ms line • block • sub Template/Provider.pm 10 15.2ms line • block • sub /srv/otrs//Kernel/Output/HTML/Layout/Ticket.pm 36 15.0ms line • block • sub File/Find.pm 29 14.3ms line • block • sub Template/Parser.pm 1503 13.6ms line • block • sub Template/Filters.pm 748 13.3ms line • block • sub File/stat.pm 12 13.3ms line • block • sub /srv/otrs//Kernel/Output/HTML/Layout/LinkObject.pm 57 13.2ms line • block • sub /srv/otrs//Kernel/System/Web/InterfaceAgent.pm 23 13.0ms line • block • sub /srv/otrs//Kernel/System/User.pm 49 12.8ms line • block • sub POSIX.pm 16 11.9ms line • block • sub Template/Directive.pm 28 10.7ms line • block • sub /srv/otrs//Kernel/System/AuthSession/DB.pm 2306 10.5ms line • block • sub Class/Struct.pm (including 1 string eval) 63 10.4ms line • block • sub /srv/otrs//Kernel/System/Time.pm 543 10.4ms line • block • sub /srv/otrs//Kernel/System/Encode.pm 59 10.1ms line • block • sub /srv/otrs//Kernel/System/DB/mysql.pm 443 9.69ms line • block • sub /srv/otrs//Kernel/Language.pm
And another:
Profile of /srv/httpd/bin/httpd for 48.8s (of 51.6s), executing 1211808 statements and 324088 subroutine calls in 318 source files and 109 string evals. Top 15 Subroutines Calls P F Exclusive Time Inclusive Time Subroutine 27422 1 1 987ms 1.07s Encode::utf8::decode_xs (xsub) 11 1 1 672ms 882ms Template::Parser::_parse 2 1 1 640ms 1.71s Kernel::System::Fred::STDERRLog::CORE:readline (opcode) 228 19 12 633ms 1.05s Kernel::System::Main::Require 104 1 1 410ms 1.86s Kernel::System::ObjectManager::_ObjectBuild (recurses: max depth 1, inclusive time 267ms) 421 4 1 252ms 252ms Kernel::System::Main::CORE:ftis (opcode) 27 2 1 223ms 228ms Template::Document::new 100 1 1 186ms 186ms Kernel::System::Main::CORE:readline (opcode) 2 1 1 185ms 1.08s JavaScript::Minifier::minify 3 1 1 174ms 270ms Kernel::Config::Defaults::new 15 1 1 160ms 160ms Template::Provider::CORE:readline (opcode) 16352 2 1 159ms 249ms JavaScript::Minifier::action4 23 1 1 138ms 138ms DBI::db::do (xsub) 6 6 6 117ms 142ms utf8::SWASHNEW 15642 5 1 115ms 352ms JavaScript::Minifier::action3 See all 4654 subroutines
Source Code Files — ordered by exclusive time then name Stmts Exclusive Time Reports Source File 1 39.3s line • block • sub -e 50 1.79s line • block • sub /srv/otrs//Kernel/System/Fred/STDERRLog.pm 319261 1.09s line • block • sub /srv/otrs/Kernel/cpan-lib/JavaScript/Minifier.pm 450013 973ms line • block • sub Template/Parser.pm 9738 785ms line • block • sub /srv/otrs//Kernel/System/Main.pm 12143 345ms line • block • sub /srv/otrs//Kernel/System/DB.pm 84131 275ms line • block • sub /srv/otrs/Kernel/cpan-lib/CSS/Minifier.pm 3332 232ms line • block • sub Template/Document.pm (including 56 string evals) 9406 226ms line • block • sub /srv/otrs//Kernel/System/ObjectManager.pm 3121 193ms line • block • sub Template/Provider.pm 6996 170ms line • block • sub /srv/otrs/Kernel/Config/Files/ZZZAAuto.pm 23868 147ms line • block • sub /srv/otrs//Kernel/Config/Defaults.pm (including 1 string eval) 18762 143ms line • block • sub utf8_heavy.pl 33285 130ms line • block • sub Template/Context.pm 14866 130ms line • block • sub /srv/otrs//Kernel/Output/HTML/Layout.pm 21569 110ms line • block • sub Template/Directive.pm 14800 102ms line • block • sub /srv/otrs//Kernel/Output/Template/Document.pm 14016 93.1ms line • block • sub /Parser.yp 23534 82.7ms line • block • sub Template/Filters.pm 90 79.0ms line • block • sub /srv/otrs//Kernel/System/Ticket.pm 6676 77.3ms line • block • sub /srv/otrs//Kernel/Language/en_ITSMChangeManagement.pm 10857 71.4ms line • block • sub /srv/otrs/Kernel/cpan-lib/JSON/PP.pm (including 20 string evals) 27122 67.0ms line • block • sub /srv/otrs/Kernel/cpan-lib/Apache2/Reload.pm 5935 53.4ms line • block • sub /srv/otrs//Kernel/System/Ticket/TicketSearch.pm 1546 40.3ms line • block • sub /srv/otrs//Kernel/Output/Template/Provider.pm 42 40.1ms line • block • sub Template/Grammar.pm 11195 39.0ms line • block • sub /srv/otrs//Kernel/System/Encode.pm 4878 38.6ms line • block • sub /srv/otrs/Kernel/Output/HTML/Templates/Standard/AgentNavigationBar.tt 223 37.3ms line • block • sub /srv/otrs//Kernel/System/ITSMChange/ITSMWorkOrder.pm 881 35.0ms line • block • sub /srv/otrs//Kernel/System/ITSMChange.pm 1287 32.0ms line • block • sub File/Path.pm 34 32.0ms line • block • sub /srv/otrs//Kernel/Modules/AgentTimeAccountingEdit.pm 4096 31.0ms line • block • sub /srv/otrs//Kernel/System/Cache/FileStorable.pm 12 30.3ms line • block • sub /srv/otrs//Kernel/System/Ticket/Article.pm 5399 29.7ms line • block • sub Template/Stash.pm 314 29.2ms line • block • sub /srv/otrs//Kernel/System/Web/InterfaceAgent.pm 2737 28.0ms line • block • sub /srv/otrs//Kernel/System/DB/mysql.pm 439 27.8ms line • block • sub DBD/mysql.pm 1041 27.8ms line • block • sub /srv/otrs//Kernel/Output/HTML/TicketOverview/Small.pm 8 25.6ms line • block • sub /srv/otrs//Kernel/System/Ticket/TicketACL.pm 1331 25.2ms line • block • sub /srv/otrs//Kernel/System/User.pm 574 24.8ms line • block • sub /srv/otrs//Kernel/System/Group.pm 88 24.3ms line • block • sub /srv/otrs//Kernel/System/TimeAccounting.pm 1142 24.3ms line • block • sub /srv/otrs//Kernel/Modules/AgentTicketQueue.pm 2116 24.3ms line • block • sub /srv/otrs//Kernel/Language/en_CA_ITSMChangeManagement.pm 3186 23.8ms line • block • sub /srv/otrs//Kernel/System/Fred/ConfigLog.pm 2116 23.1ms line • block • sub /srv/otrs//Kernel/Language/en_GB_ITSMChangeManagement.pm 120 22.4ms line • block • sub File/Temp.pm 3003 22.4ms line • block • sub /srv/otrs//Kernel/Output/HTML/Layout/Template.pm 1260 22.3ms line • block • sub Storable.pm 1697 22.3ms line • block • sub /srv/otrs//Kernel/Output/Template/Plugin/OTRS.pm 284 22.2ms line • block • sub /srv/otrs//Kernel/System/DynamicField/Backend.pm 302 21.2ms line • block • sub /srv/otrs//Kernel/Output/HTML/Layout/Ticket.pm 54 20.9ms line • block • sub /srv/otrs//Kernel/System/Daemon/SchedulerDB.pm 2533 20.9ms line • block • sub /srv/otrs//Kernel/System/AuthSession/DB.pm 2969 20.3ms line • block • sub /srv/otrs//Kernel/Language.pm 26 19.9ms line • block • sub /srv/otrs/Kernel/cpan-lib/Date/Pcalc.pm 6 19.9ms line • block • sub /srv/otrs//Kernel/System/LinkObject.pm 2010 19.8ms line • block • sub /srv/otrs/Kernel/cpan-lib/Mail/Field.pm (including 3 string evals) 146 19.7ms line • block • sub /srv/otrs//Kernel/Output/HTML/FilterElementPost/CloseTicketView.pm 36 17.7ms line • block • sub /srv/otrs/Kernel/cpan-lib/MIME/Parser.pm 1286 17.3ms line • block • sub /srv/otrs//Kernel/System/Web/Request.pm 18 17.3ms line • block • sub /srv/otrs//Kernel/System/EmailParser.pm 36 17.2ms line • block • sub /srv/otrs//Kernel/System/ITSMConfigItem.pm 36 17.2ms line • block • sub /srv/otrs//Kernel/System/DynamicField/Driver/RemoteDB.pm 104 16.9ms line • block • sub /srv/otrs//Kernel/Output/HTML/FilterContent/Fred.pm (variables that impact regex performance for whole application seen here) 327 16.7ms line • block • sub /srv/httpd/../modperl/lib/perl/5.14.2/ModPerl/RegistryCooker.pm (including 1 string eval) 38 16.0ms line • block • sub /srv/otrs//Kernel/System/DynamicField/Driver/ITSMConfigItemReference.pm 1497 15.7ms line • block • sub File/stat.pm 2000 15.7ms line • block • sub /srv/otrs/Kernel/Output/HTML/Templates/Standard/AgentTicketOverviewNavBar.tt 36 15.3ms line • block • sub File/Find.pm 32 15.2ms line • block • sub /srv/otrs/Kernel/cpan-lib/MIME/Entity.pm 12 15.1ms line • block • sub /srv/otrs//Kernel/System/DynamicField/Driver/BaseDateTime.pm 2135 14.9ms line • block • sub /srv/otrs//Kernel/System/Cache.pm 55 14.6ms line • block • sub POSIX.pm 1622 14.6ms line • block • sub /srv/otrs/Kernel/Output/HTML/Templates/Standard/Header.tt 56 14.2ms line • block • sub Cwd.pm (including 2 string evals) 4446 14.2ms line • block • sub Class/Struct.pm (including 1 string eval) 347 14.0ms line • block • sub /srv/otrs//Kernel/System/DynamicField.pm 36 13.9ms line • block • sub /srv/otrs//Kernel/System/DynamicField/Driver/Date.pm 906 13.0ms line • block • sub /srv/otrs//Kernel/System/Loader.pm 978 12.8ms line • block • sub /srv/otrs//Kernel/System/Time.pm 2009 12.6ms line • block • sub File/Basename.pm 60 12.3ms line • block • sub /srv/otrs//Kernel/System/Queue.pm 1776 11.6ms line • block • sub /srv/otrs//Kernel/System/JSON.pm 24 11.6ms line • block • sub /srv/otrs//Kernel/System/DynamicField/Driver/Multiselect.pm 10 11.4ms line • block • sub /srv/otrs//Kernel/System/ITSMConfigItem/Version.pm 1034 10.6ms line • block • sub Template/Service.pm 12 10.6ms line • block • sub /srv/otrs//Kernel/Output/HTML/Layout/LinkObject.pm 24 10.4ms line • block • sub /srv/otrs//Kernel/System/Ticket/ArticleStorageDB.pm 6 10.1ms line • block • sub /srv/otrs//Kernel/Output/HTML/Layout/FAQ.pm 10 9.89ms line • block • sub /srv/otrs//Kernel/System/DynamicField/Driver/BaseSelect.pm
Filename -e Statements Executed 0 statements in 39.3s Subroutines Calls P F Exclusive Time Inclusive Time Subroutine 1 1 1 522µs 1.92ms Kernel::System::Fred::STDERRLog::BEGIN@82 1 1 1 13µs 13µs Kernel::System::CheckItem::BEGIN@282 Call graph for these subroutines as a Graphviz dot language file. Line State ments Time on line Calls Time in subs Code 0 23 9.46s Profile data that couldn't be associated with a specific line: # spent 9.39s making 3 calls to ModPerl::Registry::handler, avg 3.13s/call # spent 67.0ms making 8 calls to Apache2::Reload::handler, avg 8.38ms/call # spent 1.92ms making 1 call to Kernel::System::Fred::STDERRLog::BEGIN@82 # spent 516µs making 3 calls to Apache::DBI::__ANON__, avg 172µs/call # spent 366µs making 1 call to Apache::DBI::childexit # spent 165µs making 3 calls to CGI::_reset_globals, avg 55µs/call # spent 116µs making 1 call to File::Temp::END # spent 97µs making 1 call to DBI::END # spent 13µs making 1 call to Kernel::System::CheckItem::BEGIN@282 # spent 7µs making 1 call to APR::Pool::DESTROY 1 1 39.3s No source code available for non-file '-e'. You probably need to use a more recent version of perl. See savesrc option in documentation. 2 - - 82 # spent 1.92ms (522µs+1.39) within Kernel::System::Fred::STDERRLog::BEGIN@82 which was called: # once (522µs+1.39ms) by Kernel::System::Fred::STDERRLog::CORE:open at line 0
So what is -e file and executed 0 statements 39 seconds. Also ModPerl::Registry::handler takes 3 seconds per call. What could be the problem. If need more debug, please advise.