panic at nytprofcalls line 222

[brendadeely]

I'm getting a panic when I try to parse an nytprof.out file with nytprofcalls (via nytprofhtml). This is the last few lines of output from nytprofcalls -d nytprof.out.1026:

<  6 DBD::Pg::db::prepare 715 (stack 6)
<  6 DBI::common::DESTROY 75 (stack 6)
<  6 DBI::common::DESTROY 1848 (stack 6)
<  6 DBD::_mem::common::DESTROY 81 (stack 6)
<  6 DBD::Pg::db::prepare 728 (stack 6)
<  6 DBI::common::DESTROY 67 (stack 6)
<  6 DBI::common::DESTROY 1780 (stack 6)
<  6 DBD::_mem::common::DESTROY 72 (stack 6)
<  6 utf8::SWASHNEW 2373 (stack 6)
<  6 DBI::common::DESTROY 96 (stack 6)
<  6 DBI::common::DESTROY 2001 (stack 6)
<  6 DBD::_mem::common::DESTROY 86 (stack 6)
<  6 DBI::common::FETCH 88 (stack 6)
<  6 DBI::common::FETCH 34 (stack 6)
<  6 DBI::common::FETCH 138 (stack 6)
<  6 SelectSaver::DESTROY 85 (stack 6)
<  6 SelectSaver::DESTROY 79 (stack 6)
<  6 DBD::_::dr::default_user 134 (stack 6)
<  7 DBI::common::FETCH 175 (stack 6)
<  7 DBI::common::FETCH 97 (stack 7)
<  7 DBI::common::STORE 166 (stack 7)
<  6 DBD::Pg::dr::connect 50893 (stack 7)
<  6 DBI::common::STORE 105 (stack 6)
<  6 DBI::common::STORE 137 (stack 6)
<  6 DBI::common::STORE 106 (stack 6)
<  6 DBI::common::FETCH 40 (stack 6)
<  6 DBI::common::STORE 66 (stack 6)
<  6 DBI::common::FETCH 74 (stack 6)
<  6 DBI::common::STORE 108 (stack 6)
<  6 DBI::common::FETCH 164 (stack 6)
<  6 DBI::common::FETCH 90 (stack 6)
<  6 DBI::common::FETCH 90 (stack 6)
<  6 SelectSaver::DESTROY 74 (stack 6)
<  6 DBD::Pg::db::prepare 823 (stack 6)
<  6 Params::Validate::_check_regex_from_xs 178 (stack 6)
<  6 DateTime::__ANON__ 142 (stack 6)
<  6 DateTime::__ANON__ 80 (stack 6)
<  6 DateTime::__ANON__ 73 (stack 6)
<  6 DateTime::__ANON__ 73 (stack 6)
<  6 DateTime::__ANON__ 66 (stack 6)
<  6 DateTime::__ANON__ 61 (stack 6)
<  6 Regexp::DESTROY 38 (stack 6)
<  6 UNIVERSAL::isa 45 (stack 6)
<  6 DateTime::_stringify 353 (stack 6)
<  6 UNIVERSAL::can 41 (stack 6)
<  6 DateTime::__ANON__ 127 (stack 6)
<  6 DateTime::__ANON__ 60 (stack 6)
<  6 DateTime::__ANON__ 58 (stack 6)
<  6 DateTime::__ANON__ 186 (stack 6)
<  6 DateTime::__ANON__ 57 (stack 6)
<  6 DateTime::__ANON__ 55 (stack 6)
<  6 DateTime::__ANON__ 59 (stack 6)
<  7 Storable::net_mstore 767 (stack 6)
<  7 Storable::CORE:subst 31 (stack 7)
<  6 Storable::_freeze 729 (stack 7)
<  6 SelectSaver::DESTROY 75 (stack 6)
<  6 DBD::Pg::db::prepare 1355 (stack 6)
<  6 DBI::common::DESTROY 90 (stack 6)
<  6 DBI::common::DESTROY 2008 (stack 6)
<  6 DBD::_mem::common::DESTROY 79 (stack 6)
<  6 DBI::common::DESTROY 51 (stack 6)
<  6 DBI::common::DESTROY 1582 (stack 6)
<  6 DBD::_mem::common::DESTROY 77 (stack 6)
visit_node: 0 HASH(0x1461ba8)
panic at cpanlib/bin/nytprofcalls line 222.

That panic is caused when $subid eq '0'. I logged out the $node that contains $subid. The first part looks like:

{
    '0' => {
        '0' => {
            '0' => {
                '0' => {
                    '0' => {
                        '0' => {
                            '0' => {
                                '0' => {
                                    '0' => {
                                        '33' => {
                                            'v' => 152
                                        },
                                        '32' => {
                                            'v' => 875
                                        },
                                        '21' => {
                                            '18' => {
                                                'v' => 187
                                            },
                                            '19' => {
                                                'v' => 73
                                            },
                                            'v' => 428
                                        },
                                        '17' => {
                                            '13' => {
                                                '11' => {
                                                    '7' => {
                                                        'v' => 74
                                                    },
                                                    'v' => 392
                                                },
                                                '16' => {
                                                    'v' => 299,
                                                    '15' => {
                                                        'v' => 1245
                                                    }
                                                },
                                                'v' => 29258,
                                                '12' => {
                                                    '9' => {
                                                        'v' => 314
                                                    },
                                                    'v' => 214
                                                },
                                                '14' => {
                                                    '13' => {
                                                        'v' => 1020
                                                    },
                                                    'v' => 302
                                                }
                                            },
                                            'v' => 377
                                        },

On a development environment, the panic occurs but the page I'm test profiling loads completely and I'm able to view the profiling tools as expected. However, on a test environment, the panic seems like it's preventing the page from loading at all.

Thanks in advance for your assistance and let me know if you need any further information.

[shawnlaffan]

Just for the record, I hit the same issue when processing a merged output file generated using nytprofmerge. This was for a test run with about 67 test files called using prove and with env var PERL5OPT=-d:NYTProf=addpid=1. The test files use Test2::V0, amongst many other packages, and were called using prove.

This occurred on both Mac ARM and Ubuntu on WSL2. Both used perl 5.38.2 built using perlbrew with default args.

Editing the nytprofcalls code to keep the zeroes and use a dummy sub name (elided) got it to process the merged file. However, only the IPC3 and similar top-level calls were in the results, above about eight dummy subs in the flame graph.

I don't have a fix but it all worked when invoking the test files using perl t/test.t and then running nytprofmerge on the results. This was without PERL5OPT`` being set - thenytprof.out``` files were manually renamed after each test.

So it would seem to be either a problem with mytprofmerge and/or how Devel::NYTProf is handling some of the packages in use. (I should really test a single prove run without the merge).