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.
---------------------------------------------------------------------
OTRS mailing list: otrs - Webpage: http://otrs.org/
Archive: http://lists.otrs.org/pipermail/otrs
To unsubscribe: http://lists.otrs.org/mailman/listinfo/otrs
