t/12-data.t fails on s390x

[jplesnik]

I want to build the version 6.08 for Fedora, but the test 12-data.t fails on s390x

t/12-data.t .............. The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s
t/12-data.t .............. 15/? The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s
The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s
The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s
The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s

#   Failed test 'Nothing dumped, as requested'
#   at t/12-data.t line 280.
The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s
The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s
The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s
The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s
The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s
# Looks like you failed 1 test of 79.
t/12-data.t .............. Dubious, test returned 1 (wstat 256, 0x100)

Complete build informati can be found on:
https://koji.fedoraproject.org/koji/taskinfo?taskID=66958623

[jkeenan]

Thank you for this report. The operating system -- s390x -- for which you are attempting to build an RPM is one that we do not have access to and from which we have not received smoke-testing reports. Hence, we'll need some direct interaction with you in order to resolve the problem. I'd like to begin by posing these questions:

1. Can you reproduce the error if you simply repeat your process?

2. You appear to be patching an existing Makefile.PL rather than simply using the Makefile.PL provided in the CPAN distribution. Can you say why you are doing so? Can you provide the patch? (I ask because we have to rule out the possibility that this failure was introduced by something over which I have no control, e.g., your RPM build process.)

3. As best I can tell from your build.log, the failure reported is this:

t/00-load.t .............. ok
Unable to open '/home/jkeenan/gitwork/zzzothers/devel-nytprof/t/test01.p' for reading: No such file or directory
t/11-reader.t ............ ok
t/12-data.t .............. 
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/79 subtests 
#   Failed test 'Nothing dumped, as requested'
#   at t/12-data.t line 272.

a. My hunch is that the Unable to open ... t/test01.p for reading warning is transient and not associated with the test failure. However, that's just a hunch based on observation of this warning in smoke-testing reports.

b. The failure you are getting comes from this part of t/12-data.t:

262 {
263     SKIP: {
264         skip "Bad interaction when trace_level is set", 3
265             if trace_level();
266         my $profile;
267         local $ENV{NYTPROF_ONLOAD} = 'alpha=beta:gamma=delta:dump=0';
268         my $stderr = capture_stderr {
269             $profile = Devel::NYTProf::Data->new( { filename => $file, quiet => 1 } );
270         };
271         ok(! $stderr, "Nothing dumped, as requested");
272         ok(defined $profile, "Direct call of constructor returned defined value");
273         isa_ok($profile, 'Devel::NYTProf::Data');
274     }
275 
276 }

What the test at line 271 is asserting is that, (a) when creating a profile of a Perl process (technically, creating a new Devel::NYTProf::Data object), (b) if we have set an environmental variable $NYTPROF_ONLOAD to not request dumping and (c) we capture the STDERR from a call to Devel::NYTProf::Data->new(), we should expect to capture no STDERR (at most, an empty string).

It would therefore be helpful to see how, in your test run, $stderr is being populated. Would it be possible for you to insert the following debugging statement after line 271 of t/12-data.t, re-run your process, and provide the output?

271         ok(! $stderr, "Nothing dumped, as requested");
            print STDERR "<$stderr>\n" if $stderr;
272         ok(defined $profile, "Direct call of constructor returned defined value");

My hunch is that, from the point of view of users of Devel-NYTProf from your RPM, the failure you are reporting is a false negative. The relevant part of lib/Devel/NYTProf/Data.pm is this:

135     # a hack for testing/debugging
136     # $ENV{NYTPROF_ONLOAD} must be a colon-delimited string of
137     # equal-sign-delimited substrings, e.g.,
138     # 'alpha=beta:gamma=delta:dump=1:exit=1';
139 
140     if (my $env = $ENV{NYTPROF_ONLOAD}) {
141         my %onload = map { split /=/, $_, 2 } split /:/, $env, -1;
142         warn _dumper($profile) if $onload{dump};
143         exit $onload{exit}     if defined $onload{exit};
144     }

Hence, what line 271 of t/12-data.t is exercising is a part of the source code that is only of interest to NYTProf developers -- not to NYTProf end-users. If this proves to be the case, then (a) you could simply do the equivalent of --force install to override the test result; and/or (b) we could, in an upcoming release of the distribution, make this test PERL_AUTHOR_TESTING only.

We look forward to your response.

Thank you very much.
Jim Keenan

[jplesnik]

Sorry for delay, but I was a bit busy.

1. Can you reproduce the error if you simply repeat your process?

I can reproduce it with version 6.08. I do not have s390x machine, but I use mock tool for it. Mock is possible to install packages for different architecture.

2. You appear to be patching an existing Makefile.PL rather than simply using the Makefile.PL provided in the CPAN distribution. Can you say why you are doing so? Can you provide the patch? (I ask because we have to rule out the possibility that this failure was introduced by something over which I have no control, e.g., your RPM build process.)

Fedora prefers to use system utilities instead of bundled one. So, we update Makefile to use flamegraph.pl from Fedora package.

3. As best I can tell from your build.log, the failure reported is this:
   a. My hunch is that the Unable to open ... t/test01.p for reading warning is transient and not associated with the test failure. However, that's just a hunch based on observation of this warning in smoke-testing reports.

It is not a problem.

b. The failure you are getting comes from this part of t/12-data.t:
[...]
What the test at line 271 is asserting is that, (a) when creating a profile of a Perl process (technically, creating a new Devel::NYTProf::Data object), (b) if we have set an environmental variable $NYTPROF_ONLOAD to not request dumping and (c) we capture the STDERR from a call to Devel::NYTProf::Data->new(), we should expect to capture no STDERR (at most, an empty string).

It would therefore be helpful to see how, in your test run, $stderr is being populated. Would it be possible for you to insert the following debugging statement after line 271 of t/12-data.t, re-run your process, and provide the output?

The result with required change is:

ok 59 - An object of class 'Devel::NYTProf::Data' isa 'Devel::NYTProf::Data'
not ok 60 - Nothing dumped, as requested
#   Failed test 'Nothing dumped, as requested'
#   at t/12-data.t line 271.
<The sum of the statement timings is -0.0% of the total time profiling. (Values slightly over 100% can be due simply to cumulative timing errors, whereas larger values can indicate a problem with the clock used.)
Summary: statements profiled 14 (=14-0), sum of time 0.000083s, profile spanned -362300392782867969815189239774873813528024437159978281124115804823579919589646289800268165617055241683980964002953329110377976124472780092725897688137538820190341951389696.000000s
>
ok 61 - Direct call of constructor returned defined value

I hope it helps you.
Jitka