search

timbunce / devel-nytprof

Devel::NYTProf is a powerful feature-rich source code profiler for Perl. (Mostly in maintenance mode, so PRs are much more likely to be acted upon than Issues.)
http://blog.timbunce.org/tag/nytprof/
67 stars 51 forks source link

Profile format error when profiling Plack+FCGI app #93

Closed leto closed 8 years ago

leto commented 8 years ago

I am getting Profile format error whilst reading string when profiling a toy Plack app with NYT 6.02 and perl 5.10.1 on CentOS:

$ cat test.psgi
#!/usr/bin/perl
use strict;
use warnings;

my $app = sub {
  return [
    '200',
    [ 'Content-Type' => 'application/javascript' ],
    [ 42 ],
  ];
};

which is invoked via: PERL5OPT=-d:NYTProf plackup -s FCGI --listen /tmp/fcgi.sock test.psgi

$ nytprofcalls -d nytprof.out.18372
Reading nytprof.out.18372...
<  7 FCGI::ProcManager::self_or_default 241 (stack 1)
<  6 FCGI::ProcManager::pm_parameter 412 (stack 7)
<  5 FCGI::ProcManager::role 335 (stack 6)
<  8 FCGI::ProcManager::self_or_default 39 (stack 5)
<  7 FCGI::ProcManager::pm_parameter 83 (stack 8)
<  6 FCGI::ProcManager::no_signals 92 (stack 7)
<  6 POSIX::sigaction 608 (stack 6)
<  6 POSIX::sigaction 120 (stack 6)
<  7 FCGI::ProcManager::self_or_default 35 (stack 6)
<  6 FCGI::ProcManager::pm_change_process_name 200 (stack 7)
<  5 FCGI::ProcManager::handling_init 1030 (stack 6)
<  6 FCGI::ProcManager::self_or_default 34 (stack 5)
<  6 FCGI::ProcManager::CORE:subst 360 (stack 6)
<  8 FCGI::ProcManager::self_or_default 34 (stack 6)
<  7 FCGI::ProcManager::pm_parameter 81 (stack 8)
<  6 FCGI::ProcManager::role 52 (stack 7)
<  6 FCGI::ProcManager::CORE:print 277 (stack 6)
<  5 FCGI::ProcManager::pm_notify 386 (stack 6)
<  4 FCGI::ProcManager::pm_manage 31817 (stack 5)
<  4 FCGI::Accept 156516222 (stack 4)
<  5 FCGI::ProcManager::self_or_default 81 (stack 4)
<  7 FCGI::ProcManager::self_or_default 34 (stack 5)
<  6 FCGI::ProcManager::pm_parameter 102 (stack 7)
<  5 FCGI::ProcManager::no_signals 89 (stack 6)
<  5 POSIX::sigaction 205 (stack 5)
<  5 POSIX::sigaction 74 (stack 5)
<  4 FCGI::ProcManager::pm_pre_dispatch 378 (stack 5)
<  4 Plack::Handler::FCGI::CORE:match 137 (stack 4)
<  5 URI::CORE:subst 76 (stack 4)
<  5 URI::CORE:subst 38 (stack 5)
<  5 URI::CORE:subst 20 (stack 5)
<  5 URI::CORE:subst 54 (stack 5)
<  5 URI::CORE:regcomp 408 (stack 5)
<  5 URI::CORE:match 41 (stack 5)
<  6 URI::CORE:regcomp 145 (stack 5)
<  6 URI::CORE:match 26 (stack 6)
<  6 URI::CORE:subst 10 (stack 6)
<  6 URI::CORE:subst 4 (stack 6)
<  6 URI::CORE:subst 8 (stack 6)
<  7 strict::import 111 (stack 6)
<  6 URI::http::BEGIN@3 379 (stack 7)
<  7 warnings::import 486 (stack 6)
<  6 URI::http::BEGIN@4 190 (stack 7)
<  8 parent::CORE:subst 108 (stack 6)
<  9 strict::import 44 (stack 8)
<  8 URI::_server::BEGIN@3 233 (stack 9)
<  9 warnings::import 135 (stack 8)
<  8 URI::_server::BEGIN@4 113 (stack 9)
< 10 parent::CORE:subst 51 (stack 8)
< 11 strict::import 41 (stack 10)
< 10 URI::_generic::BEGIN@3 194 (stack 11)
< 11 warnings::import 181 (stack 10)
< 10 URI::_generic::BEGIN@4 120 (stack 11)
< 12 parent::CORE:subst 23 (stack 10)
< 12 parent::CORE:subst 36 (stack 12)
< 13 strict::import 39 (stack 12)
< 12 URI::_query::BEGIN@3 192 (stack 13)
< 13 warnings::import 127 (stack 12)
< 12 URI::_query::BEGIN@4 109 (stack 13)
< 12 URI::_query::BEGIN@6 46 (stack 12)
< 14 Exporter::CORE:subst 67 (stack 12)
< 14 Exporter::CORE:subst 7 (stack 14)
< 14 Exporter::CORE:subst 7 (stack 14)
< 14 Exporter::CORE:subst 4 (stack 14)
< 14 Exporter::CORE:match 43 (stack 14)
< 13 Exporter::import 1386 (stack 14)
< 12 URI::_query::BEGIN@7 155 (stack 13)
< 11 parent::import 12080 (stack 12)
< 10 URI::_generic::BEGIN@6 149 (stack 11)
< 12 Exporter::CORE:match 16 (stack 10)
< 11 Exporter::import 432 (stack 12)
< 10 URI::_generic::BEGIN@8 131 (stack 11)
< 10 URI::_generic::BEGIN@9 56 (stack 10)
< 10 URI::_generic::CORE:subst 83 (stack 10)
< 10 URI::_generic::CORE:subst 25 (stack 10)
<  9 parent::import 22125 (stack 10)
<  8 URI::_server::BEGIN@6 110 (stack 9)
< 10 Exporter::CORE:match 15 (stack 8)
<  9 Exporter::import 402 (stack 10)
<  8 URI::_server::BEGIN@8 126 (stack 9)
<  7 parent::import 16863 (stack 8)
<  6 URI::http::BEGIN@9 206 (stack 7)
<  6 URI::_init_implementor 70 (stack 6)
<  5 URI::implementor 5698 (stack 6)
<  7 URI::_server::CORE:regcomp 279 (stack 5)
<  7 URI::_server::CORE:match 70 (stack 7)
<  7 URI::_server::CORE:subst 11 (stack 7)
<  7 URI::_server::CORE:subst 6 (stack 7)
<  8 URI::_server::CORE:regcomp 85 (stack 7)
<  8 URI::_server::CORE:match 12 (stack 8)
<  7 URI::_server::_host_escape 101 (stack 8)
<  8 URI::CORE:regcomp 93 (stack 7)
<  8 URI::CORE:subst 76 (stack 8)
<  8 utf8::downgrade 42 (stack 8)
<  7 URI::_uric_escape 294 (stack 8)
<  6 URI::_server::_uric_escape 832 (stack 7)
<  6 URI::CORE:regcomp 107 (stack 6)
<  6 URI::CORE:match 30 (stack 6)
<  5 URI::_init 1481 (stack 6)
<  4 URI::new   1027 (stack 5)
<  5 URI::_generic::CORE:match 43 (stack 4)
<  4 URI::_generic::path 149 (stack 5)
<  5 URI::Escape::CORE:subst 7 (stack 4)
<  4 URI::Escape::uri_unescape 159 (stack 5)
<  4 Plack::Handler::FCGI::CORE:regcomp 77 (stack 4)
<  4 Plack::Handler::FCGI::CORE:subst 4 (stack 4)
<  7 Plack::Util::Accessor::__ANON__[/usr/local/share/perl5/Plack/Util/Accessor.pm:19] 91 (stack 4)
<  9 Try::Tiny::catch 222 (stack 7)
< 11 Plack::Util::Accessor::__ANON__[/usr/local/share/perl5/Plack/Util/Accessor.pm:19] 35 (stack 9)
< 14 Plack::Middleware::Lint::CORE:match 89 (stack 11)
< 14 Plack::Middleware::Lint::CORE:match 45 (stack 14)
< 14 Plack::Middleware::Lint::CORE:match 61 (stack 14)
< 14 Plack::Middleware::Lint::CORE:match 44 (stack 14)
< 13 Plack::Middleware::Lint::validate_env 704 (stack 14)
< 13 Plack::Util::Accessor::__ANON__[/usr/local/share/perl5/Plack/Util/Accessor.pm:19] 60 (stack 13)
< 13 Plack::Sandbox::_2fvar_2fweb_2forg_2ftest_2epsgi::__ANON__[/var/web/org/test.psgi:11] 86 (stack 13)
< 14 Plack::Middleware::Lint::CORE:match 61 (stack 13)
< 14 Plack::Middleware::Lint::CORE:match 67 (stack 14)
< 14 Plack::Middleware::Lint::CORE:match 64 (stack 14)
< 14 Plack::Middleware::Lint::CORE:match 37 (stack 14)
< 15 utf8::is_utf8 89 (stack 14)
< 14 Plack::Middleware::Lint::_has_wide_char 174 (stack 15)
< 13 Plack::Middleware::Lint::validate_res 680 (stack 14)
< 12 Plack::Middleware::Lint::call 603 (stack 13)
< 11 Plack::Component::__ANON__[/usr/local/share/perl5/Plack/Component.pm:50] 133 (stack 12)
< 10 Plack::Middleware::StackTrace::__ANON__[/usr/local/share/perl5/Plack/Middleware/StackTrace.pm:39] 243 (stack 11)
<  9 Try::Tiny::try 466 (stack 10)
<  8 Plack::Middleware::StackTrace::call 654 (stack 9)
<  7 Plack::Component::__ANON__[/usr/local/share/perl5/Plack/Component.pm:50] 170 (stack 8)
<  7 Plack::Util::content_length 236 (stack 7)
<  8 Plack::Util::Accessor::__ANON__[/usr/local/share/perl5/Plack/Util/Accessor.pm:19] 122 (stack 7)
< 12 POSIX::strftime::Compiler::CORE:subst 68 (stack 8)
< 12 POSIX::strftime::Compiler::CORE:subst 32 (stack 12)
< 12 POSIX::strftime::Compiler::CORE:subst 2 (stack 12)
< 12 POSIX::strftime::Compiler::CORE:match 65 (stack 12)
< 12 POSIX::strftime::Compiler::CORE:match 5 (stack 12)
< 12 POSIX::strftime::Compiler::CORE:subst 101 (stack 12)
< 12 POSIX::strftime::Compiler::CORE:substcont 25 (stack 12)
< 12 POSIX::strftime::Compiler::__ANON__[/usr/local/share/perl5/POSIX/strftime/Compiler.pm:293] 157 (stack 12)
< 12 POSIX::strftime::Compiler::CORE:substcont 14 (stack 12)
< 11 POSIX::strftime::Compiler::compile 2695 (stack 12)
< 12 POSIX::strftime 377 (stack 11)
< 11 POSIX::strftime::Compiler::__ANON__[(eval 15)[/usr/local/share/perl5/POSIX/strftime/Compiler.pm:351]:12] 137 (stack 12)
< 10 POSIX::strftime::Compiler::strftime 390 (stack 11)
< 11 Apache::LogFormat::Compiler::CORE:subst 19 (stack 10)
< 10 Apache::LogFormat::Compiler::_safe 216 (stack 11)
< 11 Apache::LogFormat::Compiler::CORE:subst 62 (stack 10)
< 10 Apache::LogFormat::Compiler::_safe 58 (stack 11)
< 11 Apache::LogFormat::Compiler::CORE:subst 54 (stack 10)
< 10 Apache::LogFormat::Compiler::_string 144 (stack 11)
< 11 Apache::LogFormat::Compiler::CORE:subst 24 (stack 10)
< 10 Apache::LogFormat::Compiler::_string 68 (stack 11)
<  9 Apache::LogFormat::Compiler::__ANON__[(eval 7)[/usr/local/share/perl5/Apache/LogFormat/Compiler.pm:151]:21] 846 (stack 10)
<  8 Apache::LogFormat::Compiler::log_line 273 (stack 9)
<  7 Plack::Middleware::AccessLog::log_line 310 (stack 8)
<  7 Plack::Util::Accessor::__ANON__[/usr/local/share/perl5/Plack/Util/Accessor.pm:19] 48 (stack 7)
<  9 IO::Handle::CORE:print 194 (stack 7)
<  8 IO::Handle::print 278 (stack 9)
<  7 Plack::Runner::__ANON__[/usr/local/share/perl5/Plack/Runner.pm:270] 207 (stack 8)
<  6 Plack::Middleware::AccessLog::call 898 (stack 7)
<  5 Plack::Component::__ANON__[/usr/local/share/perl5/Plack/Component.pm:50] 170 (stack 6)
<  4 Plack::Util::run_app 271 (stack 5)
<  6 Symbol::qualify 89 (stack 4)
<  7 SelectSaver::CORE:select 59 (stack 6)
<  7 Symbol::qualify 31 (stack 7)
<  7 SelectSaver::CORE:select 24 (stack 7)
<  6 SelectSaver::new 493 (stack 7)
Profile format error whilst reading string at 15743: expected 24 got 6, end of file at /usr/local/lib64/perl5/Devel/NYTProf/Data.pm line 87.

There is also a nytprof.out file which gives a similar error. Here is the end of the output:

<  9 Exporter::Heavy::CORE:subst 6 (stack 9)
<  9 Exporter::Heavy::CORE:subst 5 (stack 9)
<  8 Exporter::Heavy::heavy_export 3831 (stack 9)
<  7 Exporter::import 16689 (stack 8)
<  6 POSIX::import 568 (stack 7)
<  5 FCGI::ProcManager::BEGIN@12 134 (stack 6)
<  7 vars::CORE:match 38 (stack 5)
<  7 vars::CORE:match 9 (stack 7)
<  7 vars::CORE:match 7 (stack 7)
<  7 vars::CORE:match 21 (stack 7)
<  7 vars::CORE:match 5 (stack 7)
<  7 vars::CORE:match 3 (stack 7)
<  7 vars::CORE:match 21 (stack 7)
<  7 vars::CORE:match 5 (stack 7)
<  7 vars::CORE:match 4 (stack 7)
<  7 vars::CORE:match 17 (stack 7)
<  7 vars::CORE:match 5 (stack 7)
<  7 vars::CORE:match 4 (stack 7)
<  7 vars::CORE:match 20 (stack 7)
<  7 vars::CORE:match 5 (stack 7)
<  7 vars::CORE:match 1 (stack 7)
<  7 vars::CORE:match 17 (stack 7)
<  7 vars::CORE:match 5 (stack 7)
<  7 vars::CORE:match 5 (stack 7)
<  6 vars::import 974 (stack 7)
<  5 FCGI::ProcManager::BEGIN@14 122 (stack 6)
<  5 FCGI::ProcManager::BEGIN@15 241 (stack 5)
<  4 Plack::Util::load_class 26360 (stack 5)
<  7 FCGI::ProcManager::self_or_default 47 (stack 4)
<  6 FCGI::ProcManager::pm_parameter 99 (stack 7)
<  5 FCGI::ProcManager::no_signals 67 (stack 6)
<  7 AutoLoader::CORE:match 58 (stack 5)
<  7 AutoLoader::CORE:subst 28 (stack 7)
<  7 AutoLoader::CORE:subst 23 (stack 7)
<  6 AutoLoader::find_filename 194 (stack 7)
<  5 AutoLoader::AUTOLOAD 1740 (stack 6)
<  5 POSIX::SigAction::new 134 (stack 5)
<  5 POSIX::SigAction::new 42 (stack 5)
<  4 FCGI::ProcManager::new 535 (stack 5)
<  5 FCGI::ProcManager::self_or_default 39 (stack 4)
<  7 FCGI::ProcManager::self_or_default 31 (stack 5)
<  6 FCGI::ProcManager::pm_parameter 66 (stack 7)
<  5 FCGI::ProcManager::n_processes 63 (stack 6)
<  7 FCGI::ProcManager::self_or_default 28 (stack 5)
<  6 FCGI::ProcManager::pm_parameter 59 (stack 7)
<  5 FCGI::ProcManager::role 71 (stack 6)
<  8 FCGI::ProcManager::self_or_default 27 (stack 5)
<  7 FCGI::ProcManager::pm_parameter 52 (stack 8)
<  6 FCGI::ProcManager::no_signals 37 (stack 7)
<  6 POSIX::sigaction 313 (stack 6)
<  6 POSIX::sigaction 71 (stack 6)
<  7 FCGI::ProcManager::self_or_default 32 (stack 6)
<  6 FCGI::ProcManager::pm_parameter 65 (stack 7)
<  7 FCGI::ProcManager::self_or_default 24 (stack 6)
<  6 FCGI::ProcManager::pm_change_process_name 76 (stack 7)
<  7 FCGI::ProcManager::self_or_default 24 (stack 6)
<  9 FCGI::ProcManager::self_or_default 24 (stack 7)
<  8 FCGI::ProcManager::pm_parameter 52 (stack 9)
<  7 FCGI::ProcManager::pid_fname 55 (stack 8)
<  6 FCGI::ProcManager::pm_write_pid_file 111 (stack 7)
<  5 FCGI::ProcManager::managing_init 379 (stack 6)
<  6 FCGI::ProcManager::self_or_default 26 (stack 5)
<  6 FCGI::ProcManager::CORE:subst 73 (stack 6)
<  8 FCGI::ProcManager::self_or_default 25 (stack 6)
<  7 FCGI::ProcManager::pm_parameter 58 (stack 8)
<  6 FCGI::ProcManager::role 44 (stack 7)
<  6 FCGI::ProcManager::CORE:print 154 (stack 6)
<  5 FCGI::ProcManager::pm_notify 276 (stack 6)
<  7 FCGI::ProcManager::self_or_default 31 (stack 5)
<  6 FCGI::ProcManager::pm_parameter 57 (stack 7)
Profile format error whilst reading float at 156112: expected 8 got 6, end of file at /usr/local/lib64/perl5/Devel/NYTProf/Data.pm line 87.

This looks somewhat #20. At this point it does not look like nytprof is compatible with FCGI::ProcManager.

Thanks for all your work, Tim. Please let me know how I can help. You know I am itching to get a commit into nytprof :)

timbunce commented 8 years ago

Hi. How did you terminate the process? If via a signal, including ctrl-c, did you try using the sigexit option?

leto commented 8 years ago

I did terminate via CTRL-C and didn't know about sigexit. I will try that and report back.